/* * 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.base.Function; 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, unused -> 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) { 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. * *

This is useful when the event name depends on the result of the future. */ public void applyTiming( ListenableFuture future, Function eventNameFromResultFunction) { applyTiming(future, eventNameFromResultFunction, LogCatMode.DONT_LOG_VALUES); } private void applyTiming( ListenableFuture future, Function eventNameFromResultFunction, @LogCatMode int logCatMode) { long startTime = SystemClock.elapsedRealtime(); Integer timerId = metrics.startUnnamedTimer(); Futures.addCallback( future, new FutureCallback() { @Override public void onSuccess(T result) { 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. 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); } }