From 3b331dbed51c092125f499cb129c569eae3fcc87 Mon Sep 17 00:00:00 2001 From: Jeff DeCew Date: Fri, 21 Jul 2023 12:42:47 -0400 Subject: [PATCH 1/4] Extract the SystemUI 'config' from DumpHandler to a critical Dumpable This just extracts some dump logic to clean up some cruft in DumpHandler Test: atest DumpHandlerTest Test: dumpsysui bugreport-critical Test: dumpsysui config Bug: 292221335 Change-Id: I1e91a5b31070778d7d96f8a9f6e217126258e939 --- .../com/android/systemui/dump/DumpHandler.kt | 40 +--------- .../systemui/dump/SystemUIConfigDumpable.kt | 73 +++++++++++++++++++ .../android/systemui/dump/DumpHandlerTest.kt | 20 +++-- 3 files changed, 84 insertions(+), 49 deletions(-) create mode 100644 packages/SystemUI/src/com/android/systemui/dump/SystemUIConfigDumpable.kt diff --git a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt index 75284fc181495..44de4764c8cf1 100644 --- a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt +++ b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt @@ -16,12 +16,9 @@ package com.android.systemui.dump -import android.content.Context import android.os.SystemClock import android.os.Trace -import com.android.systemui.CoreStartable import com.android.systemui.ProtoDumpable -import com.android.systemui.R import com.android.systemui.dump.DumpHandler.Companion.PRIORITY_ARG_CRITICAL import com.android.systemui.dump.DumpHandler.Companion.PRIORITY_ARG_NORMAL import com.android.systemui.dump.DumpsysEntry.DumpableEntry @@ -36,7 +33,6 @@ import java.io.FileDescriptor import java.io.FileOutputStream import java.io.PrintWriter import javax.inject.Inject -import javax.inject.Provider /** * Oversees SystemUI's output during bug reports (and dumpsys in general) @@ -91,10 +87,9 @@ import javax.inject.Provider class DumpHandler @Inject constructor( - private val context: Context, private val dumpManager: DumpManager, private val logBufferEulogizer: LogBufferEulogizer, - private val startables: MutableMap, Provider>, + private val config: SystemUIConfigDumpable, ) { /** Dump the diagnostics! Behavior can be controlled via [args]. */ fun dump(fd: FileDescriptor, pw: PrintWriter, args: Array) { @@ -148,7 +143,6 @@ constructor( dumpDumpable(target, pw, args.rawArgs) } } - dumpConfig(pw) } private fun dumpNormal(pw: PrintWriter, args: ParsedArgs) { @@ -267,37 +261,7 @@ constructor( } private fun dumpConfig(pw: PrintWriter) { - pw.println("SystemUiServiceComponents configuration:") - pw.print("vendor component: ") - pw.println(context.resources.getString(R.string.config_systemUIVendorServiceComponent)) - val services: MutableList = - startables.keys.map({ cls: Class<*> -> cls.simpleName }).toMutableList() - - services.add(context.resources.getString(R.string.config_systemUIVendorServiceComponent)) - dumpServiceList(pw, "global", services.toTypedArray()) - dumpServiceList(pw, "per-user", R.array.config_systemUIServiceComponentsPerUser) - } - - private fun dumpServiceList(pw: PrintWriter, type: String, resId: Int) { - val services: Array = context.resources.getStringArray(resId) - dumpServiceList(pw, type, services) - } - - private fun dumpServiceList(pw: PrintWriter, type: String, services: Array?) { - pw.print(type) - pw.print(": ") - if (services == null) { - pw.println("N/A") - return - } - pw.print(services.size) - pw.println(" services") - for (i in services.indices) { - pw.print(" ") - pw.print(i) - pw.print(": ") - pw.println(services[i]) - } + config.dump(pw, arrayOf()) } private fun dumpHelp(pw: PrintWriter) { diff --git a/packages/SystemUI/src/com/android/systemui/dump/SystemUIConfigDumpable.kt b/packages/SystemUI/src/com/android/systemui/dump/SystemUIConfigDumpable.kt new file mode 100644 index 0000000000000..b70edcc272541 --- /dev/null +++ b/packages/SystemUI/src/com/android/systemui/dump/SystemUIConfigDumpable.kt @@ -0,0 +1,73 @@ +/* + * 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.dump + +import android.content.Context +import com.android.systemui.CoreStartable +import com.android.systemui.Dumpable +import com.android.systemui.R +import com.android.systemui.dagger.SysUISingleton +import java.io.PrintWriter +import javax.inject.Inject +import javax.inject.Provider + +@SysUISingleton +class SystemUIConfigDumpable +@Inject +constructor( + dumpManager: DumpManager, + private val context: Context, + private val startables: MutableMap, Provider>, +) : Dumpable { + init { + dumpManager.registerCriticalDumpable("SystemUiServiceComponents", this) + } + + override fun dump(pw: PrintWriter, args: Array) { + pw.println("SystemUiServiceComponents configuration:") + pw.print("vendor component: ") + pw.println(context.resources.getString(R.string.config_systemUIVendorServiceComponent)) + val services: MutableList = + startables.keys.map { cls: Class<*> -> cls.simpleName }.toMutableList() + + services.add(context.resources.getString(R.string.config_systemUIVendorServiceComponent)) + dumpServiceList(pw, "global", services.toTypedArray()) + dumpServiceList(pw, "per-user", R.array.config_systemUIServiceComponentsPerUser) + } + + private fun dumpServiceList(pw: PrintWriter, type: String, resId: Int) { + val services: Array = context.resources.getStringArray(resId) + dumpServiceList(pw, type, services) + } + + private fun dumpServiceList(pw: PrintWriter, type: String, services: Array?) { + pw.print(type) + pw.print(": ") + if (services == null) { + pw.println("N/A") + return + } + pw.print(services.size) + pw.println(" services") + for (i in services.indices) { + pw.print(" ") + pw.print(i) + pw.print(": ") + pw.println(services[i]) + } + } +} diff --git a/packages/SystemUI/tests/src/com/android/systemui/dump/DumpHandlerTest.kt b/packages/SystemUI/tests/src/com/android/systemui/dump/DumpHandlerTest.kt index 2830476874ed4..840eb468b8c29 100644 --- a/packages/SystemUI/tests/src/com/android/systemui/dump/DumpHandlerTest.kt +++ b/packages/SystemUI/tests/src/com/android/systemui/dump/DumpHandlerTest.kt @@ -26,10 +26,6 @@ import com.android.systemui.log.table.TableLogBuffer import com.android.systemui.util.mockito.any import com.android.systemui.util.mockito.eq import com.google.common.truth.Truth.assertThat -import java.io.FileDescriptor -import java.io.PrintWriter -import java.io.StringWriter -import javax.inject.Provider import org.junit.Before import org.junit.Test import org.mockito.Mock @@ -37,6 +33,10 @@ import org.mockito.Mockito.anyInt import org.mockito.Mockito.never import org.mockito.Mockito.verify import org.mockito.MockitoAnnotations +import java.io.FileDescriptor +import java.io.PrintWriter +import java.io.StringWriter +import javax.inject.Provider @SmallTest class DumpHandlerTest : SysuiTestCase() { @@ -79,14 +79,12 @@ class DumpHandlerTest : SysuiTestCase() { fun setUp() { MockitoAnnotations.initMocks(this) - dumpHandler = DumpHandler( - mContext, - dumpManager, - logBufferEulogizer, - mutableMapOf( - EmptyCoreStartable::class.java to Provider { EmptyCoreStartable() } - ), + val config = SystemUIConfigDumpable( + dumpManager, + mContext, + mutableMapOf(EmptyCoreStartable::class.java to Provider { EmptyCoreStartable() }), ) + dumpHandler = DumpHandler(dumpManager, logBufferEulogizer, config) } @Test From 2dc4aac2aa6323d3aceb3357f4b9036dbea4bf4b Mon Sep 17 00:00:00 2001 From: Jeff DeCew Date: Fri, 21 Jul 2023 13:16:05 -0400 Subject: [PATCH 2/4] Include the dump time and warning at the end of each Dumpable dump To track down dumpables that are taking too long, add the duration of their dump to the end of their dump output. Also adds `dumpsysui all` command for simpler testing. Test: atest DumpHandlerTest Test: dumpsysui bugreport-critical Test: dumpsysui all Bug: 292221335 Change-Id: Ic2b99e7ba0ebc68aa887473aeb055da8317f0e62 --- .../com/android/systemui/dump/DumpHandler.kt | 81 ++++++++++++------- 1 file changed, 51 insertions(+), 30 deletions(-) diff --git a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt index 44de4764c8cf1..2a7b687118c51 100644 --- a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt +++ b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt @@ -33,6 +33,7 @@ import java.io.FileDescriptor import java.io.FileOutputStream import java.io.PrintWriter import javax.inject.Inject +import kotlin.system.measureTimeMillis /** * Oversees SystemUI's output during bug reports (and dumpsys in general) @@ -73,6 +74,7 @@ import javax.inject.Inject * $ dumpables * $ buffers * $ tables + * $ all * * # Finally, the following will simulate what we dump during the CRITICAL and NORMAL sections of a * # bug report: @@ -124,6 +126,11 @@ constructor( "dumpables" -> dumpDumpables(pw, args) "buffers" -> dumpBuffers(pw, args) "tables" -> dumpTables(pw, args) + "all" -> { + dumpDumpables(pw, args) + dumpBuffers(pw, args) + dumpTables(pw, args) + } "config" -> dumpConfig(pw) "help" -> dumpHelp(pw) else -> { @@ -245,21 +252,6 @@ constructor( .sortedBy { it.name } .minByOrNull { it.name.length } - private fun dumpDumpable(entry: DumpableEntry, pw: PrintWriter, args: Array) { - pw.preamble(entry) - entry.dumpable.dump(pw, args) - } - - private fun dumpBuffer(entry: LogBufferEntry, pw: PrintWriter, tailLength: Int) { - pw.preamble(entry) - entry.buffer.dump(pw, tailLength) - } - - private fun dumpTableBuffer(buffer: TableLogBufferEntry, pw: PrintWriter, args: Array) { - pw.preamble(buffer) - buffer.table.dump(pw, args) - } - private fun dumpConfig(pw: PrintWriter) { config.dump(pw, arrayOf()) } @@ -428,31 +420,60 @@ constructor( } } - /** - * Zero-arg utility to write a [DumpableEntry] to the given [PrintWriter] in a - * dumpsys-appropriate format. - */ - private fun dumpDumpable(entry: DumpableEntry, pw: PrintWriter) { - pw.preamble(entry) - entry.dumpable.dump(pw, arrayOf()) + private fun PrintWriter.footer(entry: DumpsysEntry, dumpTimeMillis: Long) { + if (entry !is DumpableEntry) return + println() + print(entry.priority) + print(" dump took ") + print(dumpTimeMillis) + print("ms -- ") + print(entry.name) + if (entry.priority == DumpPriority.CRITICAL && dumpTimeMillis > 25) { + print(" -- warning: individual dump time exceeds 5% of total CRITICAL dump time!") + } + println() + } + + private inline fun PrintWriter.wrapSection(entry: DumpsysEntry, block: () -> Unit) { + preamble(entry) + val dumpTime = measureTimeMillis(block) + footer(entry, dumpTime) } /** - * Zero-arg utility to write a [LogBufferEntry] to the given [PrintWriter] in a + * Utility to write a [DumpableEntry] to the given [PrintWriter] in a * dumpsys-appropriate format. */ - private fun dumpBuffer(entry: LogBufferEntry, pw: PrintWriter) { - pw.preamble(entry) - entry.buffer.dump(pw, 0) + private fun dumpDumpable( + entry: DumpableEntry, + pw: PrintWriter, + args: Array = arrayOf(), + ) = pw.wrapSection(entry) { + entry.dumpable.dump(pw, args) } /** - * Zero-arg utility to write a [TableLogBufferEntry] to the given [PrintWriter] in a + * Utility to write a [LogBufferEntry] to the given [PrintWriter] in a * dumpsys-appropriate format. */ - private fun dumpTableBuffer(entry: TableLogBufferEntry, pw: PrintWriter) { - pw.preamble(entry) - entry.table.dump(pw, arrayOf()) + private fun dumpBuffer( + entry: LogBufferEntry, + pw: PrintWriter, + tailLength: Int = 0, + ) = pw.wrapSection(entry) { + entry.buffer.dump(pw, tailLength) + } + + /** + * Utility to write a [TableLogBufferEntry] to the given [PrintWriter] in a + * dumpsys-appropriate format. + */ + private fun dumpTableBuffer( + entry: TableLogBufferEntry, + pw: PrintWriter, + args: Array = arrayOf(), + ) = pw.wrapSection(entry) { + entry.table.dump(pw, args) } /** From fb620579f7d8e817600c41e88a1cf7a1184cb7aa Mon Sep 17 00:00:00 2001 From: Jeff DeCew Date: Mon, 24 Jul 2023 11:24:58 -0400 Subject: [PATCH 3/4] Ensure buffers are parsed by using standard divider This also adds back the colon that caused b/292275180 Test: adb bugreport -> ABT Bug: 292221335 Change-Id: I823efa1b0ef751725a35053ea54b4dd04e801de9 --- .../src/com/android/systemui/dump/DumpHandler.kt | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt index 2a7b687118c51..6ebd351fff04e 100644 --- a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt +++ b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt @@ -382,13 +382,6 @@ constructor( const val DUMPSYS_DUMPABLE_DIVIDER = "----------------------------------------------------------------------------" - /** - * Important: do not change this divider without updating any bug report processing tools - * (e.g. ABT), since this divider is used to determine boundaries for bug report views - */ - const val DUMPSYS_BUFFER_DIVIDER = - "============================================================================" - private fun findBestTargetMatch(c: Collection, target: String) = c.asSequence().filter { it.name.endsWith(target) }.minByOrNull { it.name.length } @@ -409,14 +402,14 @@ constructor( is DumpableEntry, is TableLogBufferEntry -> { println() - println(entry.name) + println("${entry.name}:") println(DUMPSYS_DUMPABLE_DIVIDER) } is LogBufferEntry -> { println() println() println("BUFFER ${entry.name}:") - println(DUMPSYS_BUFFER_DIVIDER) + println(DUMPSYS_DUMPABLE_DIVIDER) } } From 1f89e284a4a6e0d835bfa2263331cae5f0471dbc Mon Sep 17 00:00:00 2001 From: Jeff DeCew Date: Mon, 24 Jul 2023 14:30:15 -0400 Subject: [PATCH 4/4] Print when the sysui dump actually starts. This highlights that the CRITICAL dumps are captured within 2-3s of starting the bugreport, while NORMAL dumps can sometimes take a couple minutes to start being collected. Test: adb bugreport -> ABT Bug: 292221335 Change-Id: I49cbbd17a0b73505d4911abea364bb88b95144d5 --- .../SystemUI/src/com/android/systemui/dump/DumpHandler.kt | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt index 6ebd351fff04e..ae40f7e8d7c03 100644 --- a/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt +++ b/packages/SystemUI/src/com/android/systemui/dump/DumpHandler.kt @@ -16,6 +16,7 @@ package com.android.systemui.dump +import android.icu.text.SimpleDateFormat import android.os.SystemClock import android.os.Trace import com.android.systemui.ProtoDumpable @@ -32,6 +33,7 @@ import java.io.BufferedOutputStream import java.io.FileDescriptor import java.io.FileOutputStream import java.io.PrintWriter +import java.util.Locale import javax.inject.Inject import kotlin.system.measureTimeMillis @@ -106,6 +108,8 @@ constructor( return } + pw.print("Dump starting: ") + pw.println(DATE_FORMAT.format(System.currentTimeMillis())) when { parsedArgs.dumpPriority == PRIORITY_ARG_CRITICAL -> dumpCritical(pw, parsedArgs) parsedArgs.dumpPriority == PRIORITY_ARG_NORMAL && !parsedArgs.proto -> { @@ -488,6 +492,7 @@ constructor( } } +private val DATE_FORMAT = SimpleDateFormat("MM-dd HH:mm:ss.SSS", Locale.US) private val PRIORITY_OPTIONS = arrayOf(PRIORITY_ARG_CRITICAL, PRIORITY_ARG_NORMAL) private val COMMANDS =