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