Merge "Add binder call stats tracking for individual UID" (326e3ca1) · Commits · e / os / android_frameworks_base

core/java/com/android/internal/os/BinderCallsStats.java

+147 −58

Original line number	Diff line number	Diff line
		@@ -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,8 +376,47 @@ public class BinderCallsStats implements BinderInternal.Observer {
		for (int entryIdx = 0; entryIdx < uidEntriesSize; entryIdx++) {
		final UidEntry entry = mUidEntries.valueAt(entryIdx);
		for (CallStat stat : entry.getCallStatsList()) {
		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 = entry.workSourceUid;
		exported.workSourceUid = workSourceUid;
		exported.callingUid = stat.callingUid;
		exported.className = stat.binderClass.getName();
		exported.binderClass = stat.binderClass;
		@@ -373,11 +431,11 @@ public class BinderCallsStats implements BinderInternal.Observer {
		exported.maxRequestSizeBytes = stat.maxRequestSizeBytes;
		exported.maxReplySizeBytes = stat.maxReplySizeBytes;
		exported.exceptionCount = stat.exceptionCount;
		resultCallStats.add(exported);
		}
		}
		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();
		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));
		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;

core/java/com/android/internal/os/BinderInternal.java

+2 −1

Original line number	Diff line number	Diff line
		@@ -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.
		*/

core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java

+55 −4

Original line number	Diff line number	Diff line
		@@ -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
		@@ -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<>();

services/core/java/com/android/server/BinderCallsStatsService.java

+114 −28

Original line number	Diff line number	Diff line
		@@ -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,37 +310,126 @@ 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)) {
		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");
		@@ -346,12 +437,7 @@ public class BinderCallsStatsService extends Binder {
		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);
		}
		}
		pw.println(" --work-source-uid <UID>: Track all binder calls from the UID");
		}
		mBinderCallsStats.dump(pw, AppIdToPackageMap.getSnapshot(), verbose);
		}
		}