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

Commit 5e6453dc authored by Siim Sammul's avatar Siim Sammul
Browse files

Create BinderLatencyObserver to collect binder call latency stats.

Pushing these as a metric will come in a future change.

This is a direct cherrypick with no changes.

Test: unit tests

Change-Id: I8a123f7aed7c0ce416814372f2287b04a8a04ac0
Merged-In: I8a123f7aed7c0ce416814372f2287b04a8a04ac0
(cherry picked from commit 8d0ecde2)
parent c900ba3c
Loading
Loading
Loading
Loading
+33 −0
Original line number Diff line number Diff line
@@ -54,6 +54,7 @@ public class BinderCallsStats implements BinderInternal.Observer {
    public static final int PERIODIC_SAMPLING_INTERVAL_DEFAULT = 1000;
    public static final boolean DEFAULT_TRACK_SCREEN_INTERACTIVE = false;
    public static final boolean DEFAULT_TRACK_DIRECT_CALLING_UID = true;
    public static final boolean DEFAULT_COLLECT_LATENCY_DATA = false;
    public static final int MAX_BINDER_CALL_STATS_COUNT_DEFAULT = 1500;
    private static final String DEBUG_ENTRY_PREFIX = "__DEBUG_";

@@ -89,19 +90,27 @@ public class BinderCallsStats implements BinderInternal.Observer {
    private boolean mAddDebugEntries = false;
    private boolean mTrackDirectCallingUid = DEFAULT_TRACK_DIRECT_CALLING_UID;
    private boolean mTrackScreenInteractive = DEFAULT_TRACK_SCREEN_INTERACTIVE;
    private boolean mCollectLatencyData = DEFAULT_COLLECT_LATENCY_DATA;

    private CachedDeviceState.Readonly mDeviceState;
    private CachedDeviceState.TimeInStateStopwatch mBatteryStopwatch;

    private BinderLatencyObserver mLatencyObserver;

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

        public BinderLatencyObserver getLatencyObserver() {
            return new BinderLatencyObserver(new BinderLatencyObserver.Injector());
        }
    }

    public BinderCallsStats(Injector injector) {
        this.mRandom = injector.getRandomGenerator();
        this.mLatencyObserver = injector.getLatencyObserver();
    }

    public void setDeviceState(@NonNull CachedDeviceState.Readonly deviceState) {
@@ -128,7 +137,10 @@ public class BinderCallsStats implements BinderInternal.Observer {
        if (shouldRecordDetailedData()) {
            s.cpuTimeStarted = getThreadTimeMicro();
            s.timeStarted = getElapsedRealtimeMicro();
        } else if (mCollectLatencyData) {
            s.timeStarted = getElapsedRealtimeMicro();
        }

        return s;
    }

@@ -153,6 +165,10 @@ public class BinderCallsStats implements BinderInternal.Observer {

    private void processCallEnded(CallSession s,
            int parcelRequestSize, int parcelReplySize, int workSourceUid) {
        if (mCollectLatencyData) {
            mLatencyObserver.callEnded(s);
        }

        // Non-negative time signals we need to record data for this call.
        final boolean recordCall = s.cpuTimeStarted >= 0;
        final long duration;
@@ -555,6 +571,17 @@ public class BinderCallsStats implements BinderInternal.Observer {
        }
    }

    /** Whether to collect latency histograms. */
    public void setCollectLatencyData(boolean collectLatencyData) {
        mCollectLatencyData = collectLatencyData;
    }

    /** Whether to collect latency histograms. */
    @VisibleForTesting
    public boolean getCollectLatencyData() {
        return mCollectLatencyData;
    }

    public void reset() {
        synchronized (mLock) {
            mCallStatsCount = 0;
@@ -565,6 +592,8 @@ public class BinderCallsStats implements BinderInternal.Observer {
            if (mBatteryStopwatch != null) {
                mBatteryStopwatch.reset();
            }
            // Do not reset the latency observer as binder stats and latency will be pushed to
            // statsd at different intervals so the resets should not be coupled.
        }
    }

@@ -767,6 +796,10 @@ public class BinderCallsStats implements BinderInternal.Observer {
        return mExceptionCounts;
    }

    public BinderLatencyObserver getLatencyObserver() {
        return mLatencyObserver;
    }

    @VisibleForTesting
    public static <T> List<T> getHighestValues(List<T> list, ToDoubleFunction<T> toDouble,
            double percentile) {
+157 −0
Original line number Diff line number Diff line
/*
 * Copyright (C) 2017 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.
 */

package com.android.internal.os;

import android.annotation.Nullable;
import android.os.Binder;
import android.os.SystemClock;
import android.util.ArrayMap;
import android.util.Slog;

import com.android.internal.annotations.GuardedBy;
import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.os.BinderInternal.CallSession;

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

/** Collects statistics about Binder call latency per calling API and method. */
public class BinderLatencyObserver {
    private static final String TAG = "BinderLatencyObserver";
    public static final int PERIODIC_SAMPLING_INTERVAL_DEFAULT = 10;

    // This is not the final data structure - we will eventually store latency histograms instead of
    // raw samples as it is much more memory / disk space efficient.
    // TODO(b/179999191): change this to store the histogram.
    // TODO(b/179999191): pre allocate the array size so we would not have to resize this.
    @GuardedBy("mLock")
    private final ArrayMap<LatencyDims, ArrayList<Long>> mLatencySamples = new ArrayMap<>();
    private final Object mLock = new Object();

    // Sampling period to control how often to track CPU usage. 1 means all calls, 100 means ~1 out
    // of 100 requests.
    private int mPeriodicSamplingInterval = PERIODIC_SAMPLING_INTERVAL_DEFAULT;
    private final Random mRandom;

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

    public BinderLatencyObserver(Injector injector) {
        mRandom = injector.getRandomGenerator();
    }

    /** Should be called when a Binder call completes, will store latency data. */
    public void callEnded(@Nullable CallSession s) {
        if (s == null || s.exceptionThrown || !shouldKeepSample()) {
            return;
        }

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

        synchronized (mLock) {
            if (!mLatencySamples.containsKey(dims)) {
                mLatencySamples.put(dims, new ArrayList<Long>());
            }

            mLatencySamples.get(dims).add(callDuration);
        }
    }

    protected long getElapsedRealtimeMicro() {
        return SystemClock.elapsedRealtimeNanos() / 1000;
    }

    protected boolean shouldKeepSample() {
        return mRandom.nextInt() % mPeriodicSamplingInterval == 0;
    }

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

        synchronized (mLock) {
            if (samplingInterval != mPeriodicSamplingInterval) {
                mPeriodicSamplingInterval = samplingInterval;
                reset();
            }
        }
    }

    /** Resets the sample collection. */
    public void reset() {
        synchronized (mLock) {
            mLatencySamples.clear();
        }
    }

    /** Container for binder latency information. */
    public static class LatencyDims {
        // Binder interface descriptor.
        private Class<? extends Binder> mBinderClass;
        // Binder transaction code.
        private int mTransactionCode;
        // Cached hash code, 0 if not set yet.
        private int mHashCode = 0;

        public LatencyDims(Class<? extends Binder> binderClass, int transactionCode) {
            this.mBinderClass = binderClass;
            this.mTransactionCode = transactionCode;
        }

        public Class<? extends Binder> getBinderClass() {
            return mBinderClass;
        }

        public int getTransactionCode() {
            return mTransactionCode;
        }

        @Override
        public boolean equals(final Object other) {
            if (other == null || !(other instanceof LatencyDims)) {
                return false;
            }
            LatencyDims o = (LatencyDims) other;
            return mTransactionCode == o.getTransactionCode() && mBinderClass == o.getBinderClass();
        }

        @Override
        public int hashCode() {
            if (mHashCode != 0) {
                return mHashCode;
            }
            int hash = mTransactionCode;
            hash = 31 * hash + mBinderClass.hashCode();
            mHashCode = hash;
            return hash;
        }
    }

    @VisibleForTesting
    public ArrayMap<LatencyDims, ArrayList<Long>> getLatencySamples() {
        return mLatencySamples;
    }
}
+32 −0
Original line number Diff line number Diff line
@@ -753,6 +753,34 @@ public class BinderCallsStatsTest {
        assertEquals(1, callStats.recordedCallCount);
    }

    @Test
    public void testLatencyCollectionEnabled() {
        TestBinderCallsStats bcs = new TestBinderCallsStats();
        bcs.setCollectLatencyData(true);

        Binder binder = new Binder();
        CallSession callSession = bcs.callStarted(binder, 1, WORKSOURCE_UID);
        bcs.time += 10;
        bcs.elapsedTime += 20;
        bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE, WORKSOURCE_UID);

        assertEquals(1, bcs.getLatencyObserver().getLatencySamples().size());
    }

    @Test
    public void testLatencyCollectionDisabledByDefault() {
        TestBinderCallsStats bcs = new TestBinderCallsStats();
        assertEquals(false, bcs.getCollectLatencyData());

        Binder binder = new Binder();
        CallSession callSession = bcs.callStarted(binder, 1, WORKSOURCE_UID);
        bcs.time += 10;
        bcs.elapsedTime += 20;
        bcs.callEnded(callSession, REQUEST_SIZE, REPLY_SIZE, WORKSOURCE_UID);

        assertEquals(0, bcs.getLatencyObserver().getLatencySamples().size());
    }

    class TestBinderCallsStats extends BinderCallsStats {
        public int callingUid = CALLING_UID;
        public long time = 1234;
@@ -774,6 +802,10 @@ public class BinderCallsStatsTest {
                        }
                    };
                }

                public BinderLatencyObserver getLatencyObserver() {
                    return new BinderLatencyObserverTest.TestBinderLatencyObserver();
                }
            });
            setSamplingInterval(1);
            setAddDebugEntries(false);
+110 −0
Original line number Diff line number Diff line
/*
 * Copyright (C) 2018 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.
 */

package com.android.internal.os;

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

import static org.junit.Assert.assertEquals;

import android.os.Binder;
import android.platform.test.annotations.Presubmit;
import android.util.ArrayMap;

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 org.junit.Test;
import org.junit.runner.RunWith;

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

@SmallTest
@RunWith(AndroidJUnit4.class)
@Presubmit
public class BinderLatencyObserverTest {
    @Test
    public void testLatencyCollectionWithMultipleClasses() {
        TestBinderLatencyObserver blo = new TestBinderLatencyObserver();

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

        ArrayMap<LatencyDims, ArrayList<Long>> latencySamples = blo.getLatencySamples();
        assertEquals(2, latencySamples.keySet().size());
        assertThat(latencySamples.get(new LatencyDims(binder.getClass(), 1)))
            .containsExactlyElementsIn(Arrays.asList(1L, 2L));
        assertThat(latencySamples.get(new LatencyDims(binder.getClass(), 2))).containsExactly(3L);
    }

    @Test
    public void testSampling() {
        TestBinderLatencyObserver blo = new TestBinderLatencyObserver();
        blo.setSamplingInterval(2);

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

        ArrayMap<LatencyDims, ArrayList<Long>> latencySamples = blo.getLatencySamples();
        assertEquals(1, latencySamples.size());
        LatencyDims dims = latencySamples.keySet().iterator().next();
        assertEquals(binder.getClass(), dims.getBinderClass());
        assertEquals(1, dims.getTransactionCode());
        ArrayList<Long> values = latencySamples.get(dims);
        assertThat(values).containsExactly(1L);
    }

    public static class TestBinderLatencyObserver extends BinderLatencyObserver {
        private long mElapsedTimeCallCount = 0;

        TestBinderLatencyObserver() {
            // Make random generator not random.
            super(new Injector() {
                public Random getRandomGenerator() {
                    return new Random() {
                        int mCallCount = 0;

                        public int nextInt() {
                            return mCallCount++;
                        }
                    };
                }
            });
            setSamplingInterval(1);
        }

        @Override
        protected long getElapsedRealtimeMicro() {
            return ++mElapsedTimeCallCount;
        }
    }
}
+14 −0
Original line number Diff line number Diff line
@@ -40,6 +40,7 @@ import com.android.internal.os.AppIdToPackageMap;
import com.android.internal.os.BackgroundThread;
import com.android.internal.os.BinderCallsStats;
import com.android.internal.os.BinderInternal;
import com.android.internal.os.BinderLatencyObserver;
import com.android.internal.os.CachedDeviceState;
import com.android.internal.util.DumpUtils;

@@ -120,6 +121,7 @@ public class BinderCallsStatsService extends Binder {

    /** Listens for flag changes. */
    private static class SettingsObserver extends ContentObserver {
        // Settings for BinderCallsStats.
        private static final String SETTINGS_ENABLED_KEY = "enabled";
        private static final String SETTINGS_DETAILED_TRACKING_KEY = "detailed_tracking";
        private static final String SETTINGS_UPLOAD_DATA_KEY = "upload_data";
@@ -127,6 +129,10 @@ public class BinderCallsStatsService extends Binder {
        private static final String SETTINGS_TRACK_SCREEN_INTERACTIVE_KEY = "track_screen_state";
        private static final String SETTINGS_TRACK_DIRECT_CALLING_UID_KEY = "track_calling_uid";
        private static final String SETTINGS_MAX_CALL_STATS_KEY = "max_call_stats_count";
        // Settings for BinderLatencyObserver.
        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 boolean mEnabled;
        private final Uri mUri = Settings.Global.getUriFor(Settings.Global.BINDER_CALLS_STATS);
@@ -180,6 +186,13 @@ public class BinderCallsStatsService extends Binder {
            mBinderCallsStats.setTrackDirectCallerUid(
                    mParser.getBoolean(SETTINGS_TRACK_DIRECT_CALLING_UID_KEY,
                    BinderCallsStats.DEFAULT_TRACK_DIRECT_CALLING_UID));
            mBinderCallsStats.setCollectLatencyData(
                    mParser.getBoolean(SETTINGS_COLLECT_LATENCY_DATA_KEY,
                    BinderCallsStats.DEFAULT_COLLECT_LATENCY_DATA));
            // Binder latency observer settings.
            mBinderCallsStats.getLatencyObserver().setSamplingInterval(mParser.getInt(
                    SETTINGS_LATENCY_OBSERVER_SAMPLING_INTERVAL_KEY,
                    BinderLatencyObserver.PERIODIC_SAMPLING_INTERVAL_DEFAULT));


            final boolean enabled =
@@ -198,6 +211,7 @@ public class BinderCallsStatsService extends Binder {
                mEnabled = enabled;
                mBinderCallsStats.reset();
                mBinderCallsStats.setAddDebugEntries(enabled);
                mBinderCallsStats.getLatencyObserver().reset();
            }
        }
    }