diff options
4 files changed, 339 insertions, 0 deletions
diff --git a/packages/SystemUI/src-debug/com/android/systemui/util/StartBinderLoggerModule.kt b/packages/SystemUI/src-debug/com/android/systemui/util/StartBinderLoggerModule.kt new file mode 100644 index 000000000000..d48c5b98165c --- /dev/null +++ b/packages/SystemUI/src-debug/com/android/systemui/util/StartBinderLoggerModule.kt @@ -0,0 +1,31 @@ +/* + * Copyright (C) 2023 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.systemui.util + +import com.android.systemui.CoreStartable +import dagger.Binds +import dagger.Module +import dagger.multibindings.ClassKey +import dagger.multibindings.IntoMap + +@Module +abstract class StartBinderLoggerModule { + @Binds + @IntoMap + @ClassKey(BinderLogger::class) + abstract fun bindBinderLogger(impl: BinderLogger): CoreStartable +} diff --git a/packages/SystemUI/src-release/com/android/systemui/util/StartBinderLoggerModule.kt b/packages/SystemUI/src-release/com/android/systemui/util/StartBinderLoggerModule.kt new file mode 100644 index 000000000000..6914c57dd915 --- /dev/null +++ b/packages/SystemUI/src-release/com/android/systemui/util/StartBinderLoggerModule.kt @@ -0,0 +1,24 @@ +/* + * Copyright (C) 2023 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.systemui.util + +import dagger.Module + +@Module +abstract class StartBinderLoggerModule { + // Empty because this module is only used on debug builds +} diff --git a/packages/SystemUI/src/com/android/systemui/dagger/SystemUICoreStartableModule.kt b/packages/SystemUI/src/com/android/systemui/dagger/SystemUICoreStartableModule.kt index 5d6479ef4532..078be4b7ed5d 100644 --- a/packages/SystemUI/src/com/android/systemui/dagger/SystemUICoreStartableModule.kt +++ b/packages/SystemUI/src/com/android/systemui/dagger/SystemUICoreStartableModule.kt @@ -55,6 +55,7 @@ import com.android.systemui.theme.ThemeOverlayController import com.android.systemui.toast.ToastUI import com.android.systemui.usb.StorageNotification import com.android.systemui.util.NotificationChannels +import com.android.systemui.util.StartBinderLoggerModule import com.android.systemui.volume.VolumeUI import com.android.systemui.wmshell.WMShell import dagger.Binds @@ -68,6 +69,7 @@ import dagger.multibindings.IntoMap @Module(includes = [ MultiUserUtilsModule::class, StartControlsStartableModule::class, + StartBinderLoggerModule::class, ]) abstract class SystemUICoreStartableModule { /** Inject into AuthController. */ diff --git a/packages/SystemUI/src/com/android/systemui/util/BinderLogger.kt b/packages/SystemUI/src/com/android/systemui/util/BinderLogger.kt new file mode 100644 index 000000000000..e21f0aaf5eca --- /dev/null +++ b/packages/SystemUI/src/com/android/systemui/util/BinderLogger.kt @@ -0,0 +1,282 @@ +/* + * Copyright (C) 2023 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.systemui.util + +import android.os.Binder +import android.os.Binder.ProxyTransactListener +import android.os.Build +import android.os.IBinder +import android.os.StrictMode +import android.os.StrictMode.ThreadPolicy +import android.os.Trace.TRACE_TAG_APP +import android.os.Trace.asyncTraceForTrackBegin +import android.os.Trace.asyncTraceForTrackEnd +import android.util.Log +import com.android.settingslib.utils.ThreadUtils +import com.android.systemui.CoreStartable +import com.android.systemui.DejankUtils +import com.android.systemui.dagger.SysUISingleton +import com.android.systemui.flags.FeatureFlags +import com.android.systemui.flags.Flags +import javax.inject.Inject +import kotlin.random.Random.Default.nextInt + +@SysUISingleton +class BinderLogger +@Inject +constructor( + private val featureFlags: FeatureFlags, +) : CoreStartable, ProxyTransactListener { + + override fun start() { + // This feature is only allowed on "userdebug" and "eng" builds + if (Build.IS_USER) return + if (!featureFlags.isEnabled(Flags.WARN_ON_BLOCKING_BINDER_TRANSACTIONS)) return + if (DejankUtils.STRICT_MODE_ENABLED) { + Log.e( + TAG, + "Feature disabled; persist.sysui.strictmode (DejankUtils) and " + + "WARN_ON_BLOCKING_BINDER_TRANSACTIONS (BinderLogger) are incompatible" + ) + return + } + Binder.setProxyTransactListener(this) + val policyBuilder = ThreadPolicy.Builder().detectCustomSlowCalls().penaltyLog() + StrictMode.setThreadPolicy(policyBuilder.build()) + } + + override fun onTransactStarted(binder: IBinder, transactionCode: Int, flags: Int): Any? { + // Ignore one-way binder transactions + if (flags and IBinder.FLAG_ONEWAY != 0) return null + // Ignore anything not on the main thread + if (!ThreadUtils.isMainThread()) return null + + // To make it easier to debug, log the most likely cause of the blocking binder transaction + // by parsing the stack trace. + val tr = Throwable() + val analysis = BinderTransactionAnalysis.fromStackTrace(tr.stackTrace) + val traceCookie = nextInt() + asyncTraceForTrackBegin(TRACE_TAG_APP, TRACK_NAME, analysis.traceMessage, traceCookie) + if (analysis.isSystemUi) { + StrictMode.noteSlowCall(analysis.logMessage) + } else { + Log.v(TAG, analysis.logMessage, tr) + } + return traceCookie + } + + override fun onTransactStarted(binder: IBinder, transactionCode: Int): Any? { + return null + } + + override fun onTransactEnded(o: Any?) { + if (o is Int) { + asyncTraceForTrackEnd(TRACE_TAG_APP, TRACK_NAME, o) + } + } + + /** + * Class for finding the origin of a binder transaction from a stack trace and creating an error + * message that indicates 1) whether or not the call originated from System UI, and 2) the name + * of the binder transaction and where it was called. + * + * There are two types of stack traces: + * 1. Stack traces that originate from System UI, which look like the following: ``` + * android.os.BinderProxy.transact(BinderProxy.java:541) + * android.content.pm.BaseParceledListSlice.<init>(BaseParceledListSlice.java:94) + * android.content.pm.ParceledListSlice.<init>(ParceledListSlice.java:42) + * android.content.pm.ParceledListSlice.<init>(Unknown Source:0) + * android.content.pm.ParceledListSlice$1.createFromParcel(ParceledListSlice.java:80) + * android.content.pm.ParceledListSlice$1.createFromParcel(ParceledListSlice.java:78) + * android.os.Parcel.readTypedObject(Parcel.java:3982) + * android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:5029) + * com.android.systemui.ExampleClass.runTwoWayBinderIPC(ExampleClass.kt:343) ... ``` Most of + * these binder transactions contain a reference to a `$Stub$Proxy`, but some don't. For + * example: ``` android.os.BinderProxy.transact(BinderProxy.java:541) + * android.content.ContentProviderProxy.query(ContentProviderNative.java:479) + * android.content.ContentResolver.query(ContentResolver.java:1219) + * com.android.systemui.power.PowerUI.refreshEstimateIfNeeded(PowerUI.java:383) ``` In both + * cases, we identify the call closest to a sysui package to make the error more clear. + * 2. Stack traces that originate outside of System UI, which look like the following: ``` + * android.os.BinderProxy.transact(BinderProxy.java:541) + * android.service.notification.IStatusBarNotificationHolder$Stub$Proxy.get(IStatusBarNotificationHolder.java:121) + * android.service.notification.NotificationListenerService$NotificationListenerWrapper.onNotificationPosted(NotificationListenerService.java:1396) + * android.service.notification.INotificationListener$Stub.onTransact(INotificationListener.java:248) + * android.os.Binder.execTransactInternal(Binder.java:1285) + * android.os.Binder.execTransact(Binder.java:1244) ``` + * + * @param isSystemUi Whether or not the call originated from System UI. If it didn't, it's due + * to internal implementation details of a core framework API. + * @param cause The cause of the binder transaction + * @param binderCall The binder transaction itself + */ + private class BinderTransactionAnalysis + constructor( + val isSystemUi: Boolean, + cause: StackTraceElement?, + binderCall: StackTraceElement? + ) { + val logMessage: String + val traceMessage: String + + init { + val callName = + (if (isSystemUi) getSimpleCallRefWithFileAndLineNumber(cause) + else "${getSimpleCallRef(cause)}()") + " -> ${getBinderCallRef(binderCall)}" + logMessage = + "Blocking binder transaction detected" + + (if (!isSystemUi) ", but the call did not originate from System UI" else "") + + ": $callName" + traceMessage = "${if (isSystemUi) "sysui" else "core"}: $callName" + } + + companion object { + fun fromStackTrace(stackTrace: Array<StackTraceElement>): BinderTransactionAnalysis { + if (stackTrace.size < 2) { + return BinderTransactionAnalysis(false, null, null) + } + var previousStackElement: StackTraceElement = stackTrace.first() + + // The stack element corresponding to the binder transaction. For example: + // `android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:50)` + var binderTransaction: StackTraceElement? = null + // The stack element that caused the binder transaction in the first place. + // For example: + // `com.android.systemui.ExampleClass.runTwoWayBinderIPC(ExampleClass.kt:343)` + var causeOfBinderTransaction: StackTraceElement? = null + + // Iterate starting from the top of the stack (BinderProxy.transact). + for (i in 1 until stackTrace.size) { + val stackElement = stackTrace[i] + if (previousStackElement.className?.endsWith("\$Stub\$Proxy") == true) { + binderTransaction = previousStackElement + causeOfBinderTransaction = stackElement + } + // As a heuristic, find the top-most call from a sysui package (besides this + // class) and blame it + val className = stackElement.className + if ( + className != BinderLogger::class.java.name && + (className.startsWith(SYSUI_PKG) || className.startsWith(KEYGUARD_PKG)) + ) { + causeOfBinderTransaction = stackElement + + return BinderTransactionAnalysis( + true, + causeOfBinderTransaction, + // If an IInterface.Stub.Proxy-like call has not been identified yet, + // blame the previous call in the stack. + binderTransaction ?: previousStackElement + ) + } + previousStackElement = stackElement + } + // If we never found a call originating from sysui, report it with an explanation + // that we could not find a culprit in sysui. + return BinderTransactionAnalysis(false, causeOfBinderTransaction, binderTransaction) + } + } + } + + companion object { + private const val TAG: String = "SystemUIBinder" + private const val TRACK_NAME = "Blocking Binder Transactions" + private const val SYSUI_PKG = "com.android.systemui" + private const val KEYGUARD_PKG = "com.android.keyguard" + private const val UNKNOWN = "<unknown>" + + /** + * Start of the source file for any R8 build within AOSP. + * + * TODO(b/213833843): Allow configuration of the prefix via a build variable. + */ + private const val AOSP_SOURCE_FILE_MARKER = "go/retraceme " + + /** Start of the source file for any R8 compiler build. */ + private const val R8_SOURCE_FILE_MARKER = "R8_" + + /** + * Returns a short string for a [StackTraceElement] that references a binder transaction. + * For example, a stack frame of + * `android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:50)` + * would return `android.content.pm.IPackageManager#getInstalledPackages()` + */ + private fun getBinderCallRef(stackFrame: StackTraceElement?): String = + if (stackFrame != null) "${getBinderClassName(stackFrame)}#${stackFrame.methodName}()" + else UNKNOWN + + /** + * Returns the class name of a [StackTraceElement], removing any `$Stub$Proxy` suffix, but + * still including the package name. This makes binder class names more readable. For + * example, for a stack element of + * `android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:50)` + * this would return `android.content.pm.IPackageManager` + */ + private fun getBinderClassName(stackFrame: StackTraceElement): String { + val className = stackFrame.className + val stubDefIndex = className.indexOf("\$Stub\$Proxy") + return if (stubDefIndex > 0) className.substring(0, stubDefIndex) else className + } + + /** + * Returns a short string for a [StackTraceElement], including the file name and line + * number. + * + * If the source file needs retracing, this falls back to the default `toString()` method so + * that it can be read by the `retrace` command-line tool (`m retrace`). + */ + private fun getSimpleCallRefWithFileAndLineNumber(stackFrame: StackTraceElement?): String = + if (stackFrame != null) { + with(stackFrame) { + if ( + fileName == null || + fileName.startsWith(AOSP_SOURCE_FILE_MARKER) || + fileName.startsWith(R8_SOURCE_FILE_MARKER) + ) { + // If the source file needs retracing, use the default toString() method for + // compatibility with the retrace command-line tool + "at $stackFrame" + } else { + "at ${getSimpleCallRef(stackFrame)}($fileName:$lineNumber)" + } + } + } else UNKNOWN + + /** + * Returns a short string for a [StackTraceElement] including it's class name and method + * name. For example, if the stack frame is + * `com.android.systemui.ExampleController.makeBlockingBinderIPC(ExampleController.kt:343)` + * this would return `ExampleController#makeBlockingBinderIPC()` + */ + private fun getSimpleCallRef(stackFrame: StackTraceElement?): String = + if (stackFrame != null) "${getSimpleClassName(stackFrame)}#${stackFrame.methodName}" + else UNKNOWN + + /** + * Returns a short string for a [StackTraceElement] including just its class name without + * any package name. For example, if the stack frame is + * `com.android.systemui.ExampleController.makeBlockingBinderIPC(ExampleController.kt:343)` + * this would return `ExampleController` + */ + private fun getSimpleClassName(stackFrame: StackTraceElement): String = + try { + with(Class.forName(stackFrame.className)) { + canonicalName?.substring(packageName.length + 1) + } + } finally {} ?: stackFrame.className + } +} |