Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Push the latency histograms to statsd

Browse Source 
Cherry pick from master with no changes

Test: unit tests, verified atom logging with statsd_testdrive
Bug: 180584913

Change-Id: I0b8db72c0cb3b285177bbe402ce37639c468dbf3
Merged-In: I0b8db72c0cb3b285177bbe402ce37639c468dbf3
(cherry picked from commit a28ccaf373)
This commit is contained in:
Siim Sammul
2021-03-09 17:24:29 +00:00
parent fcfa35e119
commit 100497084a
4 changed files with 354 additions and 4 deletions
Download Patch File Download Diff File Expand all files Collapse all files

144
core/java/com/android/internal/os/BinderLatencyObserver.java
View File

@@ -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;
}
}

77
core/proto/android/internal/binder_latency.proto Normal file
View File

@@ -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;
}

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

@@ -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;
}
}
}

6
services/core/java/com/android/server/BinderCallsStatsService.java
View File

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