Merge "Added some logcat and metrics logging for new call log."

6 files changed, 299 insertions, 72 deletions

diff --git a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
index a430d14a8..3765831ae 100644
--- a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
+++ b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
@@ -19,7 +19,7 @@ package com.android.dialer.calllog;
 import android.content.Context;
 import android.content.SharedPreferences;
 import com.android.dialer.calllog.constants.SharedPrefKeys;
-import com.android.dialer.calllog.database.CallLogDatabaseComponent;
+import com.android.dialer.calllog.database.MutationApplier;
 import com.android.dialer.calllog.datasources.CallLogDataSource;
 import com.android.dialer.calllog.datasources.CallLogMutations;
 import com.android.dialer.calllog.datasources.DataSources;
@@ -29,6 +29,9 @@ import com.android.dialer.common.concurrent.Annotations.LightweightExecutor;
 import com.android.dialer.common.concurrent.DialerFutureSerializer;
 import com.android.dialer.common.concurrent.DialerFutures;
 import com.android.dialer.inject.ApplicationContext;
+import com.android.dialer.metrics.FutureTimer;
+import com.android.dialer.metrics.FutureTimer.LogCatMode;
+import com.android.dialer.metrics.Metrics;
 import com.android.dialer.storage.Unencrypted;
 import com.google.common.base.Preconditions;
 import com.google.common.util.concurrent.Futures;
@@ -46,6 +49,8 @@ public class RefreshAnnotatedCallLogWorker {
   private final Context appContext;
   private final DataSources dataSources;
   private final SharedPreferences sharedPreferences;
+  private final MutationApplier mutationApplier;
+  private final FutureTimer futureTimer;
   private final ListeningExecutorService backgroundExecutorService;
   private final ListeningExecutorService lightweightExecutorService;
   // Used to ensure that only one refresh flow runs at a time. (Note that
@@ -57,11 +62,15 @@ public class RefreshAnnotatedCallLogWorker {
       @ApplicationContext Context appContext,
       DataSources dataSources,
       @Unencrypted SharedPreferences sharedPreferences,
+      MutationApplier mutationApplier,
+      FutureTimer futureTimer,
       @BackgroundExecutor ListeningExecutorService backgroundExecutorService,
       @LightweightExecutor ListeningExecutorService lightweightExecutorService) {
     this.appContext = appContext;
     this.dataSources = dataSources;
     this.sharedPreferences = sharedPreferences;
+    this.mutationApplier = mutationApplier;
+    this.futureTimer = futureTimer;
     this.backgroundExecutorService = backgroundExecutorService;
     this.lightweightExecutorService = lightweightExecutorService;
   }
@@ -79,11 +88,10 @@ public class RefreshAnnotatedCallLogWorker {
   private ListenableFuture<Void> refresh(boolean checkDirty) {
     LogUtil.i("RefreshAnnotatedCallLogWorker.refresh", "submitting serialized refresh request");
     return dialerFutureSerializer.submitAsync(
-        () -> checkDirtyAndRebuildIfNecessary(appContext, checkDirty), lightweightExecutorService);
+        () -> checkDirtyAndRebuildIfNecessary(checkDirty), lightweightExecutorService);
   }
 
-  private ListenableFuture<Void> checkDirtyAndRebuildIfNecessary(
-      Context appContext, boolean checkDirty) {
+  private ListenableFuture<Void> checkDirtyAndRebuildIfNecessary(boolean checkDirty) {
     ListenableFuture<Boolean> forceRebuildFuture =
         backgroundExecutorService.submit(
             () -> {
@@ -112,7 +120,7 @@ public class RefreshAnnotatedCallLogWorker {
             forceRebuild ->
                 Preconditions.checkNotNull(forceRebuild)
                     ? Futures.immediateFuture(true)
-                    : isDirty(appContext),
+                    : isDirty(),
             lightweightExecutorService);
 
     // After determining isDirty, conditionally call rebuild.
@@ -123,26 +131,36 @@ public class RefreshAnnotatedCallLogWorker {
               "RefreshAnnotatedCallLogWorker.checkDirtyAndRebuildIfNecessary",
               "isDirty: %b",
               Preconditions.checkNotNull(isDirty));
-          return isDirty ? rebuild(appContext) : Futures.immediateFuture(null);
+          return isDirty ? rebuild() : Futures.immediateFuture(null);
         },
         lightweightExecutorService);
   }
 
-  private ListenableFuture<Boolean> isDirty(Context appContext) {
+  private ListenableFuture<Boolean> isDirty() {
     List<ListenableFuture<Boolean>> isDirtyFutures = new ArrayList<>();
     for (CallLogDataSource dataSource : dataSources.getDataSourcesIncludingSystemCallLog()) {
-      isDirtyFutures.add(dataSource.isDirty(appContext));
+      ListenableFuture<Boolean> dataSourceDirty = dataSource.isDirty(appContext);
+      isDirtyFutures.add(dataSourceDirty);
+      String eventName =
+          String.format(Metrics.IS_DIRTY_TEMPLATE, dataSource.getClass().getSimpleName());
+      futureTimer.applyTiming(dataSourceDirty, eventName, LogCatMode.LOG_VALUES);
     }
     // Simultaneously invokes isDirty on all data sources, returning as soon as one returns true.
-    return DialerFutures.firstMatching(isDirtyFutures, Preconditions::checkNotNull, false);
+    ListenableFuture<Boolean> isDirtyFuture =
+        DialerFutures.firstMatching(isDirtyFutures, Preconditions::checkNotNull, false);
+    futureTimer.applyTiming(isDirtyFuture, Metrics.IS_DIRTY_EVENT_NAME, LogCatMode.LOG_VALUES);
+    return isDirtyFuture;
   }
 
-  private ListenableFuture<Void> rebuild(Context appContext) {
+  private ListenableFuture<Void> rebuild() {
     CallLogMutations mutations = new CallLogMutations();
 
     // Start by filling the data sources--the system call log data source must go first!
     CallLogDataSource systemCallLogDataSource = dataSources.getSystemCallLogDataSource();
     ListenableFuture<Void> fillFuture = systemCallLogDataSource.fill(appContext, mutations);
+    String systemEventName =
+        String.format(Metrics.FILL_TEMPLATE, systemCallLogDataSource.getClass().getSimpleName());
+    futureTimer.applyTiming(fillFuture, systemEventName);
 
     // After the system call log data source is filled, call fill sequentially on each remaining
     // data source. This must be done sequentially because mutations are not threadsafe and are
@@ -151,19 +169,28 @@ public class RefreshAnnotatedCallLogWorker {
       fillFuture =
           Futures.transformAsync(
               fillFuture,
-              unused -> dataSource.fill(appContext, mutations),
+              unused -> {
+                ListenableFuture<Void> dataSourceFuture = dataSource.fill(appContext, mutations);
+                String eventName =
+                    String.format(Metrics.FILL_TEMPLATE, dataSource.getClass().getSimpleName());
+                futureTimer.applyTiming(dataSourceFuture, eventName);
+                return dataSourceFuture;
+              },
               lightweightExecutorService);
     }
+    futureTimer.applyTiming(fillFuture, Metrics.FILL_EVENT_NAME);
 
     // After all data sources are filled, apply mutations (at this point "fillFuture" is the result
     // of filling the last data source).
     ListenableFuture<Void> applyMutationsFuture =
         Futures.transformAsync(
             fillFuture,
-            unused ->
-                CallLogDatabaseComponent.get(appContext)
-                    .mutationApplier()
-                    .applyToDatabase(mutations, appContext),
+            unused -> {
+              ListenableFuture<Void> mutationApplierFuture =
+                  mutationApplier.applyToDatabase(mutations, appContext);
+              futureTimer.applyTiming(mutationApplierFuture, Metrics.APPLY_MUTATIONS_EVENT_NAME);
+              return mutationApplierFuture;
+            },
             lightweightExecutorService);
 
     // After mutations applied, call onSuccessfulFill for each data source (in parallel).
@@ -174,9 +201,16 @@ public class RefreshAnnotatedCallLogWorker {
               List<ListenableFuture<Void>> onSuccessfulFillFutures = new ArrayList<>();
               for (CallLogDataSource dataSource :
                   dataSources.getDataSourcesIncludingSystemCallLog()) {
-                onSuccessfulFillFutures.add(dataSource.onSuccessfulFill(appContext));
+                ListenableFuture<Void> dataSourceFuture = dataSource.onSuccessfulFill(appContext);
+                onSuccessfulFillFutures.add(dataSourceFuture);
+                String eventName =
+                    String.format(
+                        Metrics.ON_SUCCESSFUL_FILL_TEMPLATE, dataSource.getClass().getSimpleName());
+                futureTimer.applyTiming(dataSourceFuture, eventName);
               }
-              return Futures.allAsList(onSuccessfulFillFutures);
+              ListenableFuture<List<Void>> allFutures = Futures.allAsList(onSuccessfulFillFutures);
+              futureTimer.applyTiming(allFutures, Metrics.ON_SUCCESSFUL_FILL_EVENT_NAME);
+              return allFutures;
             },
             lightweightExecutorService);
 
diff --git a/java/com/android/dialer/calllog/database/CallLogDatabaseComponent.java b/java/com/android/dialer/calllog/database/CallLogDatabaseComponent.java
index ede46911c..991237449 100644
--- a/java/com/android/dialer/calllog/database/CallLogDatabaseComponent.java
+++ b/java/com/android/dialer/calllog/database/CallLogDatabaseComponent.java
@@ -25,8 +25,6 @@ public abstract class CallLogDatabaseComponent {
 
   public abstract Coalescer coalescer();
 
-  public abstract MutationApplier mutationApplier();
-
   public static CallLogDatabaseComponent get(Context context) {
     return ((CallLogDatabaseComponent.HasComponent)
             ((HasRootComponent) context.getApplicationContext()).component())
diff --git a/java/com/android/dialer/calllog/database/MutationApplier.java b/java/com/android/dialer/calllog/database/MutationApplier.java
index c9edd3ee1..86109343b 100644
--- a/java/com/android/dialer/calllog/database/MutationApplier.java
+++ b/java/com/android/dialer/calllog/database/MutationApplier.java
@@ -45,7 +45,7 @@ public class MutationApplier {
   private final ListeningExecutorService backgroundExecutorService;
 
   @Inject
-  MutationApplier(@BackgroundExecutor ListeningExecutorService backgroundExecutorService) {
+  public MutationApplier(@BackgroundExecutor ListeningExecutorService backgroundExecutorService) {
     this.backgroundExecutorService = backgroundExecutorService;
   }
 
diff --git a/java/com/android/dialer/metrics/FutureTimer.java b/java/com/android/dialer/metrics/FutureTimer.java
new file mode 100644
index 000000000..f7ba3feef
--- /dev/null
+++ b/java/com/android/dialer/metrics/FutureTimer.java
@@ -0,0 +1,147 @@
+/*
+ * Copyright (C) 2018 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License
+ */
+
+package com.android.dialer.metrics;
+
+import android.os.SystemClock;
+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.util.concurrent.FutureCallback;
+import com.google.common.util.concurrent.Futures;
+import com.google.common.util.concurrent.ListenableFuture;
+import com.google.common.util.concurrent.ListeningExecutorService;
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
+import javax.inject.Inject;
+
+/** Applies logcat and metric logging to a supplied future. */
+public final class FutureTimer {
+
+  /** Operations which exceed this threshold will have logcat warnings printed. */
+  @VisibleForTesting static final long LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS = 100L;
+
+  private final Metrics metrics;
+  private final ListeningExecutorService lightweightExecutorService;
+
+  /** Modes for logging Future results to logcat. */
+  @Retention(RetentionPolicy.SOURCE)
+  @IntDef({LogCatMode.DONT_LOG_VALUES, LogCatMode.LOG_VALUES})
+  public @interface LogCatMode {
+    /**
+     * Don't ever log the result of the future to logcat. For example, may be appropriate if your
+     * future returns a proto and you don't want to spam the logs with multi-line entries, or if
+     * your future returns void/null and so would have no value being logged.
+     */
+    int DONT_LOG_VALUES = 1;
+    /**
+     * Always log the result of the future to logcat (at DEBUG level). Useful when your future
+     * returns a type which has a short and useful string representation (such as a boolean). PII
+     * will be sanitized.
+     */
+    int LOG_VALUES = 2;
+  }
+
+  @Inject
+  public FutureTimer(
+      Metrics metrics, @LightweightExecutor ListeningExecutorService lightweightExecutorService) {
+    this.metrics = metrics;
+    this.lightweightExecutorService = lightweightExecutorService;
+  }
+
+  /**
+   * Applies logcat and metric logging to the supplied future.
+   *
+   * <p>This should be called as soon as possible after the future is submitted for execution, as
+   * timing is not started until this method is called. While work for the supplied future may have
+   * already begun, the time elapsed since it started is expected to be negligible for the purposes
+   * 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);
+  }
+
+  /**
+   * Overload of {@link #applyTiming(ListenableFuture, String)} which allows setting of the {@link
+   * LogCatMode}.
+   */
+  public <T> void applyTiming(
+      ListenableFuture<T> future, String eventName, @LogCatMode int logCatMode) {
+    long startTime = SystemClock.elapsedRealtime();
+    metrics.startTimer(eventName);
+    Futures.addCallback(
+        future,
+        new FutureCallback<T>() {
+          @Override
+          public void onSuccess(T result) {
+            metrics.stopTimer(eventName);
+            long operationTime = SystemClock.elapsedRealtime() - startTime;
+
+            // If the operation took a long time, do some WARNING logging.
+            if (operationTime > LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS) {
+              switch (logCatMode) {
+                case LogCatMode.DONT_LOG_VALUES:
+                  LogUtil.w(
+                      "FutureTimer.onSuccess",
+                      "%s took more than %dms (took %dms)",
+                      eventName,
+                      LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS,
+                      operationTime);
+                  break;
+                case LogCatMode.LOG_VALUES:
+                  LogUtil.w(
+                      "FutureTimer.onSuccess",
+                      "%s took more than %dms (took %dms and returned %s)",
+                      eventName,
+                      LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS,
+                      operationTime,
+                      LogUtil.sanitizePii(result));
+                  break;
+                default:
+                  throw new UnsupportedOperationException("unknown logcat mode: " + logCatMode);
+              }
+              return;
+            }
+
+            // The operation didn't take a long time, so just do some DEBUG logging.
+            if (LogUtil.isDebugEnabled()) {
+              switch (logCatMode) {
+                case LogCatMode.DONT_LOG_VALUES:
+                  // Operation was fast and we're not logging values, so don't log anything.
+                  break;
+                case LogCatMode.LOG_VALUES:
+                  LogUtil.d(
+                      "FutureTimer.onSuccess",
+                      "%s took %dms and returned %s",
+                      eventName,
+                      operationTime,
+                      LogUtil.sanitizePii(result));
+                  break;
+                default:
+                  throw new UnsupportedOperationException("unknown logcat mode: " + logCatMode);
+              }
+            }
+          }
+
+          @Override
+          public void onFailure(Throwable throwable) {
+            // This callback is just for logging performance metrics; errors are handled elsewhere.
+          }
+        },
+        lightweightExecutorService);
+  }
+}
diff --git a/java/com/android/dialer/metrics/Metrics.java b/java/com/android/dialer/metrics/Metrics.java
index 9488f3068..8c18ac942 100644
--- a/java/com/android/dialer/metrics/Metrics.java
+++ b/java/com/android/dialer/metrics/Metrics.java
@@ -33,6 +33,20 @@ public interface Metrics {
   String OLD_CALL_LOG_JANK_EVENT_NAME = "OldCallLog.Jank";
   String NEW_CALL_LOG_JANK_EVENT_NAME = "NewCallLog.Jank";
 
+  // Events related to refreshing the annotated call log.
+  String IS_DIRTY_EVENT_NAME = "RefreshAnnotatedCallLog.IsDirty";
+  String FILL_EVENT_NAME = "RefreshAnnotatedCallLog.Fill";
+  String ON_SUCCESSFUL_FILL_EVENT_NAME = "RefreshAnnotatedCallLog.OnSuccessfulFill";
+  String APPLY_MUTATIONS_EVENT_NAME = "RefreshAnnotatedCallLog.ApplyMutations";
+
+  // These templates are prefixed with a CallLogDataSource or PhoneLookup simple class name.
+  String IS_DIRTY_TEMPLATE = "%s.IsDirty";
+  String FILL_TEMPLATE = "%s.Fill";
+  String GET_MOST_RECENT_INFO_TEMPLATE = "%s.GetMostRecentInfo";
+  String ON_SUCCESSFUL_FILL_TEMPLATE = "%s.OnSuccessfulFill";
+  String ON_SUCCESSFUL_BULK_UPDATE_TEMPLATE = "%s.OnSuccessfulBulkUpdate";
+  String LOOKUP_TEMPLATE = "%s.Lookup";
+
   /** Start a timer. */
   void startTimer(String timerEventName);
 
diff --git a/java/com/android/dialer/phonelookup/composite/CompositePhoneLookup.java b/java/com/android/dialer/phonelookup/composite/CompositePhoneLookup.java
index abe18f7dc..7be7732e3 100644
--- a/java/com/android/dialer/phonelookup/composite/CompositePhoneLookup.java
+++ b/java/com/android/dialer/phonelookup/composite/CompositePhoneLookup.java
@@ -22,8 +22,12 @@ import com.android.dialer.DialerPhoneNumber;
 import com.android.dialer.common.LogUtil;
 import com.android.dialer.common.concurrent.Annotations.LightweightExecutor;
 import com.android.dialer.common.concurrent.DialerFutures;
+import com.android.dialer.metrics.FutureTimer;
+import com.android.dialer.metrics.FutureTimer.LogCatMode;
+import com.android.dialer.metrics.Metrics;
 import com.android.dialer.phonelookup.PhoneLookup;
 import com.android.dialer.phonelookup.PhoneLookupInfo;
+import com.android.dialer.phonelookup.PhoneLookupInfo.Builder;
 import com.google.common.base.Preconditions;
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableMap;
@@ -32,7 +36,6 @@ import com.google.common.collect.Maps;
 import com.google.common.util.concurrent.Futures;
 import com.google.common.util.concurrent.ListenableFuture;
 import com.google.common.util.concurrent.ListeningExecutorService;
-import com.google.common.util.concurrent.MoreExecutors;
 import java.util.ArrayList;
 import java.util.List;
 import java.util.Map;
@@ -45,13 +48,16 @@ import javax.inject.Inject;
 public final class CompositePhoneLookup implements PhoneLookup<PhoneLookupInfo> {
 
   private final ImmutableList<PhoneLookup> phoneLookups;
+  private final FutureTimer futureTimer;
   private final ListeningExecutorService lightweightExecutorService;
 
   @Inject
   CompositePhoneLookup(
       ImmutableList<PhoneLookup> phoneLookups,
+      FutureTimer futureTimer,
       @LightweightExecutor ListeningExecutorService lightweightExecutorService) {
     this.phoneLookups = phoneLookups;
+    this.futureTimer = futureTimer;
     this.lightweightExecutorService = lightweightExecutorService;
   }
 
@@ -68,42 +74,48 @@ public final class CompositePhoneLookup implements PhoneLookup<PhoneLookupInfo>
     // lookups finishing when a higher-priority one has already finished.
     List<ListenableFuture<?>> futures = new ArrayList<>();
     for (PhoneLookup<?> phoneLookup : phoneLookups) {
-      futures.add(phoneLookup.lookup(dialerPhoneNumber));
+      ListenableFuture<?> lookupFuture = phoneLookup.lookup(dialerPhoneNumber);
+      String eventName =
+          String.format(Metrics.LOOKUP_TEMPLATE, phoneLookup.getClass().getSimpleName());
+      futureTimer.applyTiming(lookupFuture, eventName);
+      futures.add(lookupFuture);
     }
-    return Futures.transform(
-        Futures.allAsList(futures),
-        infos -> {
-          PhoneLookupInfo.Builder mergedInfo = PhoneLookupInfo.newBuilder();
-          for (int i = 0; i < infos.size(); i++) {
-            PhoneLookup phoneLookup = phoneLookups.get(i);
-            phoneLookup.setSubMessage(mergedInfo, infos.get(i));
-          }
-          return mergedInfo.build();
-        },
-        lightweightExecutorService);
+    ListenableFuture<PhoneLookupInfo> combinedFuture =
+        Futures.transform(
+            Futures.allAsList(futures),
+            infos -> {
+              Builder mergedInfo = PhoneLookupInfo.newBuilder();
+              for (int i = 0; i < infos.size(); i++) {
+                PhoneLookup phoneLookup = phoneLookups.get(i);
+                phoneLookup.setSubMessage(mergedInfo, infos.get(i));
+              }
+              return mergedInfo.build();
+            },
+            lightweightExecutorService);
+    String eventName =
+        String.format(Metrics.LOOKUP_TEMPLATE, CompositePhoneLookup.class.getSimpleName());
+    futureTimer.applyTiming(combinedFuture, eventName);
+    return combinedFuture;
   }
 
   @Override
   public ListenableFuture<Boolean> isDirty(ImmutableSet<DialerPhoneNumber> phoneNumbers) {
     List<ListenableFuture<Boolean>> futures = new ArrayList<>();
     for (PhoneLookup<?> phoneLookup : phoneLookups) {
-      futures.add(
-          Futures.transform(
-              phoneLookup.isDirty(phoneNumbers),
-              isDirty -> {
-                LogUtil.v(
-                    "CompositePhoneLookup.isDirty",
-                    "isDirty for %s: %b",
-                    phoneLookup.getClass().getSimpleName(),
-                    isDirty);
-                return isDirty;
-              },
-              MoreExecutors.directExecutor()));
+      ListenableFuture<Boolean> isDirtyFuture = phoneLookup.isDirty(phoneNumbers);
+      futures.add(isDirtyFuture);
+      String eventName =
+          String.format(Metrics.IS_DIRTY_TEMPLATE, phoneLookup.getClass().getSimpleName());
+      futureTimer.applyTiming(isDirtyFuture, eventName, LogCatMode.LOG_VALUES);
     }
     // Executes all child lookups (possibly in parallel), completing when the first composite lookup
     // which returns "true" completes, and cancels the others.
-    return DialerFutures.firstMatching(
-        futures, Preconditions::checkNotNull, false /* defaultValue */);
+    ListenableFuture<Boolean> firstMatching =
+        DialerFutures.firstMatching(futures, Preconditions::checkNotNull, false /* defaultValue */);
+    String eventName =
+        String.format(Metrics.IS_DIRTY_TEMPLATE, CompositePhoneLookup.class.getSimpleName());
+    futureTimer.applyTiming(firstMatching, eventName, LogCatMode.LOG_VALUES);
+    return firstMatching;
   }
 
   /**
@@ -120,28 +132,34 @@ public final class CompositePhoneLookup implements PhoneLookup<PhoneLookupInfo>
     for (PhoneLookup phoneLookup : phoneLookups) {
       futures.add(buildSubmapAndGetMostRecentInfo(existingInfoMap, phoneLookup));
     }
-    return Futures.transform(
-        Futures.allAsList(futures),
-        (allMaps) -> {
-          ImmutableMap.Builder<DialerPhoneNumber, PhoneLookupInfo> combinedMap =
-              ImmutableMap.builder();
-          for (DialerPhoneNumber dialerPhoneNumber : existingInfoMap.keySet()) {
-            PhoneLookupInfo.Builder combinedInfo = PhoneLookupInfo.newBuilder();
-            for (int i = 0; i < allMaps.size(); i++) {
-              ImmutableMap<DialerPhoneNumber, ?> map = allMaps.get(i);
-              Object subInfo = map.get(dialerPhoneNumber);
-              if (subInfo == null) {
-                throw new IllegalStateException(
-                    "A sublookup didn't return an info for number: "
-                        + LogUtil.sanitizePhoneNumber(dialerPhoneNumber.getNormalizedNumber()));
+    ListenableFuture<ImmutableMap<DialerPhoneNumber, PhoneLookupInfo>> combinedFuture =
+        Futures.transform(
+            Futures.allAsList(futures),
+            (allMaps) -> {
+              ImmutableMap.Builder<DialerPhoneNumber, PhoneLookupInfo> combinedMap =
+                  ImmutableMap.builder();
+              for (DialerPhoneNumber dialerPhoneNumber : existingInfoMap.keySet()) {
+                PhoneLookupInfo.Builder combinedInfo = PhoneLookupInfo.newBuilder();
+                for (int i = 0; i < allMaps.size(); i++) {
+                  ImmutableMap<DialerPhoneNumber, ?> map = allMaps.get(i);
+                  Object subInfo = map.get(dialerPhoneNumber);
+                  if (subInfo == null) {
+                    throw new IllegalStateException(
+                        "A sublookup didn't return an info for number: "
+                            + LogUtil.sanitizePhoneNumber(dialerPhoneNumber.getNormalizedNumber()));
+                  }
+                  phoneLookups.get(i).setSubMessage(combinedInfo, subInfo);
+                }
+                combinedMap.put(dialerPhoneNumber, combinedInfo.build());
               }
-              phoneLookups.get(i).setSubMessage(combinedInfo, subInfo);
-            }
-            combinedMap.put(dialerPhoneNumber, combinedInfo.build());
-          }
-          return combinedMap.build();
-        },
-        lightweightExecutorService);
+              return combinedMap.build();
+            },
+            lightweightExecutorService);
+    String eventName =
+        String.format(
+            Metrics.GET_MOST_RECENT_INFO_TEMPLATE, CompositePhoneLookup.class.getSimpleName());
+    futureTimer.applyTiming(combinedFuture, eventName);
+    return combinedFuture;
   }
 
   private <T> ListenableFuture<ImmutableMap<DialerPhoneNumber, T>> buildSubmapAndGetMostRecentInfo(
@@ -152,7 +170,13 @@ public final class CompositePhoneLookup implements PhoneLookup<PhoneLookupInfo>
             existingInfoMap,
             (dialerPhoneNumber, phoneLookupInfo) ->
                 phoneLookup.getSubMessage(existingInfoMap.get(dialerPhoneNumber)));
-    return phoneLookup.getMostRecentInfo(ImmutableMap.copyOf(submap));
+    ListenableFuture<ImmutableMap<DialerPhoneNumber, T>> mostRecentInfoFuture =
+        phoneLookup.getMostRecentInfo(ImmutableMap.copyOf(submap));
+    String eventName =
+        String.format(
+            Metrics.GET_MOST_RECENT_INFO_TEMPLATE, phoneLookup.getClass().getSimpleName());
+    futureTimer.applyTiming(mostRecentInfoFuture, eventName);
+    return mostRecentInfoFuture;
   }
 
   @Override
@@ -171,10 +195,20 @@ public final class CompositePhoneLookup implements PhoneLookup<PhoneLookupInfo>
   public ListenableFuture<Void> onSuccessfulBulkUpdate() {
     List<ListenableFuture<Void>> futures = new ArrayList<>();
     for (PhoneLookup<?> phoneLookup : phoneLookups) {
-      futures.add(phoneLookup.onSuccessfulBulkUpdate());
+      ListenableFuture<Void> phoneLookupFuture = phoneLookup.onSuccessfulBulkUpdate();
+      futures.add(phoneLookupFuture);
+      String eventName =
+          String.format(
+              Metrics.ON_SUCCESSFUL_BULK_UPDATE_TEMPLATE, phoneLookup.getClass().getSimpleName());
+      futureTimer.applyTiming(phoneLookupFuture, eventName);
     }
-    return Futures.transform(
-        Futures.allAsList(futures), unused -> null, lightweightExecutorService);
+    ListenableFuture<Void> combinedFuture =
+        Futures.transform(Futures.allAsList(futures), unused -> null, lightweightExecutorService);
+    String eventName =
+        String.format(
+            Metrics.ON_SUCCESSFUL_BULK_UPDATE_TEMPLATE, CompositePhoneLookup.class.getSimpleName());
+    futureTimer.applyTiming(combinedFuture, eventName);
+    return combinedFuture;
   }
 
   @Override