Merge "Added timing to some more AnnotatedCallLog operations."

7 files changed, 179 insertions, 17 deletions

diff --git a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java
index e0bfcd8a3..3019f5e3a 100644
--- a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java
+++ b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java
@@ -21,10 +21,15 @@ import android.content.Context;
 import android.content.Intent;
 import android.content.IntentFilter;
 import android.support.annotation.Nullable;
+import com.android.dialer.calllog.RefreshAnnotatedCallLogWorker.RefreshResult;
 import com.android.dialer.calllog.constants.IntentNames;
 import com.android.dialer.common.LogUtil;
 import com.android.dialer.common.concurrent.DefaultFutureCallback;
 import com.android.dialer.common.concurrent.ThreadUtil;
+import com.android.dialer.metrics.FutureTimer;
+import com.android.dialer.metrics.Metrics;
+import com.android.dialer.metrics.MetricsComponent;
+import com.google.common.base.Function;
 import com.google.common.util.concurrent.Futures;
 import com.google.common.util.concurrent.ListenableFuture;
 import com.google.common.util.concurrent.MoreExecutors;
@@ -43,6 +48,7 @@ public final class RefreshAnnotatedCallLogReceiver extends BroadcastReceiver {
   private static final long REFRESH_ANNOTATED_CALL_LOG_WAIT_MILLIS = 100L;
 
   private final RefreshAnnotatedCallLogWorker refreshAnnotatedCallLogWorker;
+  private final FutureTimer futureTimer;
 
   @Nullable private Runnable refreshAnnotatedCallLogRunnable;
 
@@ -57,6 +63,7 @@ public final class RefreshAnnotatedCallLogReceiver extends BroadcastReceiver {
   public RefreshAnnotatedCallLogReceiver(Context context) {
     refreshAnnotatedCallLogWorker =
         CallLogComponent.get(context).getRefreshAnnotatedCallLogWorker();
+    futureTimer = MetricsComponent.get(context).futureTimer();
   }
 
   @Override
@@ -97,12 +104,14 @@ public final class RefreshAnnotatedCallLogReceiver extends BroadcastReceiver {
 
     refreshAnnotatedCallLogRunnable =
         () -> {
-          ListenableFuture<Void> future =
+          ListenableFuture<RefreshResult> future =
               checkDirty
                   ? refreshAnnotatedCallLogWorker.refreshWithDirtyCheck()
                   : refreshAnnotatedCallLogWorker.refreshWithoutDirtyCheck();
           Futures.addCallback(
               future, new DefaultFutureCallback<>(), MoreExecutors.directExecutor());
+          futureTimer.applyTiming(future, new EventNameFromResultFunction(checkDirty));
+          // TODO(zachh): Should also log impression counts of RefreshResults.
         };
 
     ThreadUtil.getUiThreadHandler()
@@ -118,4 +127,29 @@ public final class RefreshAnnotatedCallLogReceiver extends BroadcastReceiver {
 
     ThreadUtil.getUiThreadHandler().removeCallbacks(refreshAnnotatedCallLogRunnable);
   }
+
+  private static class EventNameFromResultFunction implements Function<RefreshResult, String> {
+
+    private final boolean checkDirty;
+
+    private EventNameFromResultFunction(boolean checkDirty) {
+      this.checkDirty = checkDirty;
+    }
+
+    @Override
+    public String apply(RefreshResult refreshResult) {
+      switch (refreshResult) {
+        case NOT_DIRTY:
+          return Metrics.REFRESH_NOT_DIRTY; // NOT_DIRTY implies forceRefresh is false
+        case REBUILT_BUT_NO_CHANGES_NEEDED:
+          return checkDirty
+              ? Metrics.REFRESH_NO_CHANGES_NEEDED
+              : Metrics.FORCE_REFRESH_NO_CHANGES_NEEDED;
+        case REBUILT_AND_CHANGES_NEEDED:
+          return checkDirty ? Metrics.REFRESH_CHANGES_NEEDED : Metrics.FORCE_REFRESH_CHANGES_NEEDED;
+        default:
+          throw new IllegalStateException("Unsupported result: " + refreshResult);
+      }
+    }
+  }
 }
diff --git a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
index e05b77268..c399b05ea 100644
--- a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
+++ b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
@@ -79,23 +79,30 @@ public class RefreshAnnotatedCallLogWorker {
     this.lightweightExecutorService = lightweightExecutorService;
   }
 
+  /** Result of refreshing the annotated call log. */
+  public enum RefreshResult {
+    NOT_DIRTY,
+    REBUILT_BUT_NO_CHANGES_NEEDED,
+    REBUILT_AND_CHANGES_NEEDED
+  }
+
   /** Checks if the annotated call log is dirty and refreshes it if necessary. */
-  ListenableFuture<Void> refreshWithDirtyCheck() {
+  ListenableFuture<RefreshResult> refreshWithDirtyCheck() {
     return refresh(true);
   }
 
   /** Refreshes the annotated call log, bypassing dirty checks. */
-  ListenableFuture<Void> refreshWithoutDirtyCheck() {
+  ListenableFuture<RefreshResult> refreshWithoutDirtyCheck() {
     return refresh(false);
   }
 
-  private ListenableFuture<Void> refresh(boolean checkDirty) {
+  private ListenableFuture<RefreshResult> refresh(boolean checkDirty) {
     LogUtil.i("RefreshAnnotatedCallLogWorker.refresh", "submitting serialized refresh request");
     return dialerFutureSerializer.submitAsync(
         () -> checkDirtyAndRebuildIfNecessary(checkDirty), lightweightExecutorService);
   }
 
-  private ListenableFuture<Void> checkDirtyAndRebuildIfNecessary(boolean checkDirty) {
+  private ListenableFuture<RefreshResult> checkDirtyAndRebuildIfNecessary(boolean checkDirty) {
     ListenableFuture<Boolean> forceRebuildFuture =
         backgroundExecutorService.submit(
             () -> {
@@ -139,7 +146,7 @@ public class RefreshAnnotatedCallLogWorker {
             return Futures.transformAsync(
                 callLogState.isBuilt(), this::rebuild, MoreExecutors.directExecutor());
           }
-          return Futures.immediateFuture(null);
+          return Futures.immediateFuture(RefreshResult.NOT_DIRTY);
         },
         lightweightExecutorService);
   }
@@ -160,7 +167,7 @@ public class RefreshAnnotatedCallLogWorker {
     return isDirtyFuture;
   }
 
-  private ListenableFuture<Void> rebuild(boolean isBuilt) {
+  private ListenableFuture<RefreshResult> rebuild(boolean isBuilt) {
     CallLogMutations mutations = new CallLogMutations();
 
     // Start by filling the data sources--the system call log data source must go first!
@@ -225,7 +232,9 @@ public class RefreshAnnotatedCallLogWorker {
         unused -> {
           sharedPreferences.edit().putBoolean(SharedPrefKeys.FORCE_REBUILD, false).apply();
           callLogState.markBuilt();
-          return null;
+          return mutations.isEmpty()
+              ? RefreshResult.REBUILT_BUT_NO_CHANGES_NEEDED
+              : RefreshResult.REBUILT_AND_CHANGES_NEEDED;
         },
         backgroundExecutorService);
   }
diff --git a/java/com/android/dialer/calllog/database/AnnotatedCallLogContentProvider.java b/java/com/android/dialer/calllog/database/AnnotatedCallLogContentProvider.java
index 77de62ea4..69722731e 100644
--- a/java/com/android/dialer/calllog/database/AnnotatedCallLogContentProvider.java
+++ b/java/com/android/dialer/calllog/database/AnnotatedCallLogContentProvider.java
@@ -37,6 +37,8 @@ import com.android.dialer.calllog.database.contract.AnnotatedCallLogContract.Ann
 import com.android.dialer.calllog.database.contract.AnnotatedCallLogContract.CoalescedAnnotatedCallLog;
 import com.android.dialer.common.Assert;
 import com.android.dialer.common.LogUtil;
+import com.android.dialer.metrics.Metrics;
+import com.android.dialer.metrics.MetricsComponent;
 import java.util.ArrayList;
 import java.util.Arrays;
 
@@ -153,6 +155,7 @@ public class AnnotatedCallLogContentProvider extends ContentProvider {
         Assert.checkArgument(
             selectionArgs == null, "selection args not supported for coalesced call log");
         Assert.checkArgument(sortOrder == null, "sort order not supported for coalesced call log");
+        MetricsComponent.get(getContext()).metrics().startTimer(Metrics.NEW_CALL_LOG_COALESCE);
         try (Cursor allAnnotatedCallLogRows =
             queryBuilder.query(
                 db,
@@ -168,6 +171,7 @@ public class AnnotatedCallLogContentProvider extends ContentProvider {
                   .coalesce(allAnnotatedCallLogRows);
           coalescedRows.setNotificationUri(
               getContext().getContentResolver(), CoalescedAnnotatedCallLog.CONTENT_URI);
+          MetricsComponent.get(getContext()).metrics().stopTimer(Metrics.NEW_CALL_LOG_COALESCE);
           return coalescedRows;
         }
       default:
diff --git a/java/com/android/dialer/metrics/FutureTimer.java b/java/com/android/dialer/metrics/FutureTimer.java
index f7ba3feef..a45fb3835 100644
--- a/java/com/android/dialer/metrics/FutureTimer.java
+++ b/java/com/android/dialer/metrics/FutureTimer.java
@@ -21,6 +21,7 @@ import android.support.annotation.IntDef;
 import android.support.annotation.VisibleForTesting;
 import com.android.dialer.common.LogUtil;
 import com.android.dialer.common.concurrent.Annotations.LightweightExecutor;
+import com.google.common.base.Function;
 import com.google.common.util.concurrent.FutureCallback;
 import com.google.common.util.concurrent.Futures;
 import com.google.common.util.concurrent.ListenableFuture;
@@ -72,7 +73,7 @@ public final class FutureTimer {
    * of tracking heavyweight operations (which is what this method is intended for).
    */
   public <T> void applyTiming(ListenableFuture<T> future, String eventName) {
-    applyTiming(future, eventName, LogCatMode.DONT_LOG_VALUES);
+    applyTiming(future, unused -> eventName, LogCatMode.DONT_LOG_VALUES);
   }
 
   /**
@@ -81,14 +82,35 @@ public final class FutureTimer {
    */
   public <T> void applyTiming(
       ListenableFuture<T> future, String eventName, @LogCatMode int logCatMode) {
+    applyTiming(future, unused -> eventName, logCatMode);
+  }
+
+  /**
+   * Overload of {@link #applyTiming(ListenableFuture, String)} that accepts a function which
+   * specifies how to compute an event name from the result of the future.
+   *
+   * <p>This is useful when the event name depends on the result of the future.
+   */
+  public <T> void applyTiming(
+      ListenableFuture<T> future, Function<T, String> eventNameFromResultFunction) {
+    applyTiming(future, eventNameFromResultFunction, LogCatMode.DONT_LOG_VALUES);
+  }
+
+  private <T> void applyTiming(
+      ListenableFuture<T> future,
+      Function<T, String> eventNameFromResultFunction,
+      @LogCatMode int logCatMode) {
     long startTime = SystemClock.elapsedRealtime();
-    metrics.startTimer(eventName);
+    Integer timerId = metrics.startUnnamedTimer();
     Futures.addCallback(
         future,
         new FutureCallback<T>() {
           @Override
           public void onSuccess(T result) {
-            metrics.stopTimer(eventName);
+            String eventName = eventNameFromResultFunction.apply(result);
+            if (timerId != null) {
+              metrics.stopUnnamedTimer(timerId, eventName);
+            }
             long operationTime = SystemClock.elapsedRealtime() - startTime;
 
             // If the operation took a long time, do some WARNING logging.
diff --git a/java/com/android/dialer/metrics/Metrics.java b/java/com/android/dialer/metrics/Metrics.java
index b460f3ecf..e9e22c353 100644
--- a/java/com/android/dialer/metrics/Metrics.java
+++ b/java/com/android/dialer/metrics/Metrics.java
@@ -17,6 +17,7 @@
 package com.android.dialer.metrics;
 
 import android.app.Application;
+import android.support.annotation.Nullable;
 
 /** Logs metrics. */
 public interface Metrics {
@@ -36,6 +37,14 @@ public interface Metrics {
   String NEW_CALL_LOG_JANK_EVENT_NAME = "NewCallLog.Jank";
 
   // Events related to refreshing the annotated call log.
+  String NEW_CALL_LOG_COALESCE = "NewCallLog.Coalesce";
+  String REFRESH_NOT_DIRTY = "RefreshAnnotatedCallLogReceiver.NotDirty";
+  String REFRESH_CHANGES_NEEDED = "RefreshAnnotatedCallLogReceiver.ChangesNeeded";
+  String REFRESH_NO_CHANGES_NEEDED = "RefreshAnnotatedCallLogReceiver.NoChangesNeeded";
+  String FORCE_REFRESH_CHANGES_NEEDED = "RefreshAnnotatedCallLogReceiver.ForceRefreshChangesNeeded";
+  String FORCE_REFRESH_NO_CHANGES_NEEDED =
+      "RefreshAnnotatedCallLogReceiver.ForceRefreshNoChangesNeeded";
+
   String INITIAL_FILL_EVENT_NAME = "RefreshAnnotatedCallLog.Initial.Fill";
   String INITIAL_ON_SUCCESSFUL_FILL_EVENT_NAME = "RefreshAnnotatedCallLog.Initial.OnSuccessfulFill";
   String INITIAL_APPLY_MUTATIONS_EVENT_NAME = "RefreshAnnotatedCallLog.Initial.ApplyMutations";
@@ -61,6 +70,23 @@ public interface Metrics {
   /** Start a timer. */
   void startTimer(String timerEventName);
 
+  /**
+   * Starts a timer for which the name is not yet known.
+   *
+   * @return opaque identifier for the event which should be provided back to {@link
+   *     #stopUnnamedTimer(int, String)} to stop the timer. Null if the timer cannot be started, for
+   *     example because the user is locked.
+   */
+  @Nullable
+  Integer startUnnamedTimer();
+
+  /**
+   * Stop a timer which was started with {@link #startUnnamedTimer()}.
+   *
+   * @param timerId the value returned in the corresponding call to {@link #startUnnamedTimer()}
+   */
+  void stopUnnamedTimer(int timerId, String timerEventName);
+
   /** Stop a timer. */
   void stopTimer(String timerEventName);
 
diff --git a/java/com/android/dialer/metrics/MetricsComponent.java b/java/com/android/dialer/metrics/MetricsComponent.java
index f37129791..a3570db10 100644
--- a/java/com/android/dialer/metrics/MetricsComponent.java
+++ b/java/com/android/dialer/metrics/MetricsComponent.java
@@ -28,6 +28,8 @@ public abstract class MetricsComponent {
 
   public abstract Metrics.Initializer metricsInitializer();
 
+  public abstract FutureTimer futureTimer();
+
   public static MetricsComponent get(Context context) {
     return ((MetricsComponent.HasComponent)
             ((HasRootComponent) context.getApplicationContext()).component())
diff --git a/java/com/android/dialer/metrics/StubMetrics.java b/java/com/android/dialer/metrics/StubMetrics.java
index 99c3d7691..ecd2382b9 100644
--- a/java/com/android/dialer/metrics/StubMetrics.java
+++ b/java/com/android/dialer/metrics/StubMetrics.java
@@ -16,26 +16,91 @@
 
 package com.android.dialer.metrics;
 
+import android.os.SystemClock;
+import com.android.dialer.common.Assert;
+import com.android.dialer.common.LogUtil;
+import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.ConcurrentMap;
+import javax.annotation.concurrent.ThreadSafe;
 import javax.inject.Inject;
+import javax.inject.Singleton;
 
-/** Stub {@link Metrics}. */
+/** Stub {@link Metrics} which simply logs debug messages to logcat. */
+@ThreadSafe
+@Singleton
 public final class StubMetrics implements Metrics {
 
+  private final ConcurrentMap<String, StubTimerEvent> namedEvents = new ConcurrentHashMap<>();
+  private final ConcurrentMap<Integer, StubTimerEvent> unnamedEvents = new ConcurrentHashMap<>();
+
   @Inject
   StubMetrics() {}
 
   @Override
-  public void startTimer(String timerEventName) {}
+  public void startTimer(String timerEventName) {
+    namedEvents.put(timerEventName, new StubTimerEvent());
+  }
 
   @Override
-  public void stopTimer(String timerEventName) {}
+  public Integer startUnnamedTimer() {
+    StubTimerEvent stubTimerEvent = new StubTimerEvent();
+    int id = stubTimerEvent.hashCode();
+    LogUtil.d("StubMetrics.startUnnamedTimer", "started timer for id: %d", id);
+    unnamedEvents.put(id, stubTimerEvent);
+    return id;
+  }
 
   @Override
-  public void startJankRecorder(String eventName) {}
+  public void stopTimer(String timerEventName) {
+    StubTimerEvent stubTimerEvent = namedEvents.remove(timerEventName);
+    if (stubTimerEvent == null) {
+      return;
+    }
+
+    LogUtil.d(
+        "StubMetrics.stopTimer",
+        "%s took %dms",
+        timerEventName,
+        SystemClock.elapsedRealtime() - stubTimerEvent.startTime);
+  }
+
+  @Override
+  public void stopUnnamedTimer(int timerId, String timerEventName) {
+    long startTime =
+        Assert.isNotNull(
+                unnamedEvents.remove(timerId),
+                "no timer found for id: %d (%s)",
+                timerId,
+                timerEventName)
+            .startTime;
+
+    LogUtil.d(
+        "StubMetrics.stopUnnamedTimer",
+        "%s took %dms",
+        timerEventName,
+        SystemClock.elapsedRealtime() - startTime);
+  }
 
   @Override
-  public void stopJankRecorder(String eventName) {}
+  public void startJankRecorder(String eventName) {
+    LogUtil.d("StubMetrics.startJankRecorder", "started jank recorder for %s", eventName);
+  }
 
   @Override
-  public void recordMemory(String memoryEventName) {}
+  public void stopJankRecorder(String eventName) {
+    LogUtil.d("StubMetrics.startJankRecorder", "stopped jank recorder for %s", eventName);
+  }
+
+  @Override
+  public void recordMemory(String memoryEventName) {
+    LogUtil.d("StubMetrics.startJankRecorder", "recorded memory for %s", memoryEventName);
+  }
+
+  private static class StubTimerEvent {
+    final long startTime;
+
+    StubTimerEvent() {
+      this.startTime = SystemClock.elapsedRealtime();
+    }
+  }
 }