1 /* 2 * Copyright (C) 2023 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License 15 */ 16 17 package com.android.systemui.util 18 19 import android.os.Binder 20 import android.os.Binder.ProxyTransactListener 21 import android.os.Build 22 import android.os.IBinder 23 import android.os.StrictMode 24 import android.os.StrictMode.ThreadPolicy 25 import android.os.Trace.TRACE_TAG_APP 26 import android.os.Trace.asyncTraceForTrackBegin 27 import android.os.Trace.asyncTraceForTrackEnd 28 import android.util.Log 29 import com.android.settingslib.utils.ThreadUtils 30 import com.android.systemui.CoreStartable 31 import com.android.systemui.DejankUtils 32 import com.android.systemui.dagger.SysUISingleton 33 import com.android.systemui.flags.FeatureFlags 34 import com.android.systemui.flags.Flags 35 import javax.inject.Inject 36 import kotlin.random.Random.Default.nextInt 37 38 @SysUISingleton 39 class BinderLogger 40 @Inject 41 constructor( 42 private val featureFlags: FeatureFlags, 43 ) : CoreStartable, ProxyTransactListener { 44 45 override fun start() { 46 // This feature is only allowed on "userdebug" and "eng" builds 47 if (Build.IS_USER) return 48 if (!featureFlags.isEnabled(Flags.WARN_ON_BLOCKING_BINDER_TRANSACTIONS)) return 49 if (DejankUtils.STRICT_MODE_ENABLED) { 50 Log.e( 51 TAG, 52 "Feature disabled; persist.sysui.strictmode (DejankUtils) and " + 53 "WARN_ON_BLOCKING_BINDER_TRANSACTIONS (BinderLogger) are incompatible" 54 ) 55 return 56 } 57 Binder.setProxyTransactListener(this) 58 val policyBuilder = ThreadPolicy.Builder().detectCustomSlowCalls().penaltyLog() 59 StrictMode.setThreadPolicy(policyBuilder.build()) 60 } 61 62 override fun onTransactStarted(binder: IBinder, transactionCode: Int, flags: Int): Any? { 63 // Ignore one-way binder transactions 64 if (flags and IBinder.FLAG_ONEWAY != 0) return null 65 // Ignore anything not on the main thread 66 if (!ThreadUtils.isMainThread()) return null 67 68 // To make it easier to debug, log the most likely cause of the blocking binder transaction 69 // by parsing the stack trace. 70 val tr = Throwable() 71 val analysis = BinderTransactionAnalysis.fromStackTrace(tr.stackTrace) 72 val traceCookie = nextInt() 73 asyncTraceForTrackBegin(TRACE_TAG_APP, TRACK_NAME, analysis.traceMessage, traceCookie) 74 if (analysis.isSystemUi) { 75 StrictMode.noteSlowCall(analysis.logMessage) 76 } else { 77 Log.v(TAG, analysis.logMessage, tr) 78 } 79 return traceCookie 80 } 81 82 override fun onTransactStarted(binder: IBinder, transactionCode: Int): Any? { 83 return null 84 } 85 86 override fun onTransactEnded(o: Any?) { 87 if (o is Int) { 88 asyncTraceForTrackEnd(TRACE_TAG_APP, TRACK_NAME, o) 89 } 90 } 91 92 /** 93 * Class for finding the origin of a binder transaction from a stack trace and creating an error 94 * message that indicates 1) whether or not the call originated from System UI, and 2) the name 95 * of the binder transaction and where it was called. 96 * 97 * There are two types of stack traces: 98 * 1. Stack traces that originate from System UI, which look like the following: ``` 99 * android.os.BinderProxy.transact(BinderProxy.java:541) 100 * android.content.pm.BaseParceledListSlice.<init>(BaseParceledListSlice.java:94) 101 * android.content.pm.ParceledListSlice.<init>(ParceledListSlice.java:42) 102 * android.content.pm.ParceledListSlice.<init>(Unknown Source:0) 103 * android.content.pm.ParceledListSlice$1.createFromParcel(ParceledListSlice.java:80) 104 * android.content.pm.ParceledListSlice$1.createFromParcel(ParceledListSlice.java:78) 105 * android.os.Parcel.readTypedObject(Parcel.java:3982) 106 * android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:5029) 107 * com.android.systemui.ExampleClass.runTwoWayBinderIPC(ExampleClass.kt:343) ... ``` Most of 108 * these binder transactions contain a reference to a `$Stub$Proxy`, but some don't. For 109 * example: ``` android.os.BinderProxy.transact(BinderProxy.java:541) 110 * android.content.ContentProviderProxy.query(ContentProviderNative.java:479) 111 * android.content.ContentResolver.query(ContentResolver.java:1219) 112 * com.android.systemui.power.PowerUI.refreshEstimateIfNeeded(PowerUI.java:383) ``` In both 113 * cases, we identify the call closest to a sysui package to make the error more clear. 114 * 2. Stack traces that originate outside of System UI, which look like the following: ``` 115 * android.os.BinderProxy.transact(BinderProxy.java:541) 116 * android.service.notification.IStatusBarNotificationHolder$Stub$Proxy.get(IStatusBarNotificationHolder.java:121) 117 * android.service.notification.NotificationListenerService$NotificationListenerWrapper.onNotificationPosted(NotificationListenerService.java:1396) 118 * android.service.notification.INotificationListener$Stub.onTransact(INotificationListener.java:248) 119 * android.os.Binder.execTransactInternal(Binder.java:1285) 120 * android.os.Binder.execTransact(Binder.java:1244) ``` 121 * 122 * @param isSystemUi Whether or not the call originated from System UI. If it didn't, it's due 123 * to internal implementation details of a core framework API. 124 * @param cause The cause of the binder transaction 125 * @param binderCall The binder transaction itself 126 */ 127 private class BinderTransactionAnalysis 128 constructor( 129 val isSystemUi: Boolean, 130 cause: StackTraceElement?, 131 binderCall: StackTraceElement? 132 ) { 133 val logMessage: String 134 val traceMessage: String 135 136 init { 137 val callName = 138 (if (isSystemUi) getSimpleCallRefWithFileAndLineNumber(cause) 139 else "${getSimpleCallRef(cause)}()") + " -> ${getBinderCallRef(binderCall)}" 140 logMessage = 141 "Blocking binder transaction detected" + 142 (if (!isSystemUi) ", but the call did not originate from System UI" else "") + 143 ": $callName" 144 traceMessage = "${if (isSystemUi) "sysui" else "core"}: $callName" 145 } 146 147 companion object { 148 fun fromStackTrace(stackTrace: Array<StackTraceElement>): BinderTransactionAnalysis { 149 if (stackTrace.size < 2) { 150 return BinderTransactionAnalysis(false, null, null) 151 } 152 var previousStackElement: StackTraceElement = stackTrace.first() 153 154 // The stack element corresponding to the binder transaction. For example: 155 // `android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:50)` 156 var binderTransaction: StackTraceElement? = null 157 // The stack element that caused the binder transaction in the first place. 158 // For example: 159 // `com.android.systemui.ExampleClass.runTwoWayBinderIPC(ExampleClass.kt:343)` 160 var causeOfBinderTransaction: StackTraceElement? = null 161 162 // Iterate starting from the top of the stack (BinderProxy.transact). 163 for (i in 1 until stackTrace.size) { 164 val stackElement = stackTrace[i] 165 if (previousStackElement.className?.endsWith("\$Stub\$Proxy") == true) { 166 binderTransaction = previousStackElement 167 causeOfBinderTransaction = stackElement 168 } 169 // As a heuristic, find the top-most call from a sysui package (besides this 170 // class) and blame it 171 val className = stackElement.className 172 if ( 173 className != BinderLogger::class.java.name && 174 (className.startsWith(SYSUI_PKG) || className.startsWith(KEYGUARD_PKG)) 175 ) { 176 causeOfBinderTransaction = stackElement 177 178 return BinderTransactionAnalysis( 179 true, 180 causeOfBinderTransaction, 181 // If an IInterface.Stub.Proxy-like call has not been identified yet, 182 // blame the previous call in the stack. 183 binderTransaction ?: previousStackElement 184 ) 185 } 186 previousStackElement = stackElement 187 } 188 // If we never found a call originating from sysui, report it with an explanation 189 // that we could not find a culprit in sysui. 190 return BinderTransactionAnalysis(false, causeOfBinderTransaction, binderTransaction) 191 } 192 } 193 } 194 195 companion object { 196 private const val TAG: String = "SystemUIBinder" 197 private const val TRACK_NAME = "Blocking Binder Transactions" 198 private const val SYSUI_PKG = "com.android.systemui" 199 private const val KEYGUARD_PKG = "com.android.keyguard" 200 private const val UNKNOWN = "<unknown>" 201 202 /** 203 * Start of the source file for any R8 build within AOSP. 204 * 205 * TODO(b/213833843): Allow configuration of the prefix via a build variable. 206 */ 207 private const val AOSP_SOURCE_FILE_MARKER = "go/retraceme " 208 209 /** Start of the source file for any R8 compiler build. */ 210 private const val R8_SOURCE_FILE_MARKER = "R8_" 211 212 /** 213 * Returns a short string for a [StackTraceElement] that references a binder transaction. 214 * For example, a stack frame of 215 * `android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:50)` 216 * would return `android.content.pm.IPackageManager#getInstalledPackages()` 217 */ 218 private fun getBinderCallRef(stackFrame: StackTraceElement?): String = 219 if (stackFrame != null) "${getBinderClassName(stackFrame)}#${stackFrame.methodName}()" 220 else UNKNOWN 221 222 /** 223 * Returns the class name of a [StackTraceElement], removing any `$Stub$Proxy` suffix, but 224 * still including the package name. This makes binder class names more readable. For 225 * example, for a stack element of 226 * `android.content.pm.IPackageManager$Stub$Proxy.getInstalledPackages(IPackageManager.java:50)` 227 * this would return `android.content.pm.IPackageManager` 228 */ 229 private fun getBinderClassName(stackFrame: StackTraceElement): String { 230 val className = stackFrame.className 231 val stubDefIndex = className.indexOf("\$Stub\$Proxy") 232 return if (stubDefIndex > 0) className.substring(0, stubDefIndex) else className 233 } 234 235 /** 236 * Returns a short string for a [StackTraceElement], including the file name and line 237 * number. 238 * 239 * If the source file needs retracing, this falls back to the default `toString()` method so 240 * that it can be read by the `retrace` command-line tool (`m retrace`). 241 */ 242 private fun getSimpleCallRefWithFileAndLineNumber(stackFrame: StackTraceElement?): String = 243 if (stackFrame != null) { 244 with(stackFrame) { 245 if ( 246 fileName == null || 247 fileName.startsWith(AOSP_SOURCE_FILE_MARKER) || 248 fileName.startsWith(R8_SOURCE_FILE_MARKER) 249 ) { 250 // If the source file needs retracing, use the default toString() method for 251 // compatibility with the retrace command-line tool 252 "at $stackFrame" 253 } else { 254 "at ${getSimpleCallRef(stackFrame)}($fileName:$lineNumber)" 255 } 256 } 257 } else UNKNOWN 258 259 /** 260 * Returns a short string for a [StackTraceElement] including it's class name and method 261 * name. For example, if the stack frame is 262 * `com.android.systemui.ExampleController.makeBlockingBinderIPC(ExampleController.kt:343)` 263 * this would return `ExampleController#makeBlockingBinderIPC()` 264 */ 265 private fun getSimpleCallRef(stackFrame: StackTraceElement?): String = 266 if (stackFrame != null) "${getSimpleClassName(stackFrame)}#${stackFrame.methodName}" 267 else UNKNOWN 268 269 /** 270 * Returns a short string for a [StackTraceElement] including just its class name without 271 * any package name. For example, if the stack frame is 272 * `com.android.systemui.ExampleController.makeBlockingBinderIPC(ExampleController.kt:343)` 273 * this would return `ExampleController` 274 */ 275 private fun getSimpleClassName(stackFrame: StackTraceElement): String = 276 try { 277 with(Class.forName(stackFrame.className)) { 278 canonicalName?.substring(packageName.length + 1) 279 } 280 } finally {} ?: stackFrame.className 281 } 282 } 283