Merge "Added timing to some more AnnotatedCallLog operations." am: 9ed12284f4
am: c80240f11d
Change-Id: I564b541c1a76563fee530f38d65f13b3014cb83f
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();
+ }
+ }
}