diff options
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 |