diff --git a/core/java/com/android/internal/os/BinderLatencyObserver.java b/core/java/com/android/internal/os/BinderLatencyObserver.java index 59cc66d79bceb..4ca59be4877a5 100644 --- a/core/java/com/android/internal/os/BinderLatencyObserver.java +++ b/core/java/com/android/internal/os/BinderLatencyObserver.java @@ -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 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 getLatencyHistograms() { return mLatencyHistograms; } + + @VisibleForTesting + public Runnable getStatsdPushRunnable() { + return mLatencyObserverRunnable; + } } diff --git a/core/proto/android/internal/binder_latency.proto b/core/proto/android/internal/binder_latency.proto new file mode 100644 index 0000000000000..e32c3e3441c5f --- /dev/null +++ b/core/proto/android/internal/binder_latency.proto @@ -0,0 +1,77 @@ +/* + * 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 diff --git a/core/tests/coretests/src/com/android/internal/os/BinderLatencyObserverTest.java b/core/tests/coretests/src/com/android/internal/os/BinderLatencyObserverTest.java index f65fb9583d6ca..bf87683593e7a 100644 --- a/core/tests/coretests/src/com/android/internal/os/BinderLatencyObserverTest.java +++ b/core/tests/coretests/src/com/android/internal/os/BinderLatencyObserverTest.java @@ -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 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 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 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 getWrittenAtoms() { + return mWrittenAtoms; + } } } diff --git a/services/core/java/com/android/server/BinderCallsStatsService.java b/services/core/java/com/android/server/BinderCallsStatsService.java index c49b8e8e77c62..78610a2857bdc 100644 --- a/services/core/java/com/android/server/BinderCallsStatsService.java +++ b/services/core/java/com/android/server/BinderCallsStatsService.java @@ -138,6 +138,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 = @@ -218,7 +220,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);