Merge "Push the latency histograms to statsd"

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<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,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;
+}

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<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

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