/* * Copyright (C) 2017 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.internal.os; import static com.android.internal.os.BinderLatencyProto.Dims.SYSTEM_SERVER; import android.annotation.NonNull; import android.annotation.Nullable; import android.content.Context; import android.database.ContentObserver; import android.net.Uri; import android.os.Binder; import android.os.Handler; import android.os.Looper; import android.os.Process; import android.os.SystemClock; import android.os.UserHandle; import android.provider.Settings; import android.text.format.DateFormat; import android.util.ArrayMap; import android.util.ArraySet; import android.util.IntArray; import android.util.KeyValueListParser; import android.util.Pair; import android.util.Slog; import android.util.SparseArray; import com.android.internal.annotations.GuardedBy; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.os.BinderInternal.CallSession; import java.io.PrintWriter; import java.util.ArrayList; import java.util.Collection; import java.util.Comparator; import java.util.List; import java.util.Queue; import java.util.Random; import java.util.concurrent.ConcurrentLinkedQueue; import java.util.function.ToDoubleFunction; /** * Collects statistics about CPU time spent per binder call across multiple dimensions, e.g. * per thread, uid or call description. */ public class BinderCallsStats implements BinderInternal.Observer { public static final boolean ENABLED_DEFAULT = true; public static final boolean DETAILED_TRACKING_DEFAULT = true; public static final int PERIODIC_SAMPLING_INTERVAL_DEFAULT = 1000; public static final boolean DEFAULT_TRACK_SCREEN_INTERACTIVE = false; public static final boolean DEFAULT_TRACK_DIRECT_CALLING_UID = true; public static final boolean DEFAULT_IGNORE_BATTERY_STATUS = false; public static final boolean DEFAULT_COLLECT_LATENCY_DATA = true; public static final int MAX_BINDER_CALL_STATS_COUNT_DEFAULT = 1500; public static final int SHARDING_MODULO_DEFAULT = 1; private static final String DEBUG_ENTRY_PREFIX = "__DEBUG_"; private static class OverflowBinder extends Binder {} private static final String TAG = "BinderCallsStats"; private static final int CALL_SESSIONS_POOL_SIZE = 100; private static final int MAX_EXCEPTION_COUNT_SIZE = 50; private static final String EXCEPTION_COUNT_OVERFLOW_NAME = "overflow"; // Default values for overflow entry. The work source uid does not use a default value in order // to have on overflow entry per work source uid. private static final Class OVERFLOW_BINDER = OverflowBinder.class; private static final boolean OVERFLOW_SCREEN_INTERACTIVE = false; private static final int OVERFLOW_DIRECT_CALLING_UID = -1; private static final int OVERFLOW_TRANSACTION_CODE = -1; // Whether to collect all the data: cpu + exceptions + reply/request sizes. private boolean mDetailedTracking = DETAILED_TRACKING_DEFAULT; // If set to true, indicates that all transactions for specific UIDs are being // recorded, ignoring sampling. The UidEntry.recordAllTransactions flag is also set // for the UIDs being tracked. private boolean mRecordingAllTransactionsForUid; // Sampling period to control how often to track CPU usage. 1 means all calls, 100 means ~1 out // of 100 requests. private int mPeriodicSamplingInterval = PERIODIC_SAMPLING_INTERVAL_DEFAULT; private int mMaxBinderCallStatsCount = MAX_BINDER_CALL_STATS_COUNT_DEFAULT; @GuardedBy("mLock") private final SparseArray mUidEntries = new SparseArray<>(); @GuardedBy("mLock") private final ArrayMap mExceptionCounts = new ArrayMap<>(); private final Queue mCallSessionsPool = new ConcurrentLinkedQueue<>(); private final Object mLock = new Object(); private final Random mRandom; private long mStartCurrentTime = System.currentTimeMillis(); private long mStartElapsedTime = SystemClock.elapsedRealtime(); private long mCallStatsCount = 0; private boolean mAddDebugEntries = false; private boolean mTrackDirectCallingUid = DEFAULT_TRACK_DIRECT_CALLING_UID; private boolean mTrackScreenInteractive = DEFAULT_TRACK_SCREEN_INTERACTIVE; private boolean mIgnoreBatteryStatus = DEFAULT_IGNORE_BATTERY_STATUS; private boolean mCollectLatencyData = DEFAULT_COLLECT_LATENCY_DATA; // Controls how many APIs will be collected per device. 1 means all APIs, 10 means every 10th // API will be collected. private int mShardingModulo = SHARDING_MODULO_DEFAULT; // Controls which shards will be collected on this device. private int mShardingOffset; private CachedDeviceState.Readonly mDeviceState; private CachedDeviceState.TimeInStateStopwatch mBatteryStopwatch; private static final int CALL_STATS_OBSERVER_DEBOUNCE_MILLIS = 5000; private BinderLatencyObserver mLatencyObserver; private BinderInternal.CallStatsObserver mCallStatsObserver; private ArraySet mSendUidsToObserver = new ArraySet<>(32); private final Handler mCallStatsObserverHandler; private Runnable mCallStatsObserverRunnable = new Runnable() { @Override public void run() { if (mCallStatsObserver == null) { return; } noteCallsStatsDelayed(); synchronized (mLock) { int size = mSendUidsToObserver.size(); for (int i = 0; i < size; i++) { UidEntry uidEntry = mUidEntries.get(mSendUidsToObserver.valueAt(i)); if (uidEntry != null) { ArrayMap callStats = uidEntry.mCallStats; final int csize = callStats.size(); final ArrayList tmpCallStats = new ArrayList<>(csize); for (int j = 0; j < csize; j++) { tmpCallStats.add(callStats.valueAt(j).clone()); } mCallStatsObserver.noteCallStats(uidEntry.workSourceUid, uidEntry.incrementalCallCount, tmpCallStats ); uidEntry.incrementalCallCount = 0; for (int j = callStats.size() - 1; j >= 0; j--) { callStats.valueAt(j).incrementalCallCount = 0; } } } mSendUidsToObserver.clear(); } } }; private final Object mNativeTidsLock = new Object(); // @GuardedBy("mNativeTidsLock") // Cannot mark it as "GuardedBy" because it's read // directly, as a volatile field. private volatile IntArray mNativeTids = new IntArray(0); /** Injector for {@link BinderCallsStats}. */ public static class Injector { public Random getRandomGenerator() { return new Random(); } public Handler getHandler() { return new Handler(Looper.getMainLooper()); } /** Create a latency observer for the specified process. */ public BinderLatencyObserver getLatencyObserver(int processSource) { return new BinderLatencyObserver(new BinderLatencyObserver.Injector(), processSource); } } public BinderCallsStats(Injector injector) { this(injector, SYSTEM_SERVER); } public BinderCallsStats(Injector injector, int processSource) { this.mRandom = injector.getRandomGenerator(); this.mCallStatsObserverHandler = injector.getHandler(); this.mLatencyObserver = injector.getLatencyObserver(processSource); this.mShardingOffset = mRandom.nextInt(mShardingModulo); } public void setDeviceState(@NonNull CachedDeviceState.Readonly deviceState) { if (mBatteryStopwatch != null) { mBatteryStopwatch.close(); } mDeviceState = deviceState; mBatteryStopwatch = deviceState.createTimeOnBatteryStopwatch(); } /** * Registers an observer for call stats, which is invoked periodically with accumulated * binder call stats. */ public void setCallStatsObserver( BinderInternal.CallStatsObserver callStatsObserver) { mCallStatsObserver = callStatsObserver; noteBinderThreadNativeIds(); noteCallsStatsDelayed(); } private void noteCallsStatsDelayed() { mCallStatsObserverHandler.removeCallbacks(mCallStatsObserverRunnable); if (mCallStatsObserver != null) { mCallStatsObserverHandler.postDelayed(mCallStatsObserverRunnable, CALL_STATS_OBSERVER_DEBOUNCE_MILLIS); } } @Override @Nullable public CallSession callStarted(Binder binder, int code, int workSourceUid) { noteNativeThreadId(); boolean collectCpu = canCollect(); // We always want to collect data for latency if it's enabled, regardless of device state. if (!mCollectLatencyData && !collectCpu) { return null; } final CallSession s = obtainCallSession(); s.binderClass = binder.getClass(); s.transactionCode = code; s.exceptionThrown = false; s.cpuTimeStarted = -1; s.timeStarted = -1; s.recordedCall = shouldRecordDetailedData(); if (collectCpu && (mRecordingAllTransactionsForUid || s.recordedCall)) { s.cpuTimeStarted = getThreadTimeMicro(); s.timeStarted = getElapsedRealtimeMicro(); } else if (mCollectLatencyData) { s.timeStarted = getElapsedRealtimeMicro(); } return s; } private CallSession obtainCallSession() { CallSession s = mCallSessionsPool.poll(); return s == null ? new CallSession() : s; } @Override public void callEnded(@Nullable CallSession s, int parcelRequestSize, int parcelReplySize, int workSourceUid) { if (s == null) { return; } processCallEnded(s, parcelRequestSize, parcelReplySize, workSourceUid); if (mCallSessionsPool.size() < CALL_SESSIONS_POOL_SIZE) { mCallSessionsPool.add(s); } } private void processCallEnded(CallSession s, int parcelRequestSize, int parcelReplySize, int workSourceUid) { if (mCollectLatencyData) { mLatencyObserver.callEnded(s); } // Latency collection has already been processed so check if the rest should be processed. if (!canCollect()) { return; } UidEntry uidEntry = null; final boolean recordCall; if (s.recordedCall) { recordCall = true; } else if (mRecordingAllTransactionsForUid) { uidEntry = getUidEntry(workSourceUid); recordCall = uidEntry.recordAllTransactions; } else { recordCall = false; } final long duration; final long latencyDuration; if (recordCall) { duration = getThreadTimeMicro() - s.cpuTimeStarted; latencyDuration = getElapsedRealtimeMicro() - s.timeStarted; } else { duration = 0; latencyDuration = 0; } final boolean screenInteractive = mTrackScreenInteractive ? mDeviceState.isScreenInteractive() : OVERFLOW_SCREEN_INTERACTIVE; final int callingUid = mTrackDirectCallingUid ? getCallingUid() : OVERFLOW_DIRECT_CALLING_UID; synchronized (mLock) { // This was already checked in #callStart but check again while synchronized. if (!canCollect()) { return; } if (uidEntry == null) { uidEntry = getUidEntry(workSourceUid); } uidEntry.callCount++; uidEntry.incrementalCallCount++; if (recordCall) { uidEntry.cpuTimeMicros += duration; uidEntry.recordedCallCount++; final CallStat callStat = uidEntry.getOrCreate( callingUid, s.binderClass, s.transactionCode, screenInteractive, mCallStatsCount >= mMaxBinderCallStatsCount); final boolean isNewCallStat = callStat.callCount == 0; if (isNewCallStat) { mCallStatsCount++; } callStat.callCount++; callStat.incrementalCallCount++; callStat.recordedCallCount++; callStat.cpuTimeMicros += duration; callStat.maxCpuTimeMicros = Math.max(callStat.maxCpuTimeMicros, duration); callStat.latencyMicros += latencyDuration; callStat.maxLatencyMicros = Math.max(callStat.maxLatencyMicros, latencyDuration); if (mDetailedTracking) { callStat.exceptionCount += s.exceptionThrown ? 1 : 0; callStat.maxRequestSizeBytes = Math.max(callStat.maxRequestSizeBytes, parcelRequestSize); callStat.maxReplySizeBytes = Math.max(callStat.maxReplySizeBytes, parcelReplySize); } } else { // Only record the total call count if we already track data for this key. // It helps to keep the memory usage down when sampling is enabled. final CallStat callStat = uidEntry.get( callingUid, s.binderClass, s.transactionCode, screenInteractive); if (callStat != null) { callStat.callCount++; callStat.incrementalCallCount++; } } if (mCallStatsObserver != null && !UserHandle.isCore(workSourceUid)) { mSendUidsToObserver.add(workSourceUid); } } } private boolean shouldExport(ExportedCallStat e, boolean applySharding) { if (!applySharding) { return true; } int hash = e.binderClass.hashCode(); hash = 31 * hash + e.transactionCode; hash = 31 * hash + e.callingUid; hash = 31 * hash + (e.screenInteractive ? 1231 : 1237); return (hash + mShardingOffset) % mShardingModulo == 0; } private UidEntry getUidEntry(int uid) { UidEntry uidEntry = mUidEntries.get(uid); if (uidEntry == null) { uidEntry = new UidEntry(uid); mUidEntries.put(uid, uidEntry); } return uidEntry; } @Override public void callThrewException(@Nullable CallSession s, Exception exception) { if (s == null) { return; } s.exceptionThrown = true; try { String className = exception.getClass().getName(); synchronized (mLock) { if (mExceptionCounts.size() >= MAX_EXCEPTION_COUNT_SIZE) { className = EXCEPTION_COUNT_OVERFLOW_NAME; } final Integer count = mExceptionCounts.get(className); mExceptionCounts.put(className, count == null ? 1 : count + 1); } } catch (RuntimeException e) { // Do not propagate the exception. We do not want to swallow original exception. Slog.wtf(TAG, "Unexpected exception while updating mExceptionCounts"); } } private void noteNativeThreadId() { final int tid = getNativeTid(); int index = mNativeTids.binarySearch(tid); if (index >= 0) { return; } // Use the copy-on-write approach. The changes occur exceedingly infrequently, so // this code path is exercised just a few times per boot synchronized (mNativeTidsLock) { IntArray nativeTids = mNativeTids; index = nativeTids.binarySearch(tid); if (index < 0) { IntArray copyOnWriteArray = new IntArray(nativeTids.size() + 1); copyOnWriteArray.addAll(nativeTids); copyOnWriteArray.add(-index - 1, tid); mNativeTids = copyOnWriteArray; } } noteBinderThreadNativeIds(); } private void noteBinderThreadNativeIds() { if (mCallStatsObserver == null) { return; } mCallStatsObserver.noteBinderThreadNativeIds(getNativeTids()); } private boolean canCollect() { if (mRecordingAllTransactionsForUid) { return true; } if (mIgnoreBatteryStatus) { return true; } if (mDeviceState == null) { return false; } if (mDeviceState.isCharging()) { return false; } return true; } /** * This method is expensive to call. */ public ArrayList getExportedCallStats() { return getExportedCallStats(false); } /** * This method is expensive to call. * Exports call stats and applies sharding if requested. */ @VisibleForTesting public ArrayList getExportedCallStats(boolean applySharding) { // We do not collect all the data if detailed tracking is off. if (!mDetailedTracking) { return new ArrayList<>(); } ArrayList resultCallStats = new ArrayList<>(); synchronized (mLock) { final int uidEntriesSize = mUidEntries.size(); for (int entryIdx = 0; entryIdx < uidEntriesSize; entryIdx++) { final UidEntry entry = mUidEntries.valueAt(entryIdx); for (CallStat stat : entry.getCallStatsList()) { ExportedCallStat e = getExportedCallStat(entry.workSourceUid, stat); if (shouldExport(e, applySharding)) { resultCallStats.add(e); } } } } // Resolve codes outside of the lock since it can be slow. resolveBinderMethodNames(resultCallStats); // Debug entries added to help validate the data. if (mAddDebugEntries && mBatteryStopwatch != null) { resultCallStats.add(createDebugEntry("start_time_millis", mStartElapsedTime)); resultCallStats.add(createDebugEntry("end_time_millis", SystemClock.elapsedRealtime())); resultCallStats.add( createDebugEntry("battery_time_millis", mBatteryStopwatch.getMillis())); resultCallStats.add(createDebugEntry("sampling_interval", mPeriodicSamplingInterval)); resultCallStats.add(createDebugEntry("sharding_modulo", mShardingModulo)); } return resultCallStats; } /** * This method is expensive to call. */ public ArrayList getExportedCallStats(int workSourceUid) { return getExportedCallStats(workSourceUid, false); } /** * This method is expensive to call. * Exports call stats and applies sharding if requested. */ @VisibleForTesting public ArrayList getExportedCallStats( int workSourceUid, boolean applySharding) { ArrayList resultCallStats = new ArrayList<>(); synchronized (mLock) { final UidEntry entry = getUidEntry(workSourceUid); for (CallStat stat : entry.getCallStatsList()) { ExportedCallStat e = getExportedCallStat(workSourceUid, stat); if (shouldExport(e, applySharding)) { resultCallStats.add(e); } } } // Resolve codes outside of the lock since it can be slow. resolveBinderMethodNames(resultCallStats); return resultCallStats; } private ExportedCallStat getExportedCallStat(int workSourceUid, CallStat stat) { ExportedCallStat exported = new ExportedCallStat(); exported.workSourceUid = workSourceUid; exported.callingUid = stat.callingUid; exported.className = stat.binderClass.getName(); exported.binderClass = stat.binderClass; exported.transactionCode = stat.transactionCode; exported.screenInteractive = stat.screenInteractive; exported.cpuTimeMicros = stat.cpuTimeMicros; exported.maxCpuTimeMicros = stat.maxCpuTimeMicros; exported.latencyMicros = stat.latencyMicros; exported.maxLatencyMicros = stat.maxLatencyMicros; exported.recordedCallCount = stat.recordedCallCount; exported.callCount = stat.callCount; exported.maxRequestSizeBytes = stat.maxRequestSizeBytes; exported.maxReplySizeBytes = stat.maxReplySizeBytes; exported.exceptionCount = stat.exceptionCount; return exported; } private void resolveBinderMethodNames( ArrayList resultCallStats) { // Resolve codes outside of the lock since it can be slow. ExportedCallStat previous = null; String previousMethodName = null; resultCallStats.sort(BinderCallsStats::compareByBinderClassAndCode); BinderTransactionNameResolver resolver = new BinderTransactionNameResolver(); for (ExportedCallStat exported : resultCallStats) { final boolean isClassDifferent = previous == null || !previous.className.equals(exported.className); final boolean isCodeDifferent = previous == null || previous.transactionCode != exported.transactionCode; final String methodName; if (isClassDifferent || isCodeDifferent) { methodName = resolver.getMethodName(exported.binderClass, exported.transactionCode); } else { methodName = previousMethodName; } previousMethodName = methodName; exported.methodName = methodName; previous = exported; } } private ExportedCallStat createDebugEntry(String variableName, long value) { final int uid = Process.myUid(); final ExportedCallStat callStat = new ExportedCallStat(); callStat.className = ""; callStat.workSourceUid = uid; callStat.callingUid = uid; callStat.recordedCallCount = 1; callStat.callCount = 1; callStat.methodName = DEBUG_ENTRY_PREFIX + variableName; callStat.latencyMicros = value; return callStat; } /** @hide */ public ArrayMap getExportedExceptionStats() { synchronized (mLock) { return new ArrayMap(mExceptionCounts); } } /** Writes the collected statistics to the supplied {@link PrintWriter}.*/ public void dump(PrintWriter pw, AppIdToPackageMap packageMap, int workSourceUid, boolean verbose) { synchronized (mLock) { dumpLocked(pw, packageMap, workSourceUid, verbose); } } private void dumpLocked(PrintWriter pw, AppIdToPackageMap packageMap, int workSourceUid, boolean verbose) { if (workSourceUid != Process.INVALID_UID) { verbose = true; } pw.print("Start time: "); pw.println(DateFormat.format("yyyy-MM-dd HH:mm:ss", mStartCurrentTime)); pw.print("On battery time (ms): "); pw.println(mBatteryStopwatch != null ? mBatteryStopwatch.getMillis() : 0); pw.println("Sampling interval period: " + mPeriodicSamplingInterval); pw.println("Sharding modulo: " + mShardingModulo); final String datasetSizeDesc = verbose ? "" : "(top 90% by cpu time) "; final StringBuilder sb = new StringBuilder(); pw.println("Per-UID raw data " + datasetSizeDesc + "(package/uid, worksource, call_desc, screen_interactive, " + "cpu_time_micros, max_cpu_time_micros, " + "latency_time_micros, max_latency_time_micros, exception_count, " + "max_request_size_bytes, max_reply_size_bytes, recorded_call_count, " + "call_count):"); final List exportedCallStats; if (workSourceUid != Process.INVALID_UID) { exportedCallStats = getExportedCallStats(workSourceUid, true); } else { exportedCallStats = getExportedCallStats(true); } exportedCallStats.sort(BinderCallsStats::compareByCpuDesc); for (ExportedCallStat e : exportedCallStats) { if (e.methodName != null && e.methodName.startsWith(DEBUG_ENTRY_PREFIX)) { // Do not dump debug entries. continue; } sb.setLength(0); sb.append(" ") .append(packageMap.mapUid(e.callingUid)) .append(',') .append(packageMap.mapUid(e.workSourceUid)) .append(',').append(e.className) .append('#').append(e.methodName) .append(',').append(e.screenInteractive) .append(',').append(e.cpuTimeMicros) .append(',').append(e.maxCpuTimeMicros) .append(',').append(e.latencyMicros) .append(',').append(e.maxLatencyMicros) .append(',').append(mDetailedTracking ? e.exceptionCount : '_') .append(',').append(mDetailedTracking ? e.maxRequestSizeBytes : '_') .append(',').append(mDetailedTracking ? e.maxReplySizeBytes : '_') .append(',').append(e.recordedCallCount) .append(',').append(e.callCount); pw.println(sb); } pw.println(); final List entries = new ArrayList<>(); long totalCallsCount = 0; long totalRecordedCallsCount = 0; long totalCpuTime = 0; if (workSourceUid != Process.INVALID_UID) { UidEntry e = getUidEntry(workSourceUid); entries.add(e); totalCpuTime += e.cpuTimeMicros; totalRecordedCallsCount += e.recordedCallCount; totalCallsCount += e.callCount; } else { final int uidEntriesSize = mUidEntries.size(); for (int i = 0; i < uidEntriesSize; i++) { UidEntry e = mUidEntries.valueAt(i); entries.add(e); totalCpuTime += e.cpuTimeMicros; totalRecordedCallsCount += e.recordedCallCount; totalCallsCount += e.callCount; } entries.sort( Comparator.comparingDouble(value -> value.cpuTimeMicros).reversed()); } pw.println("Per-UID Summary " + datasetSizeDesc + "(cpu_time, % of total cpu_time, recorded_call_count, call_count, package/uid):"); final List summaryEntries = verbose ? entries : getHighestValues(entries, value -> value.cpuTimeMicros, 0.9); for (UidEntry entry : summaryEntries) { String uidStr = packageMap.mapUid(entry.workSourceUid); pw.println(String.format(" %10d %3.0f%% %8d %8d %s", entry.cpuTimeMicros, 100d * entry.cpuTimeMicros / totalCpuTime, entry.recordedCallCount, entry.callCount, uidStr)); } pw.println(); if (workSourceUid == Process.INVALID_UID) { pw.println(String.format(" Summary: total_cpu_time=%d, " + "calls_count=%d, avg_call_cpu_time=%.0f", totalCpuTime, totalCallsCount, (double) totalCpuTime / totalRecordedCallsCount)); pw.println(); } pw.println("Exceptions thrown (exception_count, class_name):"); final List> exceptionEntries = new ArrayList<>(); // We cannot use new ArrayList(Collection) constructor because MapCollections does not // implement toArray method. mExceptionCounts.entrySet().iterator().forEachRemaining( (e) -> exceptionEntries.add(Pair.create(e.getKey(), e.getValue()))); exceptionEntries.sort((e1, e2) -> Integer.compare(e2.second, e1.second)); for (Pair entry : exceptionEntries) { pw.println(String.format(" %6d %s", entry.second, entry.first)); } if (mPeriodicSamplingInterval != 1) { pw.println(""); pw.println("/!\\ Displayed data is sampled. See sampling interval at the top."); } } protected long getThreadTimeMicro() { return SystemClock.currentThreadTimeMicro(); } protected int getCallingUid() { return Binder.getCallingUid(); } protected int getNativeTid() { return Process.myTid(); } /** * Returns known Linux TIDs for threads taking incoming binder calls. */ public int[] getNativeTids() { return mNativeTids.toArray(); } protected long getElapsedRealtimeMicro() { return SystemClock.elapsedRealtimeNanos() / 1000; } protected boolean shouldRecordDetailedData() { return mRandom.nextInt(mPeriodicSamplingInterval) == 0; } /** * Sets to true to collect all the data. */ public void setDetailedTracking(boolean enabled) { synchronized (mLock) { if (enabled != mDetailedTracking) { mDetailedTracking = enabled; reset(); } } } /** * Whether to track the screen state. */ public void setTrackScreenInteractive(boolean enabled) { synchronized (mLock) { if (enabled != mTrackScreenInteractive) { mTrackScreenInteractive = enabled; reset(); } } } /** * Whether to track direct caller uid. */ public void setTrackDirectCallerUid(boolean enabled) { synchronized (mLock) { if (enabled != mTrackDirectCallingUid) { mTrackDirectCallingUid = enabled; reset(); } } } /** * Whether to ignore battery status when collecting stats */ public void setIgnoreBatteryStatus(boolean ignored) { synchronized (mLock) { if (ignored != mIgnoreBatteryStatus) { mIgnoreBatteryStatus = ignored; reset(); } } } /** * Marks the specified work source UID for total binder call tracking: detailed information * will be recorded for all calls from this source ID. * * This is expensive and can cause memory pressure, therefore this mode should only be used * for debugging. */ public void recordAllCallsForWorkSourceUid(int workSourceUid) { setDetailedTracking(true); Slog.i(TAG, "Recording all Binder calls for UID: " + workSourceUid); UidEntry uidEntry = getUidEntry(workSourceUid); uidEntry.recordAllTransactions = true; mRecordingAllTransactionsForUid = true; } public void setAddDebugEntries(boolean addDebugEntries) { mAddDebugEntries = addDebugEntries; } /** * Sets the maximum number of items to track. */ public void setMaxBinderCallStats(int maxKeys) { if (maxKeys <= 0) { Slog.w(TAG, "Ignored invalid max value (value must be positive): " + maxKeys); return; } synchronized (mLock) { if (maxKeys != mMaxBinderCallStatsCount) { mMaxBinderCallStatsCount = maxKeys; reset(); } } } public void setSamplingInterval(int samplingInterval) { if (samplingInterval <= 0) { Slog.w(TAG, "Ignored invalid sampling interval (value must be positive): " + samplingInterval); return; } synchronized (mLock) { if (samplingInterval != mPeriodicSamplingInterval) { mPeriodicSamplingInterval = samplingInterval; reset(); } } } /** Updates the sharding modulo. */ public void setShardingModulo(int shardingModulo) { if (shardingModulo <= 0) { Slog.w(TAG, "Ignored invalid sharding modulo (value must be positive): " + shardingModulo); return; } synchronized (mLock) { if (shardingModulo != mShardingModulo) { mShardingModulo = shardingModulo; mShardingOffset = mRandom.nextInt(shardingModulo); reset(); } } } /** Whether to collect latency histograms. */ public void setCollectLatencyData(boolean collectLatencyData) { mCollectLatencyData = collectLatencyData; } /** Whether to collect latency histograms. */ @VisibleForTesting public boolean getCollectLatencyData() { return mCollectLatencyData; } public void reset() { synchronized (mLock) { mCallStatsCount = 0; mUidEntries.clear(); mExceptionCounts.clear(); mStartCurrentTime = System.currentTimeMillis(); mStartElapsedTime = SystemClock.elapsedRealtime(); if (mBatteryStopwatch != null) { mBatteryStopwatch.reset(); } mRecordingAllTransactionsForUid = false; // Do not reset the latency observer as binder stats and latency will be pushed to WW // at different intervals so the resets should not be coupled. } } /** * Aggregated data by uid/class/method to be sent through statsd. */ public static class ExportedCallStat { public int callingUid; public int workSourceUid; public String className; public String methodName; public boolean screenInteractive; public long cpuTimeMicros; public long maxCpuTimeMicros; public long latencyMicros; public long maxLatencyMicros; public long callCount; public long recordedCallCount; public long maxRequestSizeBytes; public long maxReplySizeBytes; public long exceptionCount; // Used internally. Class binderClass; int transactionCode; } @VisibleForTesting public static class CallStat { // The UID who executed the transaction (i.e. Binder#getCallingUid). public final int callingUid; public final Class binderClass; public final int transactionCode; // True if the screen was interactive when the call ended. public final boolean screenInteractive; // Number of calls for which we collected data for. We do not record data for all the calls // when sampling is on. public long recordedCallCount; // Roughly the real number of total calls. We only track only track the API call count once // at least one non-sampled count happened. public long callCount; // Total CPU of all for all the recorded calls. // Approximate total CPU usage can be computed by // cpuTimeMicros * callCount / recordedCallCount public long cpuTimeMicros; public long maxCpuTimeMicros; // Total latency of all for all the recorded calls. // Approximate average latency can be computed by // latencyMicros * callCount / recordedCallCount public long latencyMicros; public long maxLatencyMicros; // The following fields are only computed if mDetailedTracking is set. public long maxRequestSizeBytes; public long maxReplySizeBytes; public long exceptionCount; // Call count since reset public long incrementalCallCount; public CallStat(int callingUid, Class binderClass, int transactionCode, boolean screenInteractive) { this.callingUid = callingUid; this.binderClass = binderClass; this.transactionCode = transactionCode; this.screenInteractive = screenInteractive; } @Override public CallStat clone() { CallStat clone = new CallStat(callingUid, binderClass, transactionCode, screenInteractive); clone.recordedCallCount = recordedCallCount; clone.callCount = callCount; clone.cpuTimeMicros = cpuTimeMicros; clone.maxCpuTimeMicros = maxCpuTimeMicros; clone.latencyMicros = latencyMicros; clone.maxLatencyMicros = maxLatencyMicros; clone.maxRequestSizeBytes = maxRequestSizeBytes; clone.maxReplySizeBytes = maxReplySizeBytes; clone.exceptionCount = exceptionCount; clone.incrementalCallCount = incrementalCallCount; return clone; } @Override public String toString() { // This is expensive, but CallStat.toString() is only used for debugging. String methodName = new BinderTransactionNameResolver().getMethodName(binderClass, transactionCode); return "CallStat{" + "callingUid=" + callingUid + ", transaction=" + binderClass.getSimpleName() + '.' + methodName + ", callCount=" + callCount + ", incrementalCallCount=" + incrementalCallCount + ", recordedCallCount=" + recordedCallCount + ", cpuTimeMicros=" + cpuTimeMicros + ", latencyMicros=" + latencyMicros + '}'; } } /** Key used to store CallStat object in a Map. */ public static class CallStatKey { public int callingUid; public Class binderClass; public int transactionCode; private boolean screenInteractive; @Override public boolean equals(Object o) { if (this == o) { return true; } final CallStatKey key = (CallStatKey) o; return callingUid == key.callingUid && transactionCode == key.transactionCode && screenInteractive == key.screenInteractive && (binderClass.equals(key.binderClass)); } @Override public int hashCode() { int result = binderClass.hashCode(); result = 31 * result + transactionCode; result = 31 * result + callingUid; result = 31 * result + (screenInteractive ? 1231 : 1237); return result; } } @VisibleForTesting public static class UidEntry { // The UID who is responsible for the binder transaction. If the bluetooth process execute a // transaction on behalf of app foo, the workSourceUid will be the uid of app foo. public int workSourceUid; // Number of calls for which we collected data for. We do not record data for all the calls // when sampling is on. public long recordedCallCount; // Real number of total calls. public long callCount; // Total CPU of all for all the recorded calls. // Approximate total CPU usage can be computed by // cpuTimeMicros * callCount / recordedCallCount public long cpuTimeMicros; // Call count that gets reset after delivery to BatteryStats public long incrementalCallCount; // Indicates that all transactions for the UID must be tracked public boolean recordAllTransactions; UidEntry(int uid) { this.workSourceUid = uid; } // Aggregate time spent per each call name: call_desc -> cpu_time_micros private ArrayMap mCallStats = new ArrayMap<>(); private CallStatKey mTempKey = new CallStatKey(); @Nullable CallStat get(int callingUid, Class binderClass, int transactionCode, boolean screenInteractive) { // Use a global temporary key to avoid creating new objects for every lookup. mTempKey.callingUid = callingUid; mTempKey.binderClass = binderClass; mTempKey.transactionCode = transactionCode; mTempKey.screenInteractive = screenInteractive; return mCallStats.get(mTempKey); } CallStat getOrCreate(int callingUid, Class binderClass, int transactionCode, boolean screenInteractive, boolean maxCallStatsReached) { CallStat mapCallStat = get(callingUid, binderClass, transactionCode, screenInteractive); // Only create CallStat if it's a new entry, otherwise update existing instance. if (mapCallStat == null) { if (maxCallStatsReached) { mapCallStat = get(OVERFLOW_DIRECT_CALLING_UID, OVERFLOW_BINDER, OVERFLOW_TRANSACTION_CODE, OVERFLOW_SCREEN_INTERACTIVE); if (mapCallStat != null) { return mapCallStat; } callingUid = OVERFLOW_DIRECT_CALLING_UID; binderClass = OVERFLOW_BINDER; transactionCode = OVERFLOW_TRANSACTION_CODE; screenInteractive = OVERFLOW_SCREEN_INTERACTIVE; } mapCallStat = new CallStat(callingUid, binderClass, transactionCode, screenInteractive); CallStatKey key = new CallStatKey(); key.callingUid = callingUid; key.binderClass = binderClass; key.transactionCode = transactionCode; key.screenInteractive = screenInteractive; mCallStats.put(key, mapCallStat); } return mapCallStat; } /** * Returns list of calls sorted by CPU time */ public Collection getCallStatsList() { return mCallStats.values(); } @Override public String toString() { return "UidEntry{" + "cpuTimeMicros=" + cpuTimeMicros + ", callCount=" + callCount + ", mCallStats=" + mCallStats + '}'; } @Override public boolean equals(Object o) { if (this == o) { return true; } UidEntry uidEntry = (UidEntry) o; return workSourceUid == uidEntry.workSourceUid; } @Override public int hashCode() { return workSourceUid; } } @VisibleForTesting public SparseArray getUidEntries() { return mUidEntries; } @VisibleForTesting public ArrayMap getExceptionCounts() { return mExceptionCounts; } public BinderLatencyObserver getLatencyObserver() { return mLatencyObserver; } @VisibleForTesting public static List getHighestValues(List list, ToDoubleFunction toDouble, double percentile) { List sortedList = new ArrayList<>(list); sortedList.sort(Comparator.comparingDouble(toDouble).reversed()); double total = 0; for (T item : list) { total += toDouble.applyAsDouble(item); } List result = new ArrayList<>(); double runningSum = 0; for (T item : sortedList) { if (runningSum > percentile * total) { break; } result.add(item); runningSum += toDouble.applyAsDouble(item); } return result; } private static int compareByCpuDesc( ExportedCallStat a, ExportedCallStat b) { return Long.compare(b.cpuTimeMicros, a.cpuTimeMicros); } private static int compareByBinderClassAndCode( ExportedCallStat a, ExportedCallStat b) { int result = a.className.compareTo(b.className); return result != 0 ? result : Integer.compare(a.transactionCode, b.transactionCode); } /** @hide */ public static void startForBluetooth(Context context) { new BinderCallsStats.SettingsObserver( context, new BinderCallsStats( new BinderCallsStats.Injector(), com.android.internal.os.BinderLatencyProto.Dims.BLUETOOTH)); } /** * Settings observer for other processes (not system_server). * * We do not want to collect cpu data from other processes so only latency collection should be * possible to enable. */ public static class SettingsObserver extends ContentObserver { // Settings for BinderCallsStats. public static final String SETTINGS_ENABLED_KEY = "enabled"; public static final String SETTINGS_DETAILED_TRACKING_KEY = "detailed_tracking"; public static final String SETTINGS_UPLOAD_DATA_KEY = "upload_data"; public static final String SETTINGS_SAMPLING_INTERVAL_KEY = "sampling_interval"; public static final String SETTINGS_TRACK_SCREEN_INTERACTIVE_KEY = "track_screen_state"; public static final String SETTINGS_TRACK_DIRECT_CALLING_UID_KEY = "track_calling_uid"; public static final String SETTINGS_MAX_CALL_STATS_KEY = "max_call_stats_count"; public static final String SETTINGS_IGNORE_BATTERY_STATUS_KEY = "ignore_battery_status"; public static final String SETTINGS_SHARDING_MODULO_KEY = "sharding_modulo"; // Settings for BinderLatencyObserver. public static final String SETTINGS_COLLECT_LATENCY_DATA_KEY = "collect_latency_data"; public static final String SETTINGS_LATENCY_OBSERVER_SAMPLING_INTERVAL_KEY = "latency_observer_sampling_interval"; public static final String SETTINGS_LATENCY_OBSERVER_SHARDING_MODULO_KEY = "latency_observer_sharding_modulo"; public static final String SETTINGS_LATENCY_OBSERVER_PUSH_INTERVAL_MINUTES_KEY = "latency_observer_push_interval_minutes"; public static final String SETTINGS_LATENCY_HISTOGRAM_BUCKET_COUNT_KEY = "latency_histogram_bucket_count"; public static final String SETTINGS_LATENCY_HISTOGRAM_FIRST_BUCKET_SIZE_KEY = "latency_histogram_first_bucket_size"; public static final String SETTINGS_LATENCY_HISTOGRAM_BUCKET_SCALE_FACTOR_KEY = "latency_histogram_bucket_scale_factor"; private boolean mEnabled; private final Uri mUri = Settings.Global.getUriFor(Settings.Global.BINDER_CALLS_STATS); private final Context mContext; private final KeyValueListParser mParser = new KeyValueListParser(','); private final BinderCallsStats mBinderCallsStats; public SettingsObserver(Context context, BinderCallsStats binderCallsStats) { super(BackgroundThread.getHandler()); mContext = context; context.getContentResolver().registerContentObserver(mUri, false, this); mBinderCallsStats = binderCallsStats; // Always kick once to ensure that we match current state onChange(); } @Override public void onChange(boolean selfChange, Uri uri, int userId) { if (mUri.equals(uri)) { onChange(); } } void onChange() { try { mParser.setString(Settings.Global.getString(mContext.getContentResolver(), Settings.Global.BINDER_CALLS_STATS)); } catch (IllegalArgumentException e) { Slog.e(TAG, "Bad binder call stats settings", e); } // Cpu data collection should always be disabled for other processes. mBinderCallsStats.setDetailedTracking(false); mBinderCallsStats.setTrackScreenInteractive(false); mBinderCallsStats.setTrackDirectCallerUid(false); mBinderCallsStats.setIgnoreBatteryStatus( mParser.getBoolean(SETTINGS_IGNORE_BATTERY_STATUS_KEY, BinderCallsStats.DEFAULT_IGNORE_BATTERY_STATUS)); mBinderCallsStats.setCollectLatencyData( mParser.getBoolean(SETTINGS_COLLECT_LATENCY_DATA_KEY, BinderCallsStats.DEFAULT_COLLECT_LATENCY_DATA)); // Binder latency observer settings. configureLatencyObserver(mParser, mBinderCallsStats.getLatencyObserver()); final boolean enabled = mParser.getBoolean(SETTINGS_ENABLED_KEY, BinderCallsStats.ENABLED_DEFAULT); if (mEnabled != enabled) { if (enabled) { Binder.setObserver(mBinderCallsStats); } else { Binder.setObserver(null); } mEnabled = enabled; mBinderCallsStats.reset(); mBinderCallsStats.setAddDebugEntries(enabled); mBinderCallsStats.getLatencyObserver().reset(); } } /** Configures the binder latency observer related settings. */ public static void configureLatencyObserver( KeyValueListParser mParser, BinderLatencyObserver binderLatencyObserver) { binderLatencyObserver.setSamplingInterval(mParser.getInt( SETTINGS_LATENCY_OBSERVER_SAMPLING_INTERVAL_KEY, BinderLatencyObserver.PERIODIC_SAMPLING_INTERVAL_DEFAULT)); binderLatencyObserver.setShardingModulo(mParser.getInt( SETTINGS_LATENCY_OBSERVER_SHARDING_MODULO_KEY, BinderLatencyObserver.SHARDING_MODULO_DEFAULT)); binderLatencyObserver.setHistogramBucketsParams( mParser.getInt( SETTINGS_LATENCY_HISTOGRAM_BUCKET_COUNT_KEY, BinderLatencyObserver.BUCKET_COUNT_DEFAULT), mParser.getInt( SETTINGS_LATENCY_HISTOGRAM_FIRST_BUCKET_SIZE_KEY, BinderLatencyObserver.FIRST_BUCKET_SIZE_DEFAULT), mParser.getFloat( SETTINGS_LATENCY_HISTOGRAM_BUCKET_SCALE_FACTOR_KEY, BinderLatencyObserver.BUCKET_SCALE_FACTOR_DEFAULT)); binderLatencyObserver.setPushInterval(mParser.getInt( SETTINGS_LATENCY_OBSERVER_PUSH_INTERVAL_MINUTES_KEY, BinderLatencyObserver.STATSD_PUSH_INTERVAL_MINUTES_DEFAULT)); } } }