Merge "Push the latency histograms to statsd" am: d5dd055c7e (b282f513) · Commits · e / os / android_frameworks_base

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

+143 −1

Original line number	Diff line number	Diff line
		@@ -16,22 +16,37 @@

		package com.android.internal.os;

		import static com.android.internal.os.BinderLatencyProto.Dims.SYSTEM_SERVER;

		import android.annotation.Nullable;
		import android.os.Binder;
		import android.os.Handler;
		import android.os.Looper;
		import android.os.SystemClock;
		import android.util.ArrayMap;
		import android.util.Slog;
		import android.util.proto.ProtoOutputStream;

		import com.android.internal.annotations.GuardedBy;
		import com.android.internal.annotations.VisibleForTesting;
		import com.android.internal.os.BinderInternal.CallSession;
		import com.android.internal.os.BinderLatencyProto.ApiStats;
		import com.android.internal.os.BinderLatencyProto.Dims;
		import com.android.internal.os.BinderLatencyProto.RepeatedApiStats;
		import com.android.internal.util.FrameworkStatsLog;

		import java.util.Random;

		/** Collects statistics about Binder call latency per calling API and method. */
		public class BinderLatencyObserver {
		private static final String TAG = "BinderLatencyObserver";
		private static final int MAX_ATOM_SIZE_BYTES = 4064;
		// Be conservative and leave 1K space for the last histogram so we don't go over the size limit.
		private static final int LAST_HISTOGRAM_BUFFER_SIZE_BYTES = 1000;

		// Latency observer parameters.
		public static final int PERIODIC_SAMPLING_INTERVAL_DEFAULT = 10;
		public static final int STATSD_PUSH_INTERVAL_MINUTES_DEFAULT = 360;

		// Histogram buckets parameters.
		public static final int BUCKET_COUNT_DEFAULT = 100;
		@@ -50,20 +65,124 @@ public class BinderLatencyObserver {
		private int mFirstBucketSize = FIRST_BUCKET_SIZE_DEFAULT;
		private float mBucketScaleFactor = BUCKET_SCALE_FACTOR_DEFAULT;

		private int mStatsdPushIntervalMinutes = STATSD_PUSH_INTERVAL_MINUTES_DEFAULT;

		private final Random mRandom;
		private BinderLatencyBuckets mLatencyBuckets;

		private final Handler mLatencyObserverHandler;

		private Runnable mLatencyObserverRunnable = new Runnable() {
		@Override
		public void run() {
		// Schedule the next push.
		noteLatencyDelayed();

		ArrayMap<LatencyDims, int[]> histogramMap;
		synchronized (mLock) {
		// Copy the histograms map so we don't use the lock for longer than needed.
		histogramMap = new ArrayMap<>(mLatencyHistograms);
		mLatencyHistograms.clear();
		}

		BinderTransactionNameResolver resolver = new BinderTransactionNameResolver();
		ProtoOutputStream proto = new ProtoOutputStream();
		int histogramsWritten = 0;

		for (LatencyDims dims : histogramMap.keySet()) {
		// Start a new atom if the next histogram risks going over the atom size limit.
		if (proto.getRawSize() + LAST_HISTOGRAM_BUFFER_SIZE_BYTES > getMaxAtomSizeBytes()) {
		if (histogramsWritten > 0) {
		writeAtomToStatsd(proto);
		}
		proto = new ProtoOutputStream();
		histogramsWritten = 0;
		}

		String transactionName = resolver.getMethodName(
		dims.getBinderClass(), dims.getTransactionCode());
		fillApiStatsProto(proto, dims, transactionName, histogramMap.get(dims));
		histogramsWritten++;
		}
		// Push the final atom.
		if (histogramsWritten > 0) {
		writeAtomToStatsd(proto);
		}
		}
		};

		private void fillApiStatsProto(
		ProtoOutputStream proto, LatencyDims dims, String transactionName, int[] histogram) {
		// Find the part of the histogram to write.
		int firstNonEmptyBucket = 0;
		for (int i = 0; i < mBucketCount; i++) {
		if (histogram[i] != 0) {
		firstNonEmptyBucket = i;
		break;
		}
		}
		int lastNonEmptyBucket = mBucketCount - 1;
		for (int i = mBucketCount - 1; i >= 0; i--) {
		if (histogram[i] != 0) {
		lastNonEmptyBucket = i;
		break;
		}
		}

		// Start a new ApiStats proto.
		long apiStatsToken = proto.start(RepeatedApiStats.API_STATS);

		// Write the dims.
		long dimsToken = proto.start(ApiStats.DIMS);
		proto.write(Dims.PROCESS_SOURCE, SYSTEM_SERVER);
		proto.write(Dims.SERVICE_CLASS_NAME, dims.getBinderClass().getName());
		proto.write(Dims.SERVICE_METHOD_NAME, transactionName);
		proto.end(dimsToken);

		// Write the histogram.
		proto.write(ApiStats.FIRST_BUCKET_INDEX, firstNonEmptyBucket);
		for (int i = firstNonEmptyBucket; i <= lastNonEmptyBucket; i++) {
		proto.write(ApiStats.BUCKETS, histogram[i]);
		}

		proto.end(apiStatsToken);
		}

		protected int getMaxAtomSizeBytes() {
		return MAX_ATOM_SIZE_BYTES;
		}

		protected void writeAtomToStatsd(ProtoOutputStream atom) {
		FrameworkStatsLog.write(
		FrameworkStatsLog.BINDER_LATENCY_REPORTED,
		atom.getBytes(),
		mPeriodicSamplingInterval,
		1);
		}

		private void noteLatencyDelayed() {
		mLatencyObserverHandler.removeCallbacks(mLatencyObserverRunnable);
		mLatencyObserverHandler.postDelayed(mLatencyObserverRunnable,
		mStatsdPushIntervalMinutes * 60 * 1000);
		}

		/** Injector for {@link BinderLatencyObserver}. */
		public static class Injector {
		public Random getRandomGenerator() {
		return new Random();
		}

		public Handler getHandler() {
		return new Handler(Looper.getMainLooper());
		}
		}

		public BinderLatencyObserver(Injector injector) {
		mRandom = injector.getRandomGenerator();
		mLatencyObserverHandler = injector.getHandler();
		mLatencyBuckets = new BinderLatencyBuckets(
		mBucketCount, mFirstBucketSize, mBucketScaleFactor);
		noteLatencyDelayed();
		}

		/** Should be called when a Binder call completes, will store latency data. */
		@@ -73,7 +192,8 @@ public class BinderLatencyObserver {
		}

		LatencyDims dims = new LatencyDims(s.binderClass, s.transactionCode);
		long callDuration = getElapsedRealtimeMicro() - s.timeStarted;
		long elapsedTimeMicro = getElapsedRealtimeMicro();
		long callDuration = elapsedTimeMicro - s.timeStarted;

		// Find the bucket this sample should go to.
		int bucketIdx = mLatencyBuckets.sampleToBucket(
		@@ -117,6 +237,22 @@ public class BinderLatencyObserver {
		}
		}

		/** Updates the statsd push interval. */
		public void setPushInterval(int pushIntervalMinutes) {
		if (pushIntervalMinutes <= 0) {
		Slog.w(TAG, "Ignored invalid push interval (value must be positive): "
		+ pushIntervalMinutes);
		return;
		}

		synchronized (mLock) {
		if (pushIntervalMinutes != mStatsdPushIntervalMinutes) {
		mStatsdPushIntervalMinutes = pushIntervalMinutes;
		reset();
		}
		}
		}

		/** Updates the histogram buckets parameters. */
		public void setHistogramBucketsParams(
		int bucketCount, int firstBucketSize, float bucketScaleFactor) {
		@@ -138,6 +274,7 @@ public class BinderLatencyObserver {
		synchronized (mLock) {
		mLatencyHistograms.clear();
		}
		noteLatencyDelayed();
		}

		/** Container for binder latency information. */
		@@ -187,4 +324,9 @@ public class BinderLatencyObserver {
		public ArrayMap<LatencyDims, int[]> getLatencyHistograms() {
		return mLatencyHistograms;
		}

		@VisibleForTesting
		public Runnable getStatsdPushRunnable() {
		return mLatencyObserverRunnable;
		}
		}

core/proto/android/internal/binder_latency.proto

0 → 100644

+77 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2021 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.
		*/

		syntax = "proto2";
		package com.android.internal.os;

		option java_outer_classname = "BinderLatencyProto";

		/**
		* RepeatedApiStats proto from atoms.proto, duplicated here so that it's
		* accessible in the build.
		* Must be kept in sync with the version in atoms.proto.
		*/

		message RepeatedApiStats {
		repeated ApiStats api_stats = 1;
		}

		message Dims {
		enum ProcessSource {
		UNKNOWN_PROCESS_SOURCE = 0;
		SYSTEM_SERVER = 1;
		TELEPHONY = 2;
		}

		enum ServiceClassName {
		UNKNOWN_CLASS = 0;
		}
		enum ServiceMethodName {
		UNKNOWN_METHOD = 0;
		}

		// Required.
		optional ProcessSource process_source = 1;

		// The class name of the API making the call to Binder. Enum value
		// is preferred as uses much less data to store.
		// This field does not contain PII.
		oneof service_class {
		ServiceClassName service_class_name_as_enum = 2;
		string service_class_name = 3;
		}

		// Method name of the API call. It can also be a transaction code if we
		// cannot resolve it to a name. See Binder#getTransactionName. Enum value
		// is preferred as uses much less data to store.
		// This field does not contain PII.
		oneof service_method {
		ServiceMethodName service_method_name_as_enum = 4;
		string service_method_name = 5;
		}
		}

		message ApiStats {
		// required.
		optional Dims dims = 1;

		// Indicates the first bucket that had any data. Allows omitting any empty
		// buckets at the start of the bucket list and thus save on data size.
		optional int32 first_bucket_index = 2;
		// Stores the count of samples for each bucket. The number of buckets and
		// their sizes are controlled server side with a flag.
		repeated int32 buckets = 3;
		}
		No newline at end of file

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

+129 −2

Original line number	Diff line number	Diff line
		@@ -16,6 +16,8 @@

		package com.android.internal.os;

		import static com.android.internal.os.BinderLatencyProto.Dims.SYSTEM_SERVER;

		import static com.google.common.truth.Truth.assertThat;

		import static org.junit.Assert.assertEquals;
		@@ -23,16 +25,21 @@ import static org.junit.Assert.assertEquals;
		import android.os.Binder;
		import android.platform.test.annotations.Presubmit;
		import android.util.ArrayMap;
		import android.util.proto.ProtoOutputStream;

		import androidx.test.filters.SmallTest;
		import androidx.test.runner.AndroidJUnit4;

		import com.android.internal.os.BinderInternal.CallSession;
		import com.android.internal.os.BinderLatencyObserver.LatencyDims;
		import com.android.internal.os.BinderLatencyProto.ApiStats;
		import com.android.internal.os.BinderLatencyProto.Dims;
		import com.android.internal.os.BinderLatencyProto.RepeatedApiStats;

		import org.junit.Test;
		import org.junit.runner.RunWith;

		import java.util.ArrayList;
		import java.util.Arrays;
		import java.util.Random;

		@@ -49,11 +56,17 @@ public class BinderLatencyObserverTest {
		CallSession callSession = new CallSession();
		callSession.binderClass = binder.getClass();
		callSession.transactionCode = 1;

		blo.setElapsedTime(2);
		blo.callEnded(callSession);
		blo.setElapsedTime(4);
		blo.callEnded(callSession);
		blo.setElapsedTime(6);
		blo.callEnded(callSession);
		callSession.transactionCode = 2;
		blo.setElapsedTime(8);
		blo.callEnded(callSession);
		blo.setElapsedTime(10);
		blo.callEnded(callSession);

		ArrayMap<LatencyDims, int[]> latencyHistograms = blo.getLatencyHistograms();
		@@ -74,8 +87,10 @@ public class BinderLatencyObserverTest {
		CallSession callSession = new CallSession();
		callSession.binderClass = binder.getClass();
		callSession.transactionCode = 1;
		blo.setElapsedTime(2);
		blo.callEnded(callSession);
		callSession.transactionCode = 2;
		blo.setElapsedTime(4);
		blo.callEnded(callSession);

		ArrayMap<LatencyDims, int[]> latencyHistograms = blo.getLatencyHistograms();
		@@ -89,13 +104,13 @@ public class BinderLatencyObserverTest {
		@Test
		public void testTooCallLengthOverflow() {
		TestBinderLatencyObserver blo = new TestBinderLatencyObserver();
		blo.setElapsedTime(2L + (long) Integer.MAX_VALUE);
		blo.setHistogramBucketsParams(5, 5, 1.125f);

		Binder binder = new Binder();
		CallSession callSession = new CallSession();
		callSession.binderClass = binder.getClass();
		callSession.transactionCode = 1;
		blo.setElapsedTime(2L + (long) Integer.MAX_VALUE);
		blo.callEnded(callSession);

		// The long call should be capped to maxint (to not overflow) and placed in the last bucket.
		@@ -114,6 +129,7 @@ public class BinderLatencyObserverTest {
		CallSession callSession = new CallSession();
		callSession.binderClass = binder.getClass();
		callSession.transactionCode = 1;
		blo.setElapsedTime(2);
		blo.callEnded(callSession);

		LatencyDims dims = new LatencyDims(binder.getClass(), 1);
		@@ -122,14 +138,111 @@ public class BinderLatencyObserverTest {
		assertThat(blo.getLatencyHistograms().get(dims))
		.asList().containsExactly(Integer.MAX_VALUE, Integer.MAX_VALUE, Integer.MAX_VALUE);
		// Try to add another sample.
		blo.setElapsedTime(2);
		blo.callEnded(callSession);
		// Make sure the buckets don't overflow.
		assertThat(blo.getLatencyHistograms().get(dims))
		.asList().containsExactly(Integer.MAX_VALUE, Integer.MAX_VALUE, Integer.MAX_VALUE);
		}

		@Test
		public void testSingleAtomPush() {
		TestBinderLatencyObserver blo = new TestBinderLatencyObserver();

		Binder binder = new Binder();
		CallSession callSession = new CallSession();
		callSession.binderClass = binder.getClass();
		callSession.transactionCode = 1;
		blo.setElapsedTime(7);
		blo.callEnded(callSession);
		blo.callEnded(callSession);
		blo.setElapsedTime(8);
		blo.callEnded(callSession);

		// Trigger the statsd push.
		blo.getStatsdPushRunnable().run();

		ProtoOutputStream expectedProto = new ProtoOutputStream();
		long apiStatsToken = expectedProto.start(RepeatedApiStats.API_STATS);
		long dimsToken = expectedProto.start(ApiStats.DIMS);
		expectedProto.write(Dims.PROCESS_SOURCE, SYSTEM_SERVER);
		expectedProto.write(Dims.SERVICE_CLASS_NAME, binder.getClass().getName());
		expectedProto.write(Dims.SERVICE_METHOD_NAME, "1");
		expectedProto.end(dimsToken);
		expectedProto.write(ApiStats.FIRST_BUCKET_INDEX, 3);
		expectedProto.write(ApiStats.BUCKETS, 2);
		expectedProto.write(ApiStats.BUCKETS, 1);
		expectedProto.end(apiStatsToken);

		assertThat(blo.getWrittenAtoms())
		.containsExactly(Arrays.toString(expectedProto.getBytes()));
		}

		@Test
		public void testMultipleAtomPush() {
		TestBinderLatencyObserver blo = new TestBinderLatencyObserver();

		BinderTransactionNameResolver resolver = new BinderTransactionNameResolver();


		Binder binder = new Binder();
		CallSession callSession = new CallSession();
		callSession.binderClass = binder.getClass();
		callSession.transactionCode = 1;
		blo.setElapsedTime(1);
		blo.callEnded(callSession);
		callSession.transactionCode = 2;
		blo.setElapsedTime(5);
		blo.callEnded(callSession);
		callSession.transactionCode = 3;
		blo.callEnded(callSession);

		// Trigger the statsd push.
		blo.getStatsdPushRunnable().run();

		ProtoOutputStream expectedProto1 = new ProtoOutputStream();
		long apiStatsToken = expectedProto1.start(RepeatedApiStats.API_STATS);
		long dimsToken = expectedProto1.start(ApiStats.DIMS);
		expectedProto1.write(Dims.PROCESS_SOURCE, SYSTEM_SERVER);
		expectedProto1.write(Dims.SERVICE_CLASS_NAME, binder.getClass().getName());
		expectedProto1.write(Dims.SERVICE_METHOD_NAME, "1");
		expectedProto1.end(dimsToken);
		expectedProto1.write(ApiStats.FIRST_BUCKET_INDEX, 0);
		expectedProto1.write(ApiStats.BUCKETS, 1);
		expectedProto1.end(apiStatsToken);

		apiStatsToken = expectedProto1.start(RepeatedApiStats.API_STATS);
		dimsToken = expectedProto1.start(ApiStats.DIMS);
		expectedProto1.write(Dims.PROCESS_SOURCE, SYSTEM_SERVER);
		expectedProto1.write(Dims.SERVICE_CLASS_NAME, binder.getClass().getName());
		expectedProto1.write(Dims.SERVICE_METHOD_NAME, "2");
		expectedProto1.end(dimsToken);
		expectedProto1.write(ApiStats.FIRST_BUCKET_INDEX, 1);
		expectedProto1.write(ApiStats.BUCKETS, 1);
		expectedProto1.end(apiStatsToken);

		ProtoOutputStream expectedProto2 = new ProtoOutputStream();
		apiStatsToken = expectedProto2.start(RepeatedApiStats.API_STATS);
		dimsToken = expectedProto2.start(ApiStats.DIMS);
		expectedProto2.write(Dims.PROCESS_SOURCE, SYSTEM_SERVER);
		expectedProto2.write(Dims.SERVICE_CLASS_NAME, binder.getClass().getName());
		expectedProto2.write(Dims.SERVICE_METHOD_NAME, "3");
		expectedProto2.end(dimsToken);
		expectedProto2.write(ApiStats.FIRST_BUCKET_INDEX, 1);
		expectedProto2.write(ApiStats.BUCKETS, 1);
		expectedProto2.end(apiStatsToken);

		// Each ApiStats is around ~60 bytes so only two should fit in an atom.
		assertThat(blo.getWrittenAtoms())
		.containsExactly(
		Arrays.toString(expectedProto1.getBytes()),
		Arrays.toString(expectedProto2.getBytes()))
		.inOrder();
		}

		public static class TestBinderLatencyObserver extends BinderLatencyObserver {
		private long mElapsedTime = 0;
		private ArrayList<String> mWrittenAtoms;

		TestBinderLatencyObserver() {
		// Make random generator not random.
		@@ -145,16 +258,30 @@ public class BinderLatencyObserverTest {
		}
		});
		setSamplingInterval(1);
		mWrittenAtoms = new ArrayList<>();
		}

		@Override
		protected long getElapsedRealtimeMicro() {
		mElapsedTime += 2;
		return mElapsedTime;
		}

		@Override
		protected int getMaxAtomSizeBytes() {
		return 1100;
		}

		@Override
		protected void writeAtomToStatsd(ProtoOutputStream atom) {
		mWrittenAtoms.add(Arrays.toString(atom.getBytes()));
		}

		public void setElapsedTime(long time) {
		mElapsedTime = time;
		}

		public ArrayList<String> getWrittenAtoms() {
		return mWrittenAtoms;
		}
		}
		}

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

+5 −1

Original line number	Diff line number	Diff line
		@@ -134,6 +134,8 @@ public class BinderCallsStatsService extends Binder {
		private static final String SETTINGS_COLLECT_LATENCY_DATA_KEY = "collect_Latency_data";
		private static final String SETTINGS_LATENCY_OBSERVER_SAMPLING_INTERVAL_KEY =
		"latency_observer_sampling_interval";
		private static final String SETTINGS_LATENCY_OBSERVER_PUSH_INTERVAL_MINUTES_KEY =
		"latency_observer_push_interval_minutes";
		private static final String SETTINGS_LATENCY_HISTOGRAM_BUCKET_COUNT_KEY =
		"latency_histogram_bucket_count";
		private static final String SETTINGS_LATENCY_HISTOGRAM_FIRST_BUCKET_SIZE_KEY =
		@@ -211,7 +213,9 @@ public class BinderCallsStatsService extends Binder {
		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));

		final boolean enabled =
		mParser.getBoolean(SETTINGS_ENABLED_KEY, BinderCallsStats.ENABLED_DEFAULT);