Added some logcat and metrics logging for new call log.
Bug: 70989667
Test: unit
PiperOrigin-RevId: 186726722
Change-Id: I1a68ae1e01b101b1624e4f5ede1a8d639d481ad2
diff --git a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
index a430d14..3765831 100644
--- a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
+++ b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
@@ -19,7 +19,7 @@
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.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 @@
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 @@
@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 @@
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 @@
forceRebuild ->
Preconditions.checkNotNull(forceRebuild)
? Futures.immediateFuture(true)
- : isDirty(appContext),
+ : isDirty(),
lightweightExecutorService);
// After determining isDirty, conditionally call rebuild.
@@ -123,26 +131,36 @@
"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 @@
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 @@
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 ede4691..9912374 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 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 c9edd3e..8610934 100644
--- a/java/com/android/dialer/calllog/database/MutationApplier.java
+++ b/java/com/android/dialer/calllog/database/MutationApplier.java
@@ -45,7 +45,7 @@
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 0000000..f7ba3fe
--- /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 9488f30..8c18ac9 100644
--- a/java/com/android/dialer/metrics/Metrics.java
+++ b/java/com/android/dialer/metrics/Metrics.java
@@ -33,6 +33,20 @@
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 abe18f7..7be7732 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.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.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 @@
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 @@
// 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 @@
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 @@
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 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