From dfded3aac2c4628f74cafdd2eb096f553d0d48ad Mon Sep 17 00:00:00 2001 From: zachh Date: Fri, 2 Mar 2018 17:14:35 -0800 Subject: Added timing to some more AnnotatedCallLog operations. This includes: 1) Made RefreshAnnotatedCallLogWorker.refresh() methods return a result which is "not dirty", "dirty but no changes needed" or "dirty and changes need". It will be interesting to see how often these cases occur (will log impressions in a future CL) so I thought we might as well log the latency of each case separately as well. 2) To support 1) added a new method to FutureTimer which allows you to compute the event name from the result of the timed Future. Also needed to update the Metrics interface to support deferring the event name when starting a timer via a generic token. 3) Timing the coalesce operation which is very heavyweight. 4) Made StubMetrics do some logcat logging to easily observe timing information using AOSP Bug: 70989667 Test: unit PiperOrigin-RevId: 187691203 Change-Id: I5f19a2fc94d86639486299b65b0edd66eeaab52e --- .../calllog/RefreshAnnotatedCallLogReceiver.java | 36 +++++++++++++++++++++- .../calllog/RefreshAnnotatedCallLogWorker.java | 23 +++++++++----- .../database/AnnotatedCallLogContentProvider.java | 4 +++ 3 files changed, 55 insertions(+), 8 deletions(-) (limited to 'java/com/android/dialer/calllog') 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 future = + ListenableFuture 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 { + + 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 refreshWithDirtyCheck() { + ListenableFuture refreshWithDirtyCheck() { return refresh(true); } /** Refreshes the annotated call log, bypassing dirty checks. */ - ListenableFuture refreshWithoutDirtyCheck() { + ListenableFuture refreshWithoutDirtyCheck() { return refresh(false); } - private ListenableFuture refresh(boolean checkDirty) { + private ListenableFuture refresh(boolean checkDirty) { LogUtil.i("RefreshAnnotatedCallLogWorker.refresh", "submitting serialized refresh request"); return dialerFutureSerializer.submitAsync( () -> checkDirtyAndRebuildIfNecessary(checkDirty), lightweightExecutorService); } - private ListenableFuture checkDirtyAndRebuildIfNecessary(boolean checkDirty) { + private ListenableFuture checkDirtyAndRebuildIfNecessary(boolean checkDirty) { ListenableFuture 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 rebuild(boolean isBuilt) { + private ListenableFuture 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: -- cgit v1.2.3