From 6c61f360ec1429da57a78f7918b8c257b203988d Mon Sep 17 00:00:00 2001 From: Justin Weir Date: Tue, 29 Mar 2022 20:18:11 +0000 Subject: [PATCH 1/2] Move logging to background thread in LogBuffer To avoid checking log level settings on the main thread, which can cause jank, move the settings check and logging to a background thread. During manually testing with both the original mechanism and the background thread, messages still appeared in the console with the exact same timestamp (to the millisecond). Nothing I did on the phone was able to get the background thread's BlockingQueue to ever hold more than 3 messages at any given time. Bug: 221419865 Test: Manually verified messages still logged and BlockingQueue had sufficient capacity Change-Id: If230e09674dcf1dd7e7b1026e71717f982c5b3d2 --- .../src/com/android/systemui/log/LogBuffer.kt | 26 +++++++++++++++++++ 1 file changed, 26 insertions(+) diff --git a/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt b/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt index 6d589aac2079a..9a1bd25556a5c 100644 --- a/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt +++ b/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt @@ -23,6 +23,9 @@ import java.io.PrintWriter import java.text.SimpleDateFormat import java.util.ArrayDeque import java.util.Locale +import java.util.concurrent.ArrayBlockingQueue +import java.util.concurrent.BlockingQueue +import kotlin.concurrent.thread /** * A simple ring buffer of recyclable log messages @@ -81,6 +84,19 @@ class LogBuffer @JvmOverloads constructor( } private val buffer: ArrayDeque = ArrayDeque() + private val echoMessageQueue: BlockingQueue = ArrayBlockingQueue(poolSize) + + init { + thread(start = true, priority = Thread.NORM_PRIORITY) { + try { + while (true) { + echoToDesiredEndpoints(echoMessageQueue.take()) + } + } catch (e: InterruptedException) { + Thread.currentThread().interrupt() + } + } + } var frozen = false private set @@ -176,6 +192,16 @@ class LogBuffer @JvmOverloads constructor( buffer.removeFirst() } buffer.add(message as LogMessageImpl) + // Log in the background thread only if it has capacity to avoid blocking this thread + if (echoMessageQueue.remainingCapacity() > 0) { + echoMessageQueue.put(message) + } else { + echoToDesiredEndpoints(message) + } + } + + /** Sends message to echo after determining whether to use Logcat and/or systrace. */ + private fun echoToDesiredEndpoints(message: LogMessageImpl) { val includeInLogcat = logcatEchoTracker.isBufferLoggable(name, message.level) || logcatEchoTracker.isTagLoggable(message.tag, message.level) echo(message, toLogcat = includeInLogcat, toSystrace = systrace) From 1702ffa6f21f7f83170576ac3c2803c243a24eef Mon Sep 17 00:00:00 2001 From: Justin Weir Date: Tue, 5 Apr 2022 20:34:27 +0000 Subject: [PATCH 2/2] Change Logcat to only log in background thread in debug mode The prod and always log trackers shoud just log syncrhonously, since they do not do any jank-causing work to determine whether a message should be logged. Bug: 221419865 Test: ran 'atest SystemUITests SystemUIGoogleTests' Change-Id: I2e673a480abbd5afda2d6ce3117df47e0415ea8a --- .../src/com/android/systemui/log/LogBuffer.kt | 29 ++++++++++++------- .../android/systemui/log/LogcatEchoTracker.kt | 5 ++++ .../systemui/log/LogcatEchoTrackerDebug.kt | 1 + .../systemui/log/LogcatEchoTrackerProd.kt | 2 ++ .../android/systemui/dump/LogBufferHelper.kt | 1 + 5 files changed, 28 insertions(+), 10 deletions(-) diff --git a/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt b/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt index 9a1bd25556a5c..e16da89d6ec85 100644 --- a/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt +++ b/packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt @@ -84,16 +84,19 @@ class LogBuffer @JvmOverloads constructor( } private val buffer: ArrayDeque = ArrayDeque() - private val echoMessageQueue: BlockingQueue = ArrayBlockingQueue(poolSize) + private val echoMessageQueue: BlockingQueue? = + if (logcatEchoTracker.logInBackgroundThread) ArrayBlockingQueue(poolSize) else null init { - thread(start = true, priority = Thread.NORM_PRIORITY) { - try { - while (true) { - echoToDesiredEndpoints(echoMessageQueue.take()) + if (logcatEchoTracker.logInBackgroundThread && echoMessageQueue != null) { + thread(start = true, priority = Thread.NORM_PRIORITY) { + try { + while (true) { + echoToDesiredEndpoints(echoMessageQueue.take()) + } + } catch (e: InterruptedException) { + Thread.currentThread().interrupt() } - } catch (e: InterruptedException) { - Thread.currentThread().interrupt() } } } @@ -192,9 +195,15 @@ class LogBuffer @JvmOverloads constructor( buffer.removeFirst() } buffer.add(message as LogMessageImpl) - // Log in the background thread only if it has capacity to avoid blocking this thread - if (echoMessageQueue.remainingCapacity() > 0) { - echoMessageQueue.put(message) + // Log in the background thread only if echoMessageQueue exists and has capacity (checking + // capacity avoids the possibility of blocking this thread) + if (echoMessageQueue != null && echoMessageQueue.remainingCapacity() > 0) { + try { + echoMessageQueue.put(message) + } catch (e: InterruptedException) { + // the background thread has been shut down, so just log on this one + echoToDesiredEndpoints(message) + } } else { echoToDesiredEndpoints(message) } diff --git a/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTracker.kt b/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTracker.kt index 3022f4b42a42c..8cda4236bc872 100644 --- a/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTracker.kt +++ b/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTracker.kt @@ -29,4 +29,9 @@ interface LogcatEchoTracker { * Whether [tagName] should echo messages of [level] or higher to logcat. */ fun isTagLoggable(tagName: String, level: LogLevel): Boolean + + /** + * Whether to log messages in a background thread. + */ + val logInBackgroundThread: Boolean } diff --git a/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerDebug.kt b/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerDebug.kt index 23942e1d6e3c5..91734cc361b0c 100644 --- a/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerDebug.kt +++ b/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerDebug.kt @@ -41,6 +41,7 @@ class LogcatEchoTrackerDebug private constructor( ) : LogcatEchoTracker { private val cachedBufferLevels: MutableMap = mutableMapOf() private val cachedTagLevels: MutableMap = mutableMapOf() + override val logInBackgroundThread = true companion object Factory { @JvmStatic diff --git a/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerProd.kt b/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerProd.kt index 394f624a3e58d..1a4ad1907ff15 100644 --- a/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerProd.kt +++ b/packages/SystemUI/src/com/android/systemui/log/LogcatEchoTrackerProd.kt @@ -20,6 +20,8 @@ package com.android.systemui.log * Production version of [LogcatEchoTracker] that isn't configurable. */ class LogcatEchoTrackerProd : LogcatEchoTracker { + override val logInBackgroundThread = false + override fun isBufferLoggable(bufferName: String, level: LogLevel): Boolean { return level >= LogLevel.WARNING } diff --git a/packages/SystemUI/tests/src/com/android/systemui/dump/LogBufferHelper.kt b/packages/SystemUI/tests/src/com/android/systemui/dump/LogBufferHelper.kt index 2cb19393d2c60..0720bdb065567 100644 --- a/packages/SystemUI/tests/src/com/android/systemui/dump/LogBufferHelper.kt +++ b/packages/SystemUI/tests/src/com/android/systemui/dump/LogBufferHelper.kt @@ -30,6 +30,7 @@ fun logcatLogBuffer(name: String = "EchoToLogcatLogBuffer") = * A [LogcatEchoTracker] that always allows echoing to the logcat. */ class LogcatEchoTrackerAlways : LogcatEchoTracker { + override val logInBackgroundThread = false override fun isBufferLoggable(bufferName: String, level: LogLevel): Boolean = true override fun isTagLoggable(tagName: String, level: LogLevel): Boolean = true }