Add binder call stats tracking for individual UID

Test: $ adb shell cmd binder_calls_stats --work-source-uid <UID>
followed by
$ adb shell dumpsys binder_calls_stats
or
$ adb shell dumpsys binder_calls_stats --work-source-uid <UID>

Change-Id: I8e7d8d4b50b4bd068ad13cbdc75bd87b8c25e7a6
This commit is contained in:
Dmitri Plotnikov
2020-06-18 14:15:33 -07:00
parent 1a33ace694
commit 38daff3ce2
4 changed files with 327 additions and 100 deletions

View File

@@ -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,27 +376,66 @@ 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;
@@ -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;

View File

@@ -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.
*/

View File

@@ -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<>();

View File

@@ -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)) {
reset();
pw.println("binder_calls_stats reset.");
return;
} else if ("--enable".equals(arg)) {
Binder.setObserver(mBinderCallsStats);
return;
} else if ("--disable".equals(arg)) {
Binder.setObserver(null);
return;
} else if ("--no-sampling".equals(arg)) {
mBinderCallsStats.setSamplingInterval(1);
return;
} else if ("--enable-detailed-tracking".equals(arg)) {
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)) {
SystemProperties.set(PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, "");
mBinderCallsStats.setDetailedTracking(false);
pw.println("Detailed tracking disabled");
return;
} else if ("--dump-worksource-provider".equals(arg)) {
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");
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;
} else {
pw.println("Unknown option: " + arg);
}
}
}
mBinderCallsStats.dump(pw, AppIdToPackageMap.getSnapshot(), verbose);
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.");
break;
case "--enable":
Binder.setObserver(mBinderCallsStats);
break;
case "--disable":
Binder.setObserver(null);
break;
case "--no-sampling":
mBinderCallsStats.setSamplingInterval(1);
break;
case "--enable-detailed-tracking":
SystemProperties.set(PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, "1");
mBinderCallsStats.setDetailedTracking(true);
pw.println("Detailed tracking enabled");
break;
case "--disable-detailed-tracking":
SystemProperties.set(PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, "");
mBinderCallsStats.setDetailedTracking(false);
pw.println("Detailed tracking disabled");
break;
case "--dump-worksource-provider":
mBinderCallsStats.setDetailedTracking(true);
mWorkSourceProvider.dump(pw, AppIdToPackageMap.getSnapshot());
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");
}
}
}