Merge "Binder calls stats - random sampling." (2717c714) · Commits · e / os / android_frameworks_base

apct-tests/perftests/core/src/android/os/BinderCallsStatsPerfTest.java

+3 −1

Original line number	Diff line number	Diff line
		@@ -23,6 +23,8 @@ import android.support.test.runner.AndroidJUnit4;

		import com.android.internal.os.BinderCallsStats;

		import java.util.Random;

		import org.junit.After;
		import org.junit.Before;
		import org.junit.Rule;
		@@ -45,7 +47,7 @@ public class BinderCallsStatsPerfTest {

		@Before
		public void setUp() {
		mBinderCallsStats = new BinderCallsStats();
		mBinderCallsStats = new BinderCallsStats(new Random());
		}

		@After

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

+111 −128

Original line number	Diff line number	Diff line
		@@ -38,6 +38,7 @@ import java.util.Comparator;
		import java.util.List;
		import java.util.Map;
		import java.util.Queue;
		import java.util.Random;
		import java.util.Set;
		import java.util.concurrent.ConcurrentLinkedQueue;
		import java.util.function.ToDoubleFunction;
		@@ -57,7 +58,7 @@ public class BinderCallsStats {
		private static final int MAX_EXCEPTION_COUNT_SIZE = 50;
		private static final String EXCEPTION_COUNT_OVERFLOW_NAME = "overflow";
		private static final CallSession NOT_ENABLED = new CallSession();
		private static final BinderCallsStats sInstance = new BinderCallsStats();
		private static final BinderCallsStats sInstance = new BinderCallsStats(new Random());

		private volatile boolean mEnabled = ENABLED_DEFAULT;
		private volatile boolean mDetailedTracking = DETAILED_TRACKING_DEFAULT;
		@@ -68,12 +69,12 @@ public class BinderCallsStats {
		private final ArrayMap<String, Integer> mExceptionCounts = new ArrayMap<>();
		private final Queue<CallSession> mCallSessionsPool = new ConcurrentLinkedQueue<>();
		private final Object mLock = new Object();
		private final Random mRandom;
		private long mStartTime = System.currentTimeMillis();
		@GuardedBy("mLock")
		private UidEntry mSampledEntries = new UidEntry(-1);

		@VisibleForTesting // Use getInstance() instead.
		public BinderCallsStats() {
		public BinderCallsStats(Random random) {
		this.mRandom = random;
		}

		public CallSession callStarted(Binder binder, int code) {
		@@ -98,17 +99,13 @@ public class BinderCallsStats {
		s.timeStarted = -1;

		synchronized (mLock) {
		if (mDetailedTracking) {
		s.cpuTimeStarted = getThreadTimeMicro();
		s.timeStarted = getElapsedRealtimeMicro();
		} else {
		s.sampledCallStat = mSampledEntries.getOrCreate(s.callStat);
		if (s.sampledCallStat.callCount % mPeriodicSamplingInterval == 0) {
		if (!mDetailedTracking && !shouldTrackCall()) {
		return s;
		}

		s.cpuTimeStarted = getThreadTimeMicro();
		s.timeStarted = getElapsedRealtimeMicro();
		}
		}
		}
		return s;
		}

		@@ -131,57 +128,39 @@ public class BinderCallsStats {
		return;
		}

		long duration;
		long latencyDuration;
		if (mDetailedTracking) {
		duration = getThreadTimeMicro() - s.cpuTimeStarted;
		latencyDuration = getElapsedRealtimeMicro() - s.timeStarted;
		} else {
		CallStat cs = s.sampledCallStat;
		// Non-negative time signals beginning of the new sampling interval
		if (s.cpuTimeStarted >= 0) {
		duration = getThreadTimeMicro() - s.cpuTimeStarted;
		latencyDuration = getElapsedRealtimeMicro() - s.timeStarted;
		} else {
		// callCount is always incremented, but time only once per sampling interval
		long samplesCount = cs.callCount / mPeriodicSamplingInterval + 1;
		duration = cs.cpuTimeMicros / samplesCount;
		latencyDuration = cs.latencyMicros / samplesCount;
		}
		}

		int callingUid = getCallingUid();

		final int callingUid = getCallingUid();
		UidEntry uidEntry = mUidEntries.get(callingUid);
		if (uidEntry == null) {
		uidEntry = new UidEntry(callingUid);
		mUidEntries.put(callingUid, uidEntry);
		}
		uidEntry.callCount++;
		CallStat callStat = uidEntry.getOrCreate(s.callStat);
		callStat.callCount++;

		CallStat callStat;
		// Non-negative time signals we need to record data for this call.
		final boolean recordCall = s.cpuTimeStarted >= 0;
		if (recordCall) {
		final long duration = getThreadTimeMicro() - s.cpuTimeStarted;
		final long latencyDuration = getElapsedRealtimeMicro() - s.timeStarted;
		uidEntry.cpuTimeMicros += duration;
		uidEntry.recordedCallCount++;

		callStat.recordedCallCount++;
		callStat.methodName = s.callStat.methodName;
		callStat.cpuTimeMicros += duration;
		callStat.maxCpuTimeMicros = Math.max(callStat.maxCpuTimeMicros, duration);
		callStat.latencyMicros += latencyDuration;
		callStat.maxLatencyMicros =
		Math.max(callStat.maxLatencyMicros, latencyDuration);
		if (mDetailedTracking) {
		// Find CallStat entry and update its total time
		callStat = uidEntry.getOrCreate(s.callStat);
		callStat.exceptionCount += s.exceptionThrown ? 1 : 0;
		callStat.maxRequestSizeBytes =
		Math.max(callStat.maxRequestSizeBytes, parcelRequestSize);
		callStat.maxReplySizeBytes =
		Math.max(callStat.maxReplySizeBytes, parcelReplySize);
		} else {
		// update sampled timings in the beginning of each interval
		callStat = s.sampledCallStat;
		}
		callStat.callCount++;
		callStat.methodName = s.callStat.methodName;
		if (s.cpuTimeStarted >= 0) {
		callStat.cpuTimeMicros += duration;
		callStat.maxCpuTimeMicros = Math.max(callStat.maxCpuTimeMicros, duration);
		callStat.latencyMicros += latencyDuration;
		callStat.maxLatencyMicros = Math.max(callStat.maxLatencyMicros, latencyDuration);
		}

		uidEntry.cpuTimeMicros += duration;
		uidEntry.callCount++;
		}
		}

		@@ -234,6 +213,7 @@ public class BinderCallsStats {
		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;
		@@ -259,9 +239,11 @@ public class BinderCallsStats {
		}

		long totalCallsCount = 0;
		long totalRecordedCallsCount = 0;
		long totalCpuTime = 0;
		pw.print("Start time: ");
		pw.println(DateFormat.format("yyyy-MM-dd HH:mm:ss", mStartTime));
		pw.println("Sampling interval period: " + mPeriodicSamplingInterval);
		List<UidEntry> entries = new ArrayList<>();

		int uidEntriesSize = mUidEntries.size();
		@@ -269,70 +251,53 @@ public class BinderCallsStats {
		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());
		String datasetSizeDesc = verbose ? "" : "(top 90% by cpu time) ";
		StringBuilder sb = new StringBuilder();
		if (mDetailedTracking) {
		List<UidEntry> topEntries = verbose ? entries
		: getHighestValues(entries, value -> value.cpuTimeMicros, 0.9);
		pw.println("Per-UID raw data " + datasetSizeDesc
		+ "(package/uid, call_desc, cpu_time_micros, max_cpu_time_micros, "
		+ "latency_time_micros, max_latency_time_micros, exception_count, "
		+ "max_request_size_bytes, max_reply_size_bytes, call_count):");
		List<UidEntry> topEntries = verbose ? entries
		: getHighestValues(entries, value -> value.cpuTimeMicros, 0.9);
		+ "max_request_size_bytes, max_reply_size_bytes, recorded_call_count, "
		+ "call_count):");
		for (UidEntry uidEntry : topEntries) {
		for (CallStat e : uidEntry.getCallStatsList()) {
		sb.setLength(0);
		sb.append(" ")
		.append(uidToString(uidEntry.uid, appIdToPkgNameMap))
		.append(",").append(e)
		.append(',').append(e)
		.append(',').append(e.cpuTimeMicros)
		.append(',').append(e.maxCpuTimeMicros)
		.append(',').append(e.latencyMicros)
		.append(',').append(e.maxLatencyMicros)
		.append(',').append(e.exceptionCount)
		.append(',').append(e.maxRequestSizeBytes)
		.append(',').append(e.maxReplySizeBytes)
		.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();
		} else {
		pw.println("Sampled stats " + datasetSizeDesc
		+ "(call_desc, cpu_time, call_count, exception_count):");
		List<CallStat> sampledStatsList = mSampledEntries.getCallStatsList();
		// Show all if verbose, otherwise 90th percentile
		if (!verbose) {
		sampledStatsList = getHighestValues(sampledStatsList,
		value -> value.cpuTimeMicros, 0.9);
		}
		for (CallStat e : sampledStatsList) {
		sb.setLength(0);
		sb.append(" ").append(e)
		.append(',').append(e.cpuTimeMicros * mPeriodicSamplingInterval)
		.append(',').append(e.callCount)
		.append(',').append(e.exceptionCount);
		pw.println(sb);
		}
		pw.println();
		}
		pw.println("Per-UID Summary " + datasetSizeDesc
		+ "(cpu_time, % of total cpu_time, call_count, exception_count, package/uid):");
		+ "(cpu_time, % of total cpu_time, recorded_call_count, call_count, package/uid):");
		List<UidEntry> summaryEntries = verbose ? entries
		: getHighestValues(entries, value -> value.cpuTimeMicros, 0.9);
		for (UidEntry entry : summaryEntries) {
		String uidStr = uidToString(entry.uid, appIdToPkgNameMap);
		pw.println(String.format(" %10d %3.0f%% %8d %3d %s",
		entry.cpuTimeMicros, 100d * entry.cpuTimeMicros / totalCpuTime, entry.callCount,
		entry.exceptionCount, uidStr));
		pw.println(String.format(" %10d %3.0f%% %8d %8d %s",
		entry.cpuTimeMicros, 100d * entry.cpuTimeMicros / totalCpuTime,
		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 / totalCallsCount));
		totalCpuTime, totalCallsCount, (double)totalCpuTime / totalRecordedCallsCount));
		pw.println();

		pw.println("Exceptions thrown (exception_count, class_name):");
		@@ -345,6 +310,11 @@ public class BinderCallsStats {
		for (Pair<String, Integer> entry : exceptionEntries) {
		pw.println(String.format(" %6d %s", entry.second, entry.first));
		}

		if (!mDetailedTracking && mPeriodicSamplingInterval != 1) {
		pw.println("");
		pw.println("/!\\ Displayed data is sampled. See sampling interval at the top.");
		}
		}

		private static String uidToString(int uid, Map<Integer, String> pkgNameMap) {
		@@ -366,6 +336,10 @@ public class BinderCallsStats {
		return SystemClock.elapsedRealtimeNanos() / 1000;
		}

		private boolean shouldTrackCall() {
		return mRandom.nextInt() % mPeriodicSamplingInterval == 0;
		}

		public static BinderCallsStats getInstance() {
		return sInstance;
		}
		@@ -401,7 +375,6 @@ public class BinderCallsStats {
		synchronized (mLock) {
		mUidEntries.clear();
		mExceptionCounts.clear();
		mSampledEntries.mCallStats.clear();
		mStartTime = System.currentTimeMillis();
		}
		}
		@@ -418,6 +391,7 @@ public class BinderCallsStats {
		public long latencyMicros;
		public long maxLatencyMicros;
		public long callCount;
		public long recordedCallCount;
		public long maxRequestSizeBytes;
		public long maxReplySizeBytes;
		public long exceptionCount;
		@@ -430,11 +404,21 @@ public class BinderCallsStats {
		// Method name might be null when we cannot resolve the transaction code. For instance, if
		// the binder was not generated by AIDL.
		public @Nullable String methodName;
		// 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;
		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;
		public long callCount;
		// The following fields are only computed if mDetailedTracking is set.
		public long maxRequestSizeBytes;
		public long maxReplySizeBytes;
		@@ -455,7 +439,6 @@ public class BinderCallsStats {
		}

		CallStat callStat = (CallStat) o;

		return msg == callStat.msg && (className.equals(callStat.className));
		}

		@@ -477,15 +460,20 @@ public class BinderCallsStats {
		long timeStarted;
		boolean exceptionThrown;
		final CallStat callStat = new CallStat();
		CallStat sampledCallStat;
		}

		@VisibleForTesting
		public static class UidEntry {
		int uid;
		public long cpuTimeMicros;
		// 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;
		public int exceptionCount;
		// Total CPU of all for all the recorded calls.
		// Approximate total CPU usage can be computed by
		// cpuTimeMicros * callCount / recordedCallCount
		public long cpuTimeMicros;

		UidEntry(int uid) {
		this.uid = uid;
		@@ -550,11 +538,6 @@ public class BinderCallsStats {
		return mUidEntries;
		}

		@VisibleForTesting
		public UidEntry getSampledEntries() {
		return mSampledEntries;
		}

		@VisibleForTesting
		public ArrayMap<String, Integer> getExceptionCounts() {
		return mExceptionCounts;

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

+73 −35

Original line number	Diff line number	Diff line
		@@ -33,6 +33,7 @@ import java.util.Arrays;
		import java.util.HashMap;
		import java.util.List;
		import java.util.Map;
		import java.util.Random;

		import static org.junit.Assert.assertEquals;

		@@ -48,6 +49,7 @@ public class BinderCallsStatsTest {
		public void testDetailedOff() {
		TestBinderCallsStats bcs = new TestBinderCallsStats();
		bcs.setDetailedTracking(false);
		bcs.setSamplingInterval(5);

		Binder binder = new Binder();
		BinderCallsStats.CallSession callSession = bcs.callStarted(binder, 1);
		@@ -58,44 +60,31 @@ public class BinderCallsStatsTest {
		assertEquals(1, uidEntries.size());
		BinderCallsStats.UidEntry uidEntry = uidEntries.get(TEST_UID);
		Assert.assertNotNull(uidEntry);
		List<BinderCallsStats.CallStat> callStatsList = uidEntry.getCallStatsList();
		assertEquals(1, uidEntry.callCount);
		assertEquals(1, uidEntry.recordedCallCount);
		assertEquals(10, uidEntry.cpuTimeMicros);
		assertEquals("Detailed tracking off - no entries should be returned",
		0, uidEntry.getCallStatsList().size());

		BinderCallsStats.UidEntry sampledEntries = bcs.getSampledEntries();
		List<BinderCallsStats.CallStat> sampledCallStatsList = sampledEntries.getCallStatsList();
		assertEquals(1, sampledCallStatsList.size());


		assertEquals(1, sampledCallStatsList.get(0).callCount);
		assertEquals(10, sampledCallStatsList.get(0).cpuTimeMicros);
		assertEquals(binder.getClass().getName(), sampledCallStatsList.get(0).className);
		assertEquals(1, sampledCallStatsList.get(0).msg);
		assertEquals(binder.getClass().getName(), callStatsList.get(0).className);
		assertEquals(1, callStatsList.get(0).msg);

		// CPU usage is sampled, should not be tracked here.
		callSession = bcs.callStarted(binder, 1);
		bcs.time += 20;
		bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE);

		uidEntry = bcs.getUidEntries().get(TEST_UID);
		assertEquals(2, uidEntry.callCount);
		// When sampling is enabled, cpu time is only measured for the first transaction in the
		// sampling interval, for others an average duration of previous transactions is used as
		// approximation
		assertEquals(20, uidEntry.cpuTimeMicros);
		sampledCallStatsList = sampledEntries.getCallStatsList();
		assertEquals(1, sampledCallStatsList.size());
		assertEquals(1, uidEntry.recordedCallCount);
		assertEquals(10, uidEntry.cpuTimeMicros);
		assertEquals(1, callStatsList.size());

		callSession = bcs.callStarted(binder, 2);
		bcs.time += 50;
		bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE);
		uidEntry = bcs.getUidEntries().get(TEST_UID);
		assertEquals(3, uidEntry.callCount);

		// This is the first transaction of a new type, so the real CPU time will be measured
		assertEquals(70, uidEntry.cpuTimeMicros);
		sampledCallStatsList = sampledEntries.getCallStatsList();
		assertEquals(2, sampledCallStatsList.size());
		assertEquals(1, uidEntry.recordedCallCount);
		// Still sampled even for another API.
		callStatsList = uidEntry.getCallStatsList();
		assertEquals(2, callStatsList.size());
		}

		@Test
		@@ -116,10 +105,6 @@ public class BinderCallsStatsTest {
		assertEquals(10, uidEntry.cpuTimeMicros);
		assertEquals(1, uidEntry.getCallStatsList().size());

		BinderCallsStats.UidEntry sampledEntries = bcs.getSampledEntries();
		assertEquals("Sampling is not used when detailed tracking on",
		0, bcs.getSampledEntries().getCallStatsList().size());

		List<BinderCallsStats.CallStat> callStatsList = uidEntry.getCallStatsList();
		assertEquals(1, callStatsList.get(0).callCount);
		assertEquals(10, callStatsList.get(0).cpuTimeMicros);
		@@ -216,13 +201,57 @@ public class BinderCallsStatsTest {
		BinderCallsStats.UidEntry uidEntry = uidEntries.get(TEST_UID);
		Assert.assertNotNull(uidEntry);
		assertEquals(3, uidEntry.callCount);
		assertEquals(70, uidEntry.cpuTimeMicros);
		assertEquals("Detailed tracking off - no entries should be returned",
		0, uidEntry.getCallStatsList().size());
		assertEquals(60 /* 10 + 50 */, uidEntry.cpuTimeMicros);

		List<BinderCallsStats.CallStat> callStatsList = uidEntry.getCallStatsList();
		assertEquals(1, callStatsList.size());
		BinderCallsStats.CallStat callStats = callStatsList.get(0);
		assertEquals(3, callStats.callCount);
		assertEquals(2, callStats.recordedCallCount);
		assertEquals(60, callStats.cpuTimeMicros);
		assertEquals(50, callStats.maxCpuTimeMicros);
		assertEquals(0, callStats.maxRequestSizeBytes);
		assertEquals(0, callStats.maxReplySizeBytes);
		}

		@Test
		public void testSamplingWithDifferentApis() {
		TestBinderCallsStats bcs = new TestBinderCallsStats();
		bcs.setDetailedTracking(false);
		bcs.setSamplingInterval(2);

		Binder binder = new Binder();
		BinderCallsStats.CallSession callSession = bcs.callStarted(binder, 1);
		bcs.time += 10;
		bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE);

		callSession = bcs.callStarted(binder, 2 /* another method */);
		bcs.time += 1000; // shoud be ignored.
		bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE);


		BinderCallsStats.UidEntry sampledEntries = bcs.getSampledEntries();
		List<BinderCallsStats.CallStat> sampledCallStatsList = sampledEntries.getCallStatsList();
		assertEquals(1, sampledCallStatsList.size());
		SparseArray<BinderCallsStats.UidEntry> uidEntries = bcs.getUidEntries();
		assertEquals(1, uidEntries.size());
		BinderCallsStats.UidEntry uidEntry = uidEntries.get(TEST_UID);
		assertEquals(2, uidEntry.callCount);
		assertEquals(1, uidEntry.recordedCallCount);
		assertEquals(10, uidEntry.cpuTimeMicros);

		List<BinderCallsStats.CallStat> callStatsList = uidEntry.getCallStatsList();
		assertEquals(2, callStatsList.size());

		BinderCallsStats.CallStat callStats = callStatsList.get(0);
		assertEquals(1, callStats.callCount);
		assertEquals(1, callStats.recordedCallCount);
		assertEquals(10, callStats.cpuTimeMicros);
		assertEquals(10, callStats.maxCpuTimeMicros);

		// Only call count should is tracked, rest is sampled.
		callStats = callStatsList.get(1);
		assertEquals(1, callStats.callCount);
		assertEquals(0, callStats.recordedCallCount);
		assertEquals(0, callStats.cpuTimeMicros);
		assertEquals(0, callStats.maxCpuTimeMicros);
		}

		@Test
		@@ -374,6 +403,7 @@ public class BinderCallsStatsTest {
		assertEquals(20, stat.latencyMicros);
		assertEquals(20, stat.maxLatencyMicros);
		assertEquals(1, stat.callCount);
		assertEquals(1, stat.recordedCallCount);
		assertEquals(REQUEST_SIZE, stat.maxRequestSizeBytes);
		assertEquals(REPLY_SIZE, stat.maxReplySizeBytes);
		assertEquals(0, stat.exceptionCount);
		@@ -385,6 +415,14 @@ public class BinderCallsStatsTest {
		long elapsedTime = 0;

		TestBinderCallsStats() {
		// Make random generator not random.
		super(new Random() {
		int mCallCount = 0;

		public int nextInt() {
		return mCallCount++;
		}
		});
		}

		@Override