From 9952f1c90ea6b150122cd5e79256c54419c7091e Mon Sep 17 00:00:00 2001 From: zachh Date: Thu, 22 Feb 2018 22:52:43 -0800 Subject: Added some logcat and metrics logging for new call log. Bug: 70989667 Test: unit PiperOrigin-RevId: 186726722 Change-Id: I1a68ae1e01b101b1624e4f5ede1a8d639d481ad2 --- java/com/android/dialer/metrics/FutureTimer.java | 147 +++++++++++++++++++++++ java/com/android/dialer/metrics/Metrics.java | 14 +++ 2 files changed, 161 insertions(+) create mode 100644 java/com/android/dialer/metrics/FutureTimer.java (limited to 'java/com/android/dialer/metrics') 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. + * + *

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 void applyTiming(ListenableFuture future, String eventName) { + applyTiming(future, eventName, LogCatMode.DONT_LOG_VALUES); + } + + /** + * Overload of {@link #applyTiming(ListenableFuture, String)} which allows setting of the {@link + * LogCatMode}. + */ + public void applyTiming( + ListenableFuture future, String eventName, @LogCatMode int logCatMode) { + long startTime = SystemClock.elapsedRealtime(); + metrics.startTimer(eventName); + Futures.addCallback( + future, + new FutureCallback() { + @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); -- cgit v1.2.3