diff --git a/core/java/com/android/internal/os/BinderCallsStats.java b/core/java/com/android/internal/os/BinderCallsStats.java index 14b870575769b..30a35367d6f51 100644 --- a/core/java/com/android/internal/os/BinderCallsStats.java +++ b/core/java/com/android/internal/os/BinderCallsStats.java @@ -57,6 +57,7 @@ public class BinderCallsStats implements BinderInternal.Observer { public static final boolean DEFAULT_TRACK_SCREEN_INTERACTIVE = false; public static final boolean DEFAULT_TRACK_DIRECT_CALLING_UID = true; public static final boolean DEFAULT_IGNORE_BATTERY_STATUS = false; + 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_"; @@ -97,11 +98,13 @@ public class BinderCallsStats implements BinderInternal.Observer { private boolean mTrackDirectCallingUid = DEFAULT_TRACK_DIRECT_CALLING_UID; private boolean mTrackScreenInteractive = DEFAULT_TRACK_SCREEN_INTERACTIVE; private boolean mIgnoreBatteryStatus = DEFAULT_IGNORE_BATTERY_STATUS; + private boolean mCollectLatencyData = DEFAULT_COLLECT_LATENCY_DATA; private CachedDeviceState.Readonly mDeviceState; private CachedDeviceState.TimeInStateStopwatch mBatteryStopwatch; private static final int CALL_STATS_OBSERVER_DEBOUNCE_MILLIS = 5000; + private BinderLatencyObserver mLatencyObserver; private BinderInternal.CallStatsObserver mCallStatsObserver; private ArraySet mSendUidsToObserver = new ArraySet<>(32); private final Handler mCallStatsObserverHandler; @@ -153,11 +156,16 @@ public class BinderCallsStats implements BinderInternal.Observer { public Handler getHandler() { return new Handler(Looper.getMainLooper()); } + + public BinderLatencyObserver getLatencyObserver() { + return new BinderLatencyObserver(new BinderLatencyObserver.Injector()); + } } public BinderCallsStats(Injector injector) { this.mRandom = injector.getRandomGenerator(); this.mCallStatsObserverHandler = injector.getHandler(); + this.mLatencyObserver = injector.getLatencyObserver(); } public void setDeviceState(@NonNull CachedDeviceState.Readonly deviceState) { @@ -207,7 +215,10 @@ public class BinderCallsStats implements BinderInternal.Observer { if (mRecordingAllTransactionsForUid || s.recordedCall) { s.cpuTimeStarted = getThreadTimeMicro(); s.timeStarted = getElapsedRealtimeMicro(); + } else if (mCollectLatencyData) { + s.timeStarted = getElapsedRealtimeMicro(); } + return s; } @@ -232,6 +243,10 @@ public class BinderCallsStats implements BinderInternal.Observer { private void processCallEnded(CallSession s, int parcelRequestSize, int parcelReplySize, int workSourceUid) { + if (mCollectLatencyData) { + mLatencyObserver.callEnded(s); + } + UidEntry uidEntry = null; final boolean recordCall; if (s.recordedCall) { @@ -757,6 +772,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; @@ -768,6 +794,8 @@ public class BinderCallsStats implements BinderInternal.Observer { mBatteryStopwatch.reset(); } mRecordingAllTransactionsForUid = false; + // Do not reset the latency observer as binder stats and latency will be pushed to WW + // at different intervals so the resets should not be coupled. } } @@ -1009,6 +1037,10 @@ public class BinderCallsStats implements BinderInternal.Observer { return mExceptionCounts; } + public BinderLatencyObserver getLatencyObserver() { + return mLatencyObserver; + } + @VisibleForTesting public static List getHighestValues(List list, ToDoubleFunction 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 0000000000000..92b495284de2d --- /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> 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()); + } + + 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 mBinderClass; + // Binder transaction code. + private int mTransactionCode; + // Cached hash code, 0 if not set yet. + private int mHashCode = 0; + + public LatencyDims(Class binderClass, int transactionCode) { + this.mBinderClass = binderClass; + this.mTransactionCode = transactionCode; + } + + public Class 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> 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 561c549676da8..5334a455ce9a5 100644 --- a/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java +++ b/core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java @@ -923,6 +923,34 @@ public class BinderCallsStatsTest { } } + @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()); + } + private static class TestHandler extends Handler { ArrayList mRunnables = new ArrayList<>(); @@ -963,6 +991,10 @@ public class BinderCallsStatsTest { public Handler getHandler() { return mHandler; } + + 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 0000000000000..36915a205ee0f --- /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> 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> latencySamples = blo.getLatencySamples(); + assertEquals(1, latencySamples.size()); + LatencyDims dims = latencySamples.keySet().iterator().next(); + assertEquals(binder.getClass(), dims.getBinderClass()); + assertEquals(1, dims.getTransactionCode()); + ArrayList 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 fdda239e7fde1..9e126d74b172c 100644 --- a/services/core/java/com/android/server/BinderCallsStatsService.java +++ b/services/core/java/com/android/server/BinderCallsStatsService.java @@ -43,6 +43,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; @@ -124,6 +125,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"; @@ -132,6 +134,10 @@ public class BinderCallsStatsService extends Binder { 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"; private static final String SETTINGS_IGNORE_BATTERY_STATUS_KEY = "ignore_battery_status"; + // 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); @@ -188,6 +194,13 @@ public class BinderCallsStatsService extends Binder { mBinderCallsStats.setIgnoreBatteryStatus( mParser.getBoolean(SETTINGS_IGNORE_BATTERY_STATUS_KEY, BinderCallsStats.DEFAULT_IGNORE_BATTERY_STATUS)); + 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 = @@ -206,6 +219,7 @@ public class BinderCallsStatsService extends Binder { mEnabled = enabled; mBinderCallsStats.reset(); mBinderCallsStats.setAddDebugEntries(enabled); + mBinderCallsStats.getLatencyObserver().reset(); } } }