1 /*
2  * Copyright (C) 2017 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.internal.os;
18 
19 import android.annotation.Nullable;
20 import android.os.Binder;
21 import android.os.Handler;
22 import android.os.SystemClock;
23 import android.util.ArrayMap;
24 import android.util.Slog;
25 import android.util.proto.ProtoOutputStream;
26 
27 import com.android.internal.annotations.GuardedBy;
28 import com.android.internal.annotations.VisibleForTesting;
29 import com.android.internal.os.BinderInternal.CallSession;
30 import com.android.internal.os.BinderLatencyProto.ApiStats;
31 import com.android.internal.os.BinderLatencyProto.Dims;
32 import com.android.internal.os.BinderLatencyProto.RepeatedApiStats;
33 import com.android.internal.util.FrameworkStatsLog;
34 
35 import java.util.Random;
36 
37 /** Collects statistics about Binder call latency per calling API and method. */
38 public class BinderLatencyObserver {
39     private static final String TAG = "BinderLatencyObserver";
40     private static final int MAX_ATOM_SIZE_BYTES = 4064;
41     // Be conservative and leave 1K space for the last histogram so we don't go over the size limit.
42     private static final int LAST_HISTOGRAM_BUFFER_SIZE_BYTES = 1000;
43 
44     // Latency observer parameters.
45     public static final int PERIODIC_SAMPLING_INTERVAL_DEFAULT = 10;
46     public static final int SHARDING_MODULO_DEFAULT = 1;
47     public static final int STATSD_PUSH_INTERVAL_MINUTES_DEFAULT = 360;
48 
49     // Histogram buckets parameters.
50     public static final int BUCKET_COUNT_DEFAULT = 100;
51     public static final int FIRST_BUCKET_SIZE_DEFAULT = 5;
52     public static final float BUCKET_SCALE_FACTOR_DEFAULT = 1.125f;
53 
54     @GuardedBy("mLock")
55     private final ArrayMap<LatencyDims, int[]> mLatencyHistograms = new ArrayMap<>();
56     private final Object mLock = new Object();
57 
58     // Sampling period to control how often to track CPU usage. 1 means all calls, 100 means ~1 out
59     // of 100 requests.
60     private int mPeriodicSamplingInterval = PERIODIC_SAMPLING_INTERVAL_DEFAULT;
61     // Controls how many APIs will be collected per device. 1 means all APIs, 10 means every 10th
62     // API will be collected.
63     private int mShardingModulo = SHARDING_MODULO_DEFAULT;
64     // Controls which shards will be collected on this device.
65     private int mShardingOffset;
66 
67     private int mBucketCount = BUCKET_COUNT_DEFAULT;
68     private int mFirstBucketSize = FIRST_BUCKET_SIZE_DEFAULT;
69     private float mBucketScaleFactor = BUCKET_SCALE_FACTOR_DEFAULT;
70 
71     private int mStatsdPushIntervalMinutes = STATSD_PUSH_INTERVAL_MINUTES_DEFAULT;
72 
73     private final Random mRandom;
74     private final Handler mLatencyObserverHandler;
75     private final int mProcessSource;
76 
77     private BinderLatencyBuckets mLatencyBuckets;
78 
79     private Runnable mLatencyObserverRunnable = new Runnable() {
80         @Override
81         public void run() {
82             // Schedule the next push.
83             noteLatencyDelayed();
84 
85             ArrayMap<LatencyDims, int[]> histogramMap;
86             synchronized (mLock) {
87                 // Copy the histograms map so we don't use the lock for longer than needed.
88                 histogramMap = new ArrayMap<>(mLatencyHistograms);
89                 mLatencyHistograms.clear();
90             }
91 
92             BinderTransactionNameResolver resolver = new BinderTransactionNameResolver();
93             ProtoOutputStream proto = new ProtoOutputStream();
94             int histogramsWritten = 0;
95 
96             for (LatencyDims dims : histogramMap.keySet()) {
97                 // Start a new atom if the next histogram risks going over the atom size limit.
98                 if (proto.getRawSize() + LAST_HISTOGRAM_BUFFER_SIZE_BYTES > getMaxAtomSizeBytes()) {
99                     if (histogramsWritten > 0) {
100                         writeAtomToStatsd(proto);
101                     }
102                     proto = new ProtoOutputStream();
103                     histogramsWritten = 0;
104                 }
105 
106                 String transactionName = resolver.getMethodName(
107                         dims.getBinderClass(), dims.getTransactionCode());
108                 fillApiStatsProto(proto, dims, transactionName, histogramMap.get(dims));
109                 histogramsWritten++;
110             }
111             // Push the final atom.
112             if (histogramsWritten > 0) {
113                 writeAtomToStatsd(proto);
114             }
115         }
116     };
117 
fillApiStatsProto( ProtoOutputStream proto, LatencyDims dims, String transactionName, int[] histogram)118     private void fillApiStatsProto(
119             ProtoOutputStream proto, LatencyDims dims, String transactionName, int[] histogram) {
120         // Find the part of the histogram to write.
121         int firstNonEmptyBucket = 0;
122         for (int i = 0; i < mBucketCount; i++) {
123             if (histogram[i] != 0) {
124                 firstNonEmptyBucket = i;
125                 break;
126             }
127         }
128         int lastNonEmptyBucket = mBucketCount - 1;
129         for (int i = mBucketCount - 1; i >= 0; i--) {
130             if (histogram[i] != 0) {
131                 lastNonEmptyBucket = i;
132                 break;
133             }
134         }
135 
136         // Start a new ApiStats proto.
137         long apiStatsToken = proto.start(RepeatedApiStats.API_STATS);
138 
139         // Write the dims.
140         long dimsToken = proto.start(ApiStats.DIMS);
141         proto.write(Dims.PROCESS_SOURCE, mProcessSource);
142         proto.write(Dims.SERVICE_CLASS_NAME, dims.getBinderClass().getName());
143         proto.write(Dims.SERVICE_METHOD_NAME, transactionName);
144         proto.end(dimsToken);
145 
146         // Write the histogram.
147         proto.write(ApiStats.FIRST_BUCKET_INDEX, firstNonEmptyBucket);
148         for (int i = firstNonEmptyBucket; i <= lastNonEmptyBucket; i++) {
149             proto.write(ApiStats.BUCKETS, histogram[i]);
150         }
151 
152         proto.end(apiStatsToken);
153     }
154 
getMaxAtomSizeBytes()155     protected int getMaxAtomSizeBytes() {
156         return MAX_ATOM_SIZE_BYTES;
157     }
158 
writeAtomToStatsd(ProtoOutputStream atom)159     protected void writeAtomToStatsd(ProtoOutputStream atom) {
160         FrameworkStatsLog.write(
161                 FrameworkStatsLog.BINDER_LATENCY_REPORTED,
162                 atom.getBytes(),
163                 mPeriodicSamplingInterval,
164                 mShardingModulo,
165                 mBucketCount,
166                 mFirstBucketSize,
167                 mBucketScaleFactor);
168     }
169 
noteLatencyDelayed()170     private void noteLatencyDelayed() {
171         mLatencyObserverHandler.removeCallbacks(mLatencyObserverRunnable);
172         mLatencyObserverHandler.postDelayed(mLatencyObserverRunnable,
173                 mStatsdPushIntervalMinutes * 60 * 1000);
174     }
175 
176     /** Injector for {@link BinderLatencyObserver}. */
177     public static class Injector {
getRandomGenerator()178         public Random getRandomGenerator() {
179             return new Random();
180         }
181 
getHandler()182         public Handler getHandler() {
183             return BackgroundThread.getHandler();
184         }
185     }
186 
BinderLatencyObserver(Injector injector, int processSource)187     public BinderLatencyObserver(Injector injector, int processSource) {
188         mRandom = injector.getRandomGenerator();
189         mLatencyObserverHandler = injector.getHandler();
190         mLatencyBuckets = new BinderLatencyBuckets(
191             mBucketCount, mFirstBucketSize, mBucketScaleFactor);
192         mProcessSource = processSource;
193         mShardingOffset = mRandom.nextInt(mShardingModulo);
194         noteLatencyDelayed();
195     }
196 
197     /** Should be called when a Binder call completes, will store latency data. */
callEnded(@ullable CallSession s)198     public void callEnded(@Nullable CallSession s) {
199         if (s == null || s.exceptionThrown || !shouldKeepSample()) {
200             return;
201         }
202 
203         LatencyDims dims = LatencyDims.create(s.binderClass, s.transactionCode);
204 
205         if (!shouldCollect(dims)) {
206             return;
207         }
208 
209         long elapsedTimeMicro = getElapsedRealtimeMicro();
210         long callDuration = elapsedTimeMicro - s.timeStarted;
211 
212         // Find the bucket this sample should go to.
213         int bucketIdx = mLatencyBuckets.sampleToBucket(
214                 callDuration > Integer.MAX_VALUE ? Integer.MAX_VALUE : (int) callDuration);
215 
216         synchronized (mLock) {
217             int[] buckets = mLatencyHistograms.get(dims);
218             if (buckets == null) {
219                 buckets = new int[mBucketCount];
220                 mLatencyHistograms.put(dims, buckets);
221             }
222 
223             // Increment the correct bucket.
224             if (buckets[bucketIdx] < Integer.MAX_VALUE) {
225                 buckets[bucketIdx] += 1;
226             }
227         }
228     }
229 
getElapsedRealtimeMicro()230     protected long getElapsedRealtimeMicro() {
231         return SystemClock.elapsedRealtimeNanos() / 1000;
232     }
233 
shouldCollect(LatencyDims dims)234     protected boolean shouldCollect(LatencyDims dims) {
235         return (dims.hashCode() + mShardingOffset) % mShardingModulo == 0;
236     }
237 
shouldKeepSample()238     protected boolean shouldKeepSample() {
239         return mRandom.nextInt(mPeriodicSamplingInterval) == 0;
240     }
241 
242     /** Updates the sampling interval. */
setSamplingInterval(int samplingInterval)243     public void setSamplingInterval(int samplingInterval) {
244         if (samplingInterval <= 0) {
245             Slog.w(TAG, "Ignored invalid sampling interval (value must be positive): "
246                     + samplingInterval);
247             return;
248         }
249 
250         synchronized (mLock) {
251             if (samplingInterval != mPeriodicSamplingInterval) {
252                 mPeriodicSamplingInterval = samplingInterval;
253                 reset();
254             }
255         }
256     }
257 
258     /** Updates the sharding modulo. */
setShardingModulo(int shardingModulo)259     public void setShardingModulo(int shardingModulo) {
260         if (shardingModulo <= 0) {
261             Slog.w(TAG, "Ignored invalid sharding modulo (value must be positive): "
262                     + shardingModulo);
263             return;
264         }
265 
266         synchronized (mLock) {
267             if (shardingModulo != mShardingModulo) {
268                 mShardingModulo = shardingModulo;
269                 mShardingOffset = mRandom.nextInt(shardingModulo);
270                 reset();
271             }
272         }
273     }
274 
275     /** Updates the statsd push interval. */
setPushInterval(int pushIntervalMinutes)276     public void setPushInterval(int pushIntervalMinutes) {
277         if (pushIntervalMinutes <= 0) {
278             Slog.w(TAG, "Ignored invalid push interval (value must be positive): "
279                     + pushIntervalMinutes);
280             return;
281         }
282 
283         synchronized (mLock) {
284             if (pushIntervalMinutes != mStatsdPushIntervalMinutes) {
285                 mStatsdPushIntervalMinutes = pushIntervalMinutes;
286                 reset();
287             }
288         }
289     }
290 
291     /** Updates the histogram buckets parameters. */
setHistogramBucketsParams( int bucketCount, int firstBucketSize, float bucketScaleFactor)292     public void setHistogramBucketsParams(
293             int bucketCount, int firstBucketSize, float bucketScaleFactor) {
294         synchronized (mLock) {
295             if (bucketCount != mBucketCount || firstBucketSize != mFirstBucketSize
296                     || bucketScaleFactor != mBucketScaleFactor) {
297                 mBucketCount = bucketCount;
298                 mFirstBucketSize = firstBucketSize;
299                 mBucketScaleFactor = bucketScaleFactor;
300                 mLatencyBuckets = new BinderLatencyBuckets(
301                     mBucketCount, mFirstBucketSize, mBucketScaleFactor);
302                 reset();
303             }
304         }
305     }
306 
307     /** Resets the sample collection. */
reset()308     public void reset() {
309         synchronized (mLock) {
310             mLatencyHistograms.clear();
311         }
312         noteLatencyDelayed();
313     }
314 
315     /** Container for binder latency information. */
316     public static class LatencyDims {
317         // Binder interface descriptor.
318         private Class<? extends Binder> mBinderClass;
319         // Binder transaction code.
320         private int mTransactionCode;
321         // Cached hash code, 0 if not set yet.
322         private int mHashCode = 0;
323 
324         /** Creates a new instance of LatencyDims. */
create(Class<? extends Binder> binderClass, int transactionCode)325         public static LatencyDims create(Class<? extends Binder> binderClass, int transactionCode) {
326             return new LatencyDims(binderClass, transactionCode);
327         }
328 
LatencyDims(Class<? extends Binder> binderClass, int transactionCode)329         private LatencyDims(Class<? extends Binder> binderClass, int transactionCode) {
330             this.mBinderClass = binderClass;
331             this.mTransactionCode = transactionCode;
332         }
333 
getBinderClass()334         public Class<? extends Binder> getBinderClass() {
335             return mBinderClass;
336         }
337 
getTransactionCode()338         public int getTransactionCode() {
339             return mTransactionCode;
340         }
341 
342         @Override
equals(final Object other)343         public boolean equals(final Object other) {
344             if (other == null || !(other instanceof LatencyDims)) {
345                 return false;
346             }
347             LatencyDims o = (LatencyDims) other;
348             return mTransactionCode == o.getTransactionCode() && mBinderClass == o.getBinderClass();
349         }
350 
351         @Override
hashCode()352         public int hashCode() {
353             if (mHashCode != 0) {
354                 return mHashCode;
355             }
356             int hash = mTransactionCode;
357             hash = 31 * hash + mBinderClass.getName().hashCode();
358             mHashCode = hash;
359             return hash;
360         }
361     }
362 
363     @VisibleForTesting
getLatencyHistograms()364     public ArrayMap<LatencyDims, int[]> getLatencyHistograms() {
365         return mLatencyHistograms;
366     }
367 
368     @VisibleForTesting
getStatsdPushRunnable()369     public Runnable getStatsdPushRunnable() {
370         return mLatencyObserverRunnable;
371     }
372 
373     @VisibleForTesting
getProcessSource()374     public int getProcessSource() {
375         return mProcessSource;
376     }
377 }
378