1 /* 2 * Copyright (C) 2018 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License 15 */ 16 17 package com.android.dialer.metrics; 18 19 import android.os.SystemClock; 20 import android.support.annotation.IntDef; 21 import android.support.annotation.VisibleForTesting; 22 import com.android.dialer.common.LogUtil; 23 import com.android.dialer.common.concurrent.Annotations.LightweightExecutor; 24 import com.google.common.base.Function; 25 import com.google.common.util.concurrent.FutureCallback; 26 import com.google.common.util.concurrent.Futures; 27 import com.google.common.util.concurrent.ListenableFuture; 28 import com.google.common.util.concurrent.ListeningExecutorService; 29 import java.lang.annotation.Retention; 30 import java.lang.annotation.RetentionPolicy; 31 import javax.inject.Inject; 32 33 /** Applies logcat and metric logging to a supplied future. */ 34 public final class FutureTimer { 35 36 /** Operations which exceed this threshold will have logcat warnings printed. */ 37 @VisibleForTesting static final long LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS = 100L; 38 39 private final Metrics metrics; 40 private final ListeningExecutorService lightweightExecutorService; 41 42 /** Modes for logging Future results to logcat. */ 43 @Retention(RetentionPolicy.SOURCE) 44 @IntDef({LogCatMode.DONT_LOG_VALUES, LogCatMode.LOG_VALUES}) 45 public @interface LogCatMode { 46 /** 47 * Don't ever log the result of the future to logcat. For example, may be appropriate if your 48 * future returns a proto and you don't want to spam the logs with multi-line entries, or if 49 * your future returns void/null and so would have no value being logged. 50 */ 51 int DONT_LOG_VALUES = 1; 52 /** 53 * Always log the result of the future to logcat (at DEBUG level). Useful when your future 54 * returns a type which has a short and useful string representation (such as a boolean). PII 55 * will be sanitized. 56 */ 57 int LOG_VALUES = 2; 58 } 59 60 @Inject 61 public FutureTimer( 62 Metrics metrics, @LightweightExecutor ListeningExecutorService lightweightExecutorService) { 63 this.metrics = metrics; 64 this.lightweightExecutorService = lightweightExecutorService; 65 } 66 67 /** 68 * Applies logcat and metric logging to the supplied future. 69 * 70 * <p>This should be called as soon as possible after the future is submitted for execution, as 71 * timing is not started until this method is called. While work for the supplied future may have 72 * already begun, the time elapsed since it started is expected to be negligible for the purposes 73 * of tracking heavyweight operations (which is what this method is intended for). 74 */ 75 public <T> void applyTiming(ListenableFuture<T> future, String eventName) { 76 applyTiming(future, unused -> eventName, LogCatMode.DONT_LOG_VALUES); 77 } 78 79 /** 80 * Overload of {@link #applyTiming(ListenableFuture, String)} which allows setting of the {@link 81 * LogCatMode}. 82 */ 83 public <T> void applyTiming( 84 ListenableFuture<T> future, String eventName, @LogCatMode int logCatMode) { 85 applyTiming(future, unused -> eventName, logCatMode); 86 } 87 88 /** 89 * Overload of {@link #applyTiming(ListenableFuture, String)} that accepts a function which 90 * specifies how to compute an event name from the result of the future. 91 * 92 * <p>This is useful when the event name depends on the result of the future. 93 */ 94 public <T> void applyTiming( 95 ListenableFuture<T> future, Function<T, String> eventNameFromResultFunction) { 96 applyTiming(future, eventNameFromResultFunction, LogCatMode.DONT_LOG_VALUES); 97 } 98 99 private <T> void applyTiming( 100 ListenableFuture<T> future, 101 Function<T, String> eventNameFromResultFunction, 102 @LogCatMode int logCatMode) { 103 long startTime = SystemClock.elapsedRealtime(); 104 Integer timerId = metrics.startUnnamedTimer(); 105 Futures.addCallback( 106 future, 107 new FutureCallback<T>() { 108 @Override 109 public void onSuccess(T result) { 110 String eventName = eventNameFromResultFunction.apply(result); 111 if (timerId != null) { 112 metrics.stopUnnamedTimer(timerId, eventName); 113 } 114 long operationTime = SystemClock.elapsedRealtime() - startTime; 115 116 // If the operation took a long time, do some WARNING logging. 117 if (operationTime > LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS) { 118 switch (logCatMode) { 119 case LogCatMode.DONT_LOG_VALUES: 120 LogUtil.w( 121 "FutureTimer.onSuccess", 122 "%s took more than %dms (took %dms)", 123 eventName, 124 LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS, 125 operationTime); 126 break; 127 case LogCatMode.LOG_VALUES: 128 LogUtil.w( 129 "FutureTimer.onSuccess", 130 "%s took more than %dms (took %dms and returned %s)", 131 eventName, 132 LONG_OPERATION_LOGCAT_THRESHOLD_MILLIS, 133 operationTime, 134 LogUtil.sanitizePii(result)); 135 break; 136 default: 137 throw new UnsupportedOperationException("unknown logcat mode: " + logCatMode); 138 } 139 return; 140 } 141 142 // The operation didn't take a long time, so just do some DEBUG logging. 143 if (LogUtil.isDebugEnabled()) { 144 switch (logCatMode) { 145 case LogCatMode.DONT_LOG_VALUES: 146 // Operation was fast and we're not logging values, so don't log anything. 147 break; 148 case LogCatMode.LOG_VALUES: 149 LogUtil.d( 150 "FutureTimer.onSuccess", 151 "%s took %dms and returned %s", 152 eventName, 153 operationTime, 154 LogUtil.sanitizePii(result)); 155 break; 156 default: 157 throw new UnsupportedOperationException("unknown logcat mode: " + logCatMode); 158 } 159 } 160 } 161 162 @Override 163 public void onFailure(Throwable throwable) { 164 // This callback is just for logging performance metrics; errors are handled elsewhere. 165 } 166 }, 167 lightweightExecutorService); 168 } 169 } 170
