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
diff --git a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java
index e0bfcd8..3019f5e 100644
--- a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java
+++ b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogReceiver.java
@@ -21,10 +21,15 @@
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 @@
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 RefreshAnnotatedCallLogReceiver(Context context) {
refreshAnnotatedCallLogWorker =
CallLogComponent.get(context).getRefreshAnnotatedCallLogWorker();
+ futureTimer = MetricsComponent.get(context).futureTimer();
}
@Override
@@ -97,12 +104,14 @@
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 @@
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 e05b772..c399b05 100644
--- a/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
+++ b/java/com/android/dialer/calllog/RefreshAnnotatedCallLogWorker.java
@@ -79,23 +79,30 @@
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 @@
return Futures.transformAsync(
callLogState.isBuilt(), this::rebuild, MoreExecutors.directExecutor());
}
- return Futures.immediateFuture(null);
+ return Futures.immediateFuture(RefreshResult.NOT_DIRTY);
},
lightweightExecutorService);
}
@@ -160,7 +167,7 @@
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 @@
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 77de62e..6972273 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.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 @@
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 @@
.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 f7ba3fe..a45fb38 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.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 @@
* 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 <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 b460f3e..e9e22c3 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 @@
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 @@
/** 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 f371297..a3570db 100644
--- a/java/com/android/dialer/metrics/MetricsComponent.java
+++ b/java/com/android/dialer/metrics/MetricsComponent.java
@@ -28,6 +28,8 @@
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 99c3d76..ecd2382 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 stopJankRecorder(String eventName) {}
+ 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 recordMemory(String memoryEventName) {}
+ public void startJankRecorder(String eventName) {
+ LogUtil.d("StubMetrics.startJankRecorder", "started jank recorder for %s", eventName);
+ }
+
+ @Override
+ 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();
+ }
+ }
}