Merge "Create BinderLatencyObserver to collect binder call latency stats. Pushing these as a metric will come in a future change." am: 60cd2fa626 am: 0e29db726c

Original change: https://android-review.googlesource.com/c/platform/frameworks/base/+/1697178

Change-Id: I0af62c50b32487734cc49a0f649c544728179593

5 files changed, 346 insertions, 0 deletions

diff --git a/core/java/com/android/internal/os/BinderCallsStats.java b/core/java/com/android/internal/os/BinderCallsStats.java
index 0fb2728aed73..dbba469dda1a 100644
--- a/core/java/com/android/internal/os/BinderCallsStats.java
+++ b/core/java/com/android/internal/os/BinderCallsStats.java
@@ -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) {
diff --git a/core/java/com/android/internal/os/BinderLatencyObserver.java b/core/java/com/android/internal/os/BinderLatencyObserver.java
new file mode 100644
index 000000000000..92b495284de2
--- /dev/null
+++ b/core/java/com/android/internal/os/BinderLatencyObserver.java
@@ -0,0 +1,157 @@
+/*
+ * 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;
+    }
+}
diff --git a/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java b/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java
index eb9c7b66d642..1156120217aa 100644
--- a/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java
+++ b/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java
@@ -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);
diff --git a/core/tests/coretests/src/com/android/internal/os/BinderLatencyObserverTest.java b/core/tests/coretests/src/com/android/internal/os/BinderLatencyObserverTest.java
new file mode 100644
index 000000000000..36915a205ee0
--- /dev/null
+++ b/core/tests/coretests/src/com/android/internal/os/BinderLatencyObserverTest.java
@@ -0,0 +1,110 @@
+/*
+ * 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;
+        }
+    }
+}
diff --git a/services/core/java/com/android/server/BinderCallsStatsService.java b/services/core/java/com/android/server/BinderCallsStatsService.java
index c771eb701b1d..9c8582f78134 100644
--- a/services/core/java/com/android/server/BinderCallsStatsService.java
+++ b/services/core/java/com/android/server/BinderCallsStatsService.java
@@ -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();
             }
         }
     }