Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit a28ccaf3 authored by Siim Sammul's avatar Siim Sammul
Browse files

Push the latency histograms to statsd 

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

Change-Id: I0b8db72c0cb3b285177bbe402ce37639c468dbf3
parent 5a85ba2e

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