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
FutureTimer( Metrics metrics, @LightweightExecutor ListeningExecutorService lightweightExecutorService)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    */
applyTiming(ListenableFuture<T> future, String eventName)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    */
applyTiming( ListenableFuture<T> future, String eventName, @LogCatMode int logCatMode)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    */
applyTiming( ListenableFuture<T> future, Function<T, String> eventNameFromResultFunction)94   public <T> void applyTiming(
95       ListenableFuture<T> future, Function<T, String> eventNameFromResultFunction) {
96     applyTiming(future, eventNameFromResultFunction, LogCatMode.DONT_LOG_VALUES);
97   }
98 
applyTiming( ListenableFuture<T> future, Function<T, String> eventNameFromResultFunction, @LogCatMode int logCatMode)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