Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit e24611f4 authored by Ned Burns's avatar Ned Burns
Browse files

Refactor LogBuffer to no longer use threads/locks

Previously, we were spinning up a new logging thread for each log
buffer. Each thread would maintain a queue of work and pull items off to
be logged as they came in.

In the old system, the "loggability" of a buffer or tag was determined
on-demand. If a new tag came in that we hadn't seen before, we check
GlobalSettings to see if we had an entry for that tag. This (a) resulted
in a bunch of needless reads of Settings and (b) required a blocking IPC
each time we needed to perform a read (thus the need to offload the work
to background threads).

In the new system, all "loggability" overrides are read once, when
SystemUI starts up. The actual act of checking the loggability of an
individual tag or buffer is no longer blocking, and so can be done
without the need for a background thread. The one downside to this
approach is that there is a period, at the very beginning of SystemUI
startup, in which the overrides have not yet been loaded. A future CL
may create a temporary buffer that messages can be held in while waiting
for this initial read.

Finally, this CL creates a new statusbar command that can be used to
manipulate and view echoing overrides. Developers no longer need to
write directly to global settings

Flag: None
Bug: 235365671
Test: atest
Change-Id: I974da6a3651a2c7f3f2e2dd02f6748c4b63a5750
parent bdf96b34
Loading
Loading
Loading
Loading
+21 −55
Original line number Diff line number Diff line
@@ -26,9 +26,6 @@ import com.android.systemui.log.core.MessageInitializer
import com.android.systemui.log.core.MessagePrinter
import com.google.errorprone.annotations.CompileTimeConstant
import java.io.PrintWriter
import java.util.concurrent.ArrayBlockingQueue
import java.util.concurrent.BlockingQueue
import kotlin.concurrent.thread
import kotlin.math.max

/**
@@ -51,12 +48,12 @@ import kotlin.math.max
 *
 * To enable logcat echoing for an entire buffer:
 * ```
 * $ adb shell settings put global systemui/buffer/<bufferName> <level>
 * $ adb shell cmd statusbar echo -b <bufferName>:<level>
 * ```
 *
 * To enable logcat echoing for a specific tag:
 * ```
 * $ adb shell settings put global systemui/tag/<tag> <level>
 * $ adb shell cmd statusbar echo -t <tagName>:<level>
 * ```
 *
 * In either case, `level` can be any of `verbose`, `debug`, `info`, `warn`, `error`, `assert`, or
@@ -81,23 +78,6 @@ constructor(
) : MessageBuffer {
    private val buffer = RingBuffer(maxSize) { LogMessageImpl.create() }

    private val echoMessageQueue: BlockingQueue<LogMessage>? =
        if (logcatEchoTracker.logInBackgroundThread) ArrayBlockingQueue(10) else null

    init {
        if (logcatEchoTracker.logInBackgroundThread && echoMessageQueue != null) {
            thread(start = true, name = "LogBuffer-$name", priority = Thread.NORM_PRIORITY) {
                try {
                    while (true) {
                        echoToDesiredEndpoints(echoMessageQueue.take())
                    }
                } catch (e: InterruptedException) {
                    Thread.currentThread().interrupt()
                }
            }
        }
    }

    var frozen = false
        private set

@@ -204,26 +184,26 @@ constructor(
        if (!mutable) {
            return
        }
        // 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)
        }
    }

    /** Sends message to echo after determining whether to use Logcat and/or systrace. */
    private fun echoToDesiredEndpoints(message: LogMessage) {
        val includeInLogcat =
            logcatEchoTracker.isBufferLoggable(name, message.level) ||
                logcatEchoTracker.isTagLoggable(message.tag, message.level)
        echo(message, toLogcat = includeInLogcat, toSystrace = systrace)

        val includeInSystrace = systrace && Trace.isTagEnabled(Trace.TRACE_TAG_APP)

        if (includeInLogcat || includeInSystrace) {
            val strMessage = message.messagePrinter(message)
            if (includeInLogcat) {
                echoToLogcat(message, strMessage)
            }
            if (includeInSystrace) {
                echoToSystrace(message.level, message.tag, strMessage)
            }
        }
    }

    /** Converts the entire buffer to a newline-delimited string */
@@ -263,27 +243,13 @@ constructor(
        }
    }

    private fun echo(message: LogMessage, toLogcat: Boolean, toSystrace: Boolean) {
        if (toLogcat || toSystrace) {
            val strMessage = message.messagePrinter(message)
            if (toSystrace) {
                echoToSystrace(message, strMessage)
            }
            if (toLogcat) {
                echoToLogcat(message, strMessage)
            }
        }
    }

    private fun echoToSystrace(message: LogMessage, strMessage: String) {
        if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) {
    private fun echoToSystrace(level: LogLevel, tag: String, strMessage: String) {
        Trace.instantForTrack(
            Trace.TRACE_TAG_APP,
            "UI Events",
                "$name - ${message.level.shortString} ${message.tag}: $strMessage"
            "$name - ${level.shortString} $tag: $strMessage"
        )
    }
    }

    private fun echoToLogcat(message: LogMessage, strMessage: String) {
        when (message.level) {
+0 −3
Original line number Diff line number Diff line
@@ -25,7 +25,4 @@ 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
}
+0 −140
Original line number Diff line number Diff line
/*
 * Copyright (C) 2020 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.log

import android.content.ContentResolver
import android.database.ContentObserver
import android.net.Uri
import android.os.Handler
import android.os.Looper
import android.os.Trace
import android.provider.Settings
import com.android.systemui.log.core.LogLevel

/**
 * Version of [LogcatEchoTracker] for debuggable builds
 *
 * The log level of individual buffers or tags can be controlled via global settings:
 * ```
 * # Echo any message to <bufferName> of <level> or higher
 * $ adb shell settings put global systemui/buffer/<bufferName> <level>
 *
 * # Echo any message of <tag> and of <level> or higher
 * $ adb shell settings put global systemui/tag/<tag> <level>
 * ```
 */
class LogcatEchoTrackerDebug private constructor(private val contentResolver: ContentResolver) :
    LogcatEchoTracker {
    private val cachedBufferLevels: MutableMap<String, LogLevel> = mutableMapOf()
    private val cachedTagLevels: MutableMap<String, LogLevel> = mutableMapOf()
    override val logInBackgroundThread = true

    companion object Factory {
        @JvmStatic
        fun create(contentResolver: ContentResolver, mainLooper: Looper): LogcatEchoTrackerDebug {
            val tracker = LogcatEchoTrackerDebug(contentResolver)
            tracker.attach(mainLooper)
            return tracker
        }
    }

    private fun clearCache() {
        Trace.beginSection("LogcatEchoTrackerDebug#clearCache")
        cachedBufferLevels.clear()
        Trace.endSection()
    }

    private fun attach(mainLooper: Looper) {
        Trace.beginSection("LogcatEchoTrackerDebug#attach")
        contentResolver.registerContentObserver(
            Settings.Global.getUriFor(BUFFER_PATH),
            true,
            object : ContentObserver(Handler(mainLooper)) {
                override fun onChange(selfChange: Boolean, uri: Uri?) {
                    super.onChange(selfChange, uri)
                    clearCache()
                }
            }
        )

        contentResolver.registerContentObserver(
            Settings.Global.getUriFor(TAG_PATH),
            true,
            object : ContentObserver(Handler(mainLooper)) {
                override fun onChange(selfChange: Boolean, uri: Uri?) {
                    super.onChange(selfChange, uri)
                    clearCache()
                }
            }
        )
        Trace.endSection()
    }

    /** Whether [bufferName] should echo messages of [level] or higher to logcat. */
    @Synchronized
    override fun isBufferLoggable(bufferName: String, level: LogLevel): Boolean {
        return level.ordinal >= getLogLevel(bufferName, BUFFER_PATH, cachedBufferLevels).ordinal
    }

    /** Whether [tagName] should echo messages of [level] or higher to logcat. */
    @Synchronized
    override fun isTagLoggable(tagName: String, level: LogLevel): Boolean {
        return level >= getLogLevel(tagName, TAG_PATH, cachedTagLevels)
    }

    private fun getLogLevel(
        name: String,
        path: String,
        cache: MutableMap<String, LogLevel>
    ): LogLevel {
        return cache[name] ?: readSetting("$path/$name").also { cache[name] = it }
    }

    private fun readSetting(path: String): LogLevel {
        return try {
            Trace.beginSection("LogcatEchoTrackerDebug#readSetting")
            parseProp(Settings.Global.getString(contentResolver, path))
        } catch (_: Settings.SettingNotFoundException) {
            DEFAULT_LEVEL
        } finally {
            Trace.endSection()
        }
    }

    private fun parseProp(propValue: String?): LogLevel {
        return when (propValue?.lowercase()) {
            "verbose" -> LogLevel.VERBOSE
            "v" -> LogLevel.VERBOSE
            "debug" -> LogLevel.DEBUG
            "d" -> LogLevel.DEBUG
            "info" -> LogLevel.INFO
            "i" -> LogLevel.INFO
            "warning" -> LogLevel.WARNING
            "warn" -> LogLevel.WARNING
            "w" -> LogLevel.WARNING
            "error" -> LogLevel.ERROR
            "e" -> LogLevel.ERROR
            "assert" -> LogLevel.WTF
            "wtf" -> LogLevel.WTF
            else -> DEFAULT_LEVEL
        }
    }
}

private val DEFAULT_LEVEL = LogLevel.WARNING
private const val BUFFER_PATH = "systemui/buffer"
private const val TAG_PATH = "systemui/tag"
+7 −8
Original line number Diff line number Diff line
@@ -16,17 +16,14 @@

package com.android.systemui.log.dagger;

import android.content.ContentResolver;
import android.os.Build;
import android.os.Looper;

import com.android.systemui.dagger.SysUISingleton;
import com.android.systemui.dagger.qualifiers.Main;
import com.android.systemui.log.LogBuffer;
import com.android.systemui.log.LogBufferFactory;
import com.android.systemui.log.LogcatEchoTracker;
import com.android.systemui.log.LogcatEchoTrackerDebug;
import com.android.systemui.log.LogcatEchoTrackerProd;
import com.android.systemui.log.echo.LogcatEchoTrackerDebug;
import com.android.systemui.log.echo.LogcatEchoTrackerProd;
import com.android.systemui.log.table.TableLogBuffer;
import com.android.systemui.log.table.TableLogBufferFactory;
import com.android.systemui.qs.QSFragmentLegacy;
@@ -36,6 +33,7 @@ import com.android.systemui.statusbar.notification.NotifPipelineFlags;
import com.android.systemui.util.Compile;
import com.android.systemui.util.wakelock.WakeLockLog;

import dagger.Lazy;
import dagger.Module;
import dagger.Provides;

@@ -349,10 +347,11 @@ public class LogModule {
    @Provides
    @SysUISingleton
    public static LogcatEchoTracker provideLogcatEchoTracker(
            ContentResolver contentResolver,
            @Main Looper looper) {
            Lazy<LogcatEchoTrackerDebug> lazyTrackerDebug) {
        if (Build.isDebuggable()) {
            return LogcatEchoTrackerDebug.create(contentResolver, looper);
            LogcatEchoTrackerDebug trackerDebug = lazyTrackerDebug.get();
            trackerDebug.start();
            return trackerDebug;
        } else {
            return new LogcatEchoTrackerProd();
        }
+139 −0
Original line number Diff line number Diff line
/*
 * 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.log.echo

import android.util.Log
import com.android.systemui.log.core.LogLevel
import java.util.StringJoiner

/**
 * Encodes/decodes the list of tags/buffers that [LogcatEchoTrackerDebug] echoes to logcat to/from a
 * string format (that can be stored in a permanent place like a setting).
 */
class LogcatEchoSettingFormat {
    fun parseOverrides(str: String): List<LogcatEchoOverride> {
        // The format begins with a schema version specifier formatted as "<number>;", followed by
        // the encoded data.

        // First, read the schema version:
        val split = str.split(";", limit = 2)
        if (split.size != 2) {
            Log.e(TAG, "Unrecognized echo override format: \"$str\"")
            return emptyList()
        }
        val formatVersion =
            try {
                split[0].toInt()
            } catch (e: NumberFormatException) {
                Log.e(TAG, "Unrecognized echo override formation version: ${split[0]}")
                return emptyList()
            }

        // Then, dispatch to the appropriate parser based on format
        return when (formatVersion) {
            0 -> parseOverridesV0(split[1])
            else -> {
                Log.e(TAG, "Unrecognized echo override formation version: $formatVersion")
                emptyList()
            }
        }
    }

    fun stringifyOverrides(
        overrides: List<LogcatEchoOverride>,
    ): String {
        return stringifyOverridesV0(overrides)
    }

    private fun parseOverridesV0(
        str: String,
    ): List<LogcatEchoOverride> {
        // Format: <type>;<name>;<level>(;...)
        // Where
        // <type> = "b" | "t"
        // <name> = string
        // <level> = "v" | "d" | "i" | "w" | "e" | "!"

        val list = mutableListOf<LogcatEchoOverride>()

        // Split on any ";" that is not preceded by a "\"
        val pieces = str.split(Regex("""(?<!\\);"""))

        var i = 0
        while (i < pieces.size) {
            if (pieces.size - i < 3) {
                break
            }
            val type =
                when (pieces[i]) {
                    "b" -> EchoOverrideType.BUFFER
                    "t" -> EchoOverrideType.TAG
                    else -> break
                }
            val name = pieces[i + 1].replace("\\;", ";")
            val level =
                when (pieces[i + 2]) {
                    "v" -> LogLevel.VERBOSE
                    "d" -> LogLevel.DEBUG
                    "i" -> LogLevel.INFO
                    "w" -> LogLevel.WARNING
                    "e" -> LogLevel.ERROR
                    "!" -> LogLevel.WTF
                    else -> break
                }
            i += 3

            list.add(LogcatEchoOverride(type, name, level))
        }

        return list
    }

    private fun stringifyOverridesV0(
        overrides: List<LogcatEchoOverride>,
    ): String {
        val sj = StringJoiner(";")

        sj.add("0")

        for (override in overrides) {
            sj.add(
                when (override.type) {
                    EchoOverrideType.BUFFER -> "b"
                    EchoOverrideType.TAG -> "t"
                }
            )
            sj.add(override.name.replace(";", "\\;"))
            sj.add(
                when (override.level) {
                    LogLevel.VERBOSE -> "v"
                    LogLevel.DEBUG -> "d"
                    LogLevel.INFO -> "i"
                    LogLevel.WARNING -> "w"
                    LogLevel.ERROR -> "e"
                    LogLevel.WTF -> "!"
                }
            )
        }

        return sj.toString()
    }
}

data class LogcatEchoOverride(val type: EchoOverrideType, val name: String, val level: LogLevel)

private const val TAG = "EchoFormat"
Loading