diff options
4 files changed, 318 insertions, 91 deletions
diff --git a/core/java/com/android/internal/os/BinderCallsStats.java b/core/java/com/android/internal/os/BinderCallsStats.java index 201626abd820..f5bef0b006f5 100644 --- a/core/java/com/android/internal/os/BinderCallsStats.java +++ b/core/java/com/android/internal/os/BinderCallsStats.java @@ -74,6 +74,10 @@ public class BinderCallsStats implements BinderInternal.Observer { // 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; @@ -178,7 +182,8 @@ public class BinderCallsStats implements BinderInternal.Observer { @Override @Nullable public CallSession callStarted(Binder binder, int code, int workSourceUid) { - if (mDeviceState == null || mDeviceState.isCharging()) { + if (!mRecordingAllTransactionsForUid + && (mDeviceState == null || mDeviceState.isCharging())) { return null; } @@ -190,7 +195,9 @@ public class BinderCallsStats implements BinderInternal.Observer { s.exceptionThrown = false; s.cpuTimeStarted = -1; s.timeStarted = -1; - if (shouldRecordDetailedData()) { + s.recordedCall = shouldRecordDetailedData(); + + if (mRecordingAllTransactionsForUid || s.recordedCall) { s.cpuTimeStarted = getThreadTimeMicro(); s.timeStarted = getElapsedRealtimeMicro(); } @@ -218,8 +225,17 @@ public class BinderCallsStats implements BinderInternal.Observer { private void processCallEnded(CallSession s, int parcelRequestSize, int parcelReplySize, int workSourceUid) { - // Non-negative time signals we need to record data for this call. - final boolean recordCall = s.cpuTimeStarted >= 0; + 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) { @@ -238,14 +254,17 @@ public class BinderCallsStats implements BinderInternal.Observer { synchronized (mLock) { // This was already checked in #callStart but check again while synchronized. - if (mDeviceState == null || mDeviceState.isCharging()) { + if (!mRecordingAllTransactionsForUid + && (mDeviceState == null || mDeviceState.isCharging())) { return; } - final UidEntry uidEntry = getUidEntry(workSourceUid); + if (uidEntry == null) { + uidEntry = getUidEntry(workSourceUid); + } + uidEntry.callCount++; uidEntry.incrementalCallCount++; - if (recordCall) { uidEntry.cpuTimeMicros += duration; uidEntry.recordedCallCount++; @@ -357,28 +376,67 @@ public class BinderCallsStats implements BinderInternal.Observer { for (int entryIdx = 0; entryIdx < uidEntriesSize; entryIdx++) { final UidEntry entry = mUidEntries.valueAt(entryIdx); for (CallStat stat : entry.getCallStatsList()) { - ExportedCallStat exported = new ExportedCallStat(); - exported.workSourceUid = entry.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; - resultCallStats.add(exported); + resultCallStats.add(getExportedCallStat(entry.workSourceUid, stat)); } } } // 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)); + } + + return resultCallStats; + } + + /** + * This method is expensive to call. + */ + public ArrayList<ExportedCallStat> getExportedCallStats(int workSourceUid) { + ArrayList<ExportedCallStat> resultCallStats = new ArrayList<>(); + synchronized (mLock) { + final UidEntry entry = getUidEntry(workSourceUid); + for (CallStat stat : entry.getCallStatsList()) { + resultCallStats.add(getExportedCallStat(workSourceUid, stat)); + } + } + + // 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<ExportedCallStat> resultCallStats) { + // Resolve codes outside of the lock since it can be slow. ExportedCallStat previous = null; String previousMethodName = null; resultCallStats.sort(BinderCallsStats::compareByBinderClassAndCode); @@ -398,17 +456,6 @@ public class BinderCallsStats implements BinderInternal.Observer { exported.methodName = methodName; previous = exported; } - - // 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)); - } - - return resultCallStats; } private ExportedCallStat createDebugEntry(String variableName, long value) { @@ -432,33 +479,24 @@ public class BinderCallsStats implements BinderInternal.Observer { } /** Writes the collected statistics to the supplied {@link PrintWriter}.*/ - public void dump(PrintWriter pw, AppIdToPackageMap packageMap, boolean verbose) { + public void dump(PrintWriter pw, AppIdToPackageMap packageMap, int workSourceUid, + boolean verbose) { synchronized (mLock) { - dumpLocked(pw, packageMap, verbose); + dumpLocked(pw, packageMap, workSourceUid, verbose); } } - private void dumpLocked(PrintWriter pw, AppIdToPackageMap packageMap, boolean verbose) { - long totalCallsCount = 0; - long totalRecordedCallsCount = 0; - long totalCpuTime = 0; + 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); - final List<UidEntry> entries = new ArrayList<>(); - 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.<UidEntry>comparingDouble(value -> value.cpuTimeMicros).reversed()); final String datasetSizeDesc = verbose ? "" : "(top 90% by cpu time) "; final StringBuilder sb = new StringBuilder(); pw.println("Per-UID raw data " + datasetSizeDesc @@ -467,10 +505,15 @@ public class BinderCallsStats implements BinderInternal.Observer { + "latency_time_micros, max_latency_time_micros, exception_count, " + "max_request_size_bytes, max_reply_size_bytes, recorded_call_count, " + "call_count):"); - final List<ExportedCallStat> exportedCallStats = getExportedCallStats(); + final List<ExportedCallStat> exportedCallStats; + if (workSourceUid != Process.INVALID_UID) { + exportedCallStats = getExportedCallStats(workSourceUid); + } else { + exportedCallStats = getExportedCallStats(); + } exportedCallStats.sort(BinderCallsStats::compareByCpuDesc); for (ExportedCallStat e : exportedCallStats) { - if (e.methodName.startsWith(DEBUG_ENTRY_PREFIX)) { + if (e.methodName != null && e.methodName.startsWith(DEBUG_ENTRY_PREFIX)) { // Do not dump debug entries. continue; } @@ -494,6 +537,30 @@ public class BinderCallsStats implements BinderInternal.Observer { pw.println(sb); } pw.println(); + final List<UidEntry> 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.<UidEntry>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<UidEntry> summaryEntries = verbose ? entries @@ -505,10 +572,13 @@ public class BinderCallsStats implements BinderInternal.Observer { entry.recordedCallCount, entry.callCount, uidStr)); } pw.println(); - pw.println(String.format(" Summary: total_cpu_time=%d, " - + "calls_count=%d, avg_call_cpu_time=%.0f", - totalCpuTime, totalCallsCount, (double) totalCpuTime / totalRecordedCallsCount)); - 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<Pair<String, Integer>> exceptionEntries = new ArrayList<>(); @@ -590,6 +660,22 @@ public class BinderCallsStats implements BinderInternal.Observer { } } + /** + * 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; } @@ -637,6 +723,7 @@ public class BinderCallsStats implements BinderInternal.Observer { if (mBatteryStopwatch != null) { mBatteryStopwatch.reset(); } + mRecordingAllTransactionsForUid = false; } } @@ -767,6 +854,8 @@ public class BinderCallsStats implements BinderInternal.Observer { 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; diff --git a/core/java/com/android/internal/os/BinderInternal.java b/core/java/com/android/internal/os/BinderInternal.java index f14d5f2bbbeb..2645b8e84cf1 100644 --- a/core/java/com/android/internal/os/BinderInternal.java +++ b/core/java/com/android/internal/os/BinderInternal.java @@ -85,9 +85,10 @@ public class BinderInternal { long timeStarted; // Should be set to one when an exception is thrown. boolean exceptionThrown; + // Detailed information should be recorded for this call when it ends. + public boolean recordedCall; } - /** * Responsible for resolving a work source. */ diff --git a/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java b/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java index 188ba9e0ca0e..96250db4aa51 100644 --- a/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java +++ b/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java @@ -20,6 +20,7 @@ import static com.google.common.truth.Truth.assertThat; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; import android.os.Binder; import android.os.Handler; @@ -44,6 +45,7 @@ import java.io.PrintWriter; import java.io.StringWriter; import java.util.ArrayList; import java.util.Arrays; +import java.util.Collection; import java.util.HashMap; import java.util.List; import java.util.Random; @@ -493,7 +495,9 @@ public class BinderCallsStatsTest { bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE, WORKSOURCE_UID); PrintWriter pw = new PrintWriter(new StringWriter()); - bcs.dump(pw, new AppIdToPackageMap(new HashMap<>()), true); + bcs.dump(pw, new AppIdToPackageMap(new HashMap<>()), Process.INVALID_UID, true); + + bcs.dump(pw, new AppIdToPackageMap(new HashMap<>()), WORKSOURCE_UID, true); } @Test @@ -606,8 +610,8 @@ public class BinderCallsStatsTest { assertEquals("-1", callStats.methodName); assertEquals("com.android.internal.os.BinderCallsStats$OverflowBinder", callStats.className); - assertEquals(false , callStats.screenInteractive); - assertEquals(-1 , callStats.callingUid); + assertEquals(false, callStats.screenInteractive); + assertEquals(-1, callStats.callingUid); } @Test @@ -785,7 +789,7 @@ public class BinderCallsStatsTest { bcs.time += 30; bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE, WORKSOURCE_UID); - for (Runnable runnable: mHandler.mRunnables) { + for (Runnable runnable : mHandler.mRunnables) { // Execute all pending runnables. Ignore the delay. runnable.run(); } @@ -839,6 +843,53 @@ public class BinderCallsStatsTest { assertEquals(3, tids[2]); } + @Test + public void testTrackingSpecificWorksourceUid() { + mDeviceState.setCharging(true); + + Binder binder = new Binder(); + + TestBinderCallsStats bcs = new TestBinderCallsStats(); + bcs.recordAllCallsForWorkSourceUid(WORKSOURCE_UID); + + int[] transactions = {41, 42, 43, 42, 43, 43}; + int[] durationsMs = {100, 200, 300, 400, 500, 600}; + + for (int i = 0; i < transactions.length; i++) { + CallSession callSession = bcs.callStarted(binder, transactions[i], WORKSOURCE_UID); + bcs.time += durationsMs[i]; + bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE, WORKSOURCE_UID); + } + + BinderCallsStats.UidEntry uidEntry = bcs.getUidEntries().get(WORKSOURCE_UID); + Assert.assertNotNull(uidEntry); + assertEquals(6, uidEntry.callCount); + + Collection<BinderCallsStats.CallStat> callStatsList = uidEntry.getCallStatsList(); + assertEquals(3, callStatsList.size()); + for (BinderCallsStats.CallStat callStat : callStatsList) { + switch (callStat.transactionCode) { + case 41: + assertEquals(1, callStat.callCount); + assertEquals(1, callStat.incrementalCallCount); + assertEquals(100, callStat.cpuTimeMicros); + break; + case 42: + assertEquals(2, callStat.callCount); + assertEquals(2, callStat.incrementalCallCount); + assertEquals(200 + 400, callStat.cpuTimeMicros); + break; + case 43: + assertEquals(3, callStat.callCount); + assertEquals(3, callStat.incrementalCallCount); + assertEquals(300 + 500 + 600, callStat.cpuTimeMicros); + break; + default: + fail("Unexpected transaction code: " + callStat.transactionCode); + } + } + } + private static class TestHandler extends Handler { ArrayList<Runnable> mRunnables = new ArrayList<>(); diff --git a/services/core/java/com/android/server/BinderCallsStatsService.java b/services/core/java/com/android/server/BinderCallsStatsService.java index a3c04be02c6f..c9513592ea79 100644 --- a/services/core/java/com/android/server/BinderCallsStatsService.java +++ b/services/core/java/com/android/server/BinderCallsStatsService.java @@ -28,7 +28,9 @@ import android.database.ContentObserver; import android.net.Uri; import android.os.BatteryStatsInternal; import android.os.Binder; +import android.os.ParcelFileDescriptor; import android.os.Process; +import android.os.ShellCommand; import android.os.SystemProperties; import android.os.UserHandle; import android.provider.Settings; @@ -308,50 +310,134 @@ public class BinderCallsStatsService extends Binder { } boolean verbose = false; + int worksourceUid = Process.INVALID_UID; if (args != null) { - for (final String arg : args) { + for (int i = 0; i < args.length; i++) { + String arg = args[i]; if ("-a".equals(arg)) { verbose = true; - } else if ("--reset".equals(arg)) { + } else if ("-h".equals(arg)) { + pw.println("dumpsys binder_calls_stats options:"); + pw.println(" -a: Verbose"); + pw.println(" --work-source-uid <UID>: Dump binder calls from the UID"); + return; + } else if ("--work-source-uid".equals(arg)) { + i++; + if (i >= args.length) { + throw new IllegalArgumentException( + "Argument expected after \"" + arg + "\""); + } + String uidArg = args[i]; + try { + worksourceUid = Integer.parseInt(uidArg); + } catch (NumberFormatException e) { + pw.println("Invalid UID: " + uidArg); + return; + } + } + } + + if (args.length > 0 && worksourceUid == Process.INVALID_UID) { + // For compatibility, support "cmd"-style commands when passed to "dumpsys". + BinderCallsStatsShellCommand command = new BinderCallsStatsShellCommand(pw); + int status = command.exec(this, null, FileDescriptor.out, FileDescriptor.err, args); + if (status == 0) { + return; + } + } + } + mBinderCallsStats.dump(pw, AppIdToPackageMap.getSnapshot(), worksourceUid, verbose); + } + + @Override + public int handleShellCommand(ParcelFileDescriptor in, ParcelFileDescriptor out, + ParcelFileDescriptor err, String[] args) { + ShellCommand command = new BinderCallsStatsShellCommand(null); + int status = command.exec(this, in.getFileDescriptor(), out.getFileDescriptor(), + err.getFileDescriptor(), args); + if (status != 0) { + command.onHelp(); + } + return status; + } + + private class BinderCallsStatsShellCommand extends ShellCommand { + private final PrintWriter mPrintWriter; + + BinderCallsStatsShellCommand(PrintWriter printWriter) { + mPrintWriter = printWriter; + } + + @Override + public PrintWriter getOutPrintWriter() { + if (mPrintWriter != null) { + return mPrintWriter; + } + return super.getOutPrintWriter(); + } + + @Override + public int onCommand(String cmd) { + PrintWriter pw = getOutPrintWriter(); + if (cmd == null) { + return -1; + } + + switch (cmd) { + case "--reset": reset(); pw.println("binder_calls_stats reset."); - return; - } else if ("--enable".equals(arg)) { + break; + case "--enable": Binder.setObserver(mBinderCallsStats); - return; - } else if ("--disable".equals(arg)) { + break; + case "--disable": Binder.setObserver(null); - return; - } else if ("--no-sampling".equals(arg)) { + break; + case "--no-sampling": mBinderCallsStats.setSamplingInterval(1); - return; - } else if ("--enable-detailed-tracking".equals(arg)) { + break; + case "--enable-detailed-tracking": SystemProperties.set(PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, "1"); mBinderCallsStats.setDetailedTracking(true); pw.println("Detailed tracking enabled"); - return; - } else if ("--disable-detailed-tracking".equals(arg)) { + break; + case "--disable-detailed-tracking": SystemProperties.set(PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, ""); mBinderCallsStats.setDetailedTracking(false); pw.println("Detailed tracking disabled"); - return; - } else if ("--dump-worksource-provider".equals(arg)) { + break; + case "--dump-worksource-provider": + mBinderCallsStats.setDetailedTracking(true); mWorkSourceProvider.dump(pw, AppIdToPackageMap.getSnapshot()); - return; - } else if ("-h".equals(arg)) { - pw.println("binder_calls_stats commands:"); - pw.println(" --reset: Reset stats"); - pw.println(" --enable: Enable tracking binder calls"); - pw.println(" --disable: Disables tracking binder calls"); - pw.println(" --no-sampling: Tracks all calls"); - pw.println(" --enable-detailed-tracking: Enables detailed tracking"); - pw.println(" --disable-detailed-tracking: Disables detailed tracking"); - return; - } else { - pw.println("Unknown option: " + arg); - } + break; + case "--work-source-uid": + String uidArg = getNextArgRequired(); + try { + int uid = Integer.parseInt(uidArg); + mBinderCallsStats.recordAllCallsForWorkSourceUid(uid); + } catch (NumberFormatException e) { + pw.println("Invalid UID: " + uidArg); + return -1; + } + break; + default: + return handleDefaultCommands(cmd); } + return 0; + } + + @Override + public void onHelp() { + PrintWriter pw = getOutPrintWriter(); + pw.println("binder_calls_stats commands:"); + pw.println(" --reset: Reset stats"); + pw.println(" --enable: Enable tracking binder calls"); + pw.println(" --disable: Disables tracking binder calls"); + pw.println(" --no-sampling: Tracks all calls"); + pw.println(" --enable-detailed-tracking: Enables detailed tracking"); + pw.println(" --disable-detailed-tracking: Disables detailed tracking"); + pw.println(" --work-source-uid <UID>: Track all binder calls from the UID"); } - mBinderCallsStats.dump(pw, AppIdToPackageMap.getSnapshot(), verbose); } } |