diff options
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(); + } + } } |