1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
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.
*
* <p>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 <T> void applyTiming(ListenableFuture<T> future, String eventName) {
applyTiming(future, eventName, LogCatMode.DONT_LOG_VALUES);
}
/**
* Overload of {@link #applyTiming(ListenableFuture, String)} which allows setting of the {@link
* LogCatMode}.
*/
public <T> void applyTiming(
ListenableFuture<T> future, String eventName, @LogCatMode int logCatMode) {
long startTime = SystemClock.elapsedRealtime();
metrics.startTimer(eventName);
Futures.addCallback(
future,
new FutureCallback<T>() {
@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);
}
}
|
