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

Commit 56a0ea12 authored by Ned Burns's avatar Ned Burns
Browse files

Hyper-lightweight logging update 

Update to our system for high-volume logging with the goal of having any
logging call result in *zero* allocations, not even strings.

The core pieces are LogBuffer and LogMessage. LogBuffer is a simple
ring buffer that holds instances of LogMessage. LogMessages store
data related the thing they're logging, but in a generic way that
allows them to be reused across ALL log types.

In order to log a message, the caller must supply two things:

- The _initializer_, a function that stores data on a LogMessage
- The _printer_, a function that converts a LogMessage containing the
stored data into a human-readable string.

When a message is logged, the initializer is called on a newly-obtained
instance of LogMessage. The printer is also stored on the message and
the message itself is inserted into the buffer. Later, when the message
needs to be dumped, the printer is called on the message instance to
create a human-readable string.

Using features of Kotlin, we can inline calls to the initializer so the
function is effectively erased. The printers cannot be erased (we need
to maintain a reference to them) and so each printer requires a (small)
classdef. However, because the printers are stateless, we only ever need
one instance copy per printer.

Advantages of this system:
- Lightweight: no-allocation logging (still some overhead, but it's
very slight).
- Ease of use: easy to add new logs. Log-generating code is easy to
read.
- Closer match to logcat: system uses TAG and logcat levels (VERBOSE,
etc)
- Finer-grained control over debugging: Can control which tags and/or
buffers log to logcat and at what logging level (VERBOSE, etc).

Disadvantages:
- Each log type requires the creation of an anonymous class def (the
printer function). With a ton of such class defs, our code might get
bloated (it's unlikely for us to reach this point, however).
- Easy to accidentally write a log message that triggers an allocation
(if your printer function captures any outside scope, such as one of the
original log parameters, then the system will need to instantiate a new
instance of the printer function for each call instead of reusing a
singleton static instance).

Test: manual
Change-Id: I2c7c272cda4ce61d56427ab1d6eb270d9365b325
parent 617b3b71

packages/SystemUI/src/com/android/systemui/dagger/SystemUIModule.java

+7 −3
Original line number Diff line number Diff line
@@ -27,6 +27,7 @@ import com.android.systemui.BootCompleteCacheImpl; 
import com.android.systemui.DumpController;

import com.android.systemui.assist.AssistModule;

import com.android.systemui.dagger.qualifiers.Main;

import com.android.systemui.log.dagger.LogModule;

import com.android.systemui.model.SysUiState;

import com.android.systemui.plugins.statusbar.StatusBarStateController;

import com.android.systemui.recents.Recents;
@@ -59,9 +60,12 @@ import dagger.Provides; 
 * A dagger module for injecting components of System UI that are not overridden by the System UI

 * implementation.

 */

@Module(includes = {AssistModule.class,

@Module(includes = {

            AssistModule.class,

            ConcurrencyModule.class,

                    PeopleHubModule.class},

            LogModule.class,

            PeopleHubModule.class,

        },

        subcomponents = {StatusBarComponent.class, NotificationRowComponent.class})

public abstract class SystemUIModule {

packages/SystemUI/src/com/android/systemui/log/LogBuffer.kt

0 → 100644
+213 −0
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.util.Log

import com.android.systemui.DumpController

import com.android.systemui.Dumpable

import com.android.systemui.log.dagger.LogModule

import java.text.SimpleDateFormat

import java.util.ArrayDeque

import java.util.Locale



/**

 * A simple ring buffer of recyclable log messages

 *

 * The goal of this class is to enable logging that is both extremely chatty and extremely

 * lightweight. If done properly, logging a message will not result in any heap allocations or

 * string generation. Messages are only converted to strings if the log is actually dumped (usually

 * as the result of taking a bug report).

 *

 * You can dump the entire buffer at any time by running:

 *

 * ```

 * $ adb shell dumpsys activity service com.android.systemui/.SystemUIService \

 *      dependency DumpController <bufferName>

 * ```

 *

 * where `bufferName` is the (case-sensitive) [name] passed to the constructor.

 *

 * By default, only messages of WARN level or higher are echoed to logcat, but this can be adjusted

 * locally (usually for debugging purposes).

 *

 * To enable logcat echoing for an entire buffer:

 *

 * ```

 * $ adb shell settings put global systemui/buffer/<bufferName> <level>

 * ```

 *

 * To enable logcat echoing for a specific tag:

 *

 * ```

 * $ adb shell settings put global systemui/tag/<tag> <level>

 * ```

 *

 * In either case, `level` can be any of `verbose`, `debug`, `info`, `warn`, `error`, `assert`, or

 * the first letter of any of the previous.

 *

 * Buffers are provided by [LogModule].

 *

 * @param name The name of this buffer

 * @param maxLogs The maximum number of messages to keep in memory at any one time, including the

 * unused pool.

 * @param poolSize The maximum amount that the size of the buffer is allowed to flex in response to

 * sequential calls to [document] that aren't immediately followed by a matching call to [push].

 */

class LogBuffer(

    private val name: String,

    private val maxLogs: Int,

    private val poolSize: Int,

    private val logcatEchoTracker: LogcatEchoTracker

) {

    private val buffer: ArrayDeque<LogMessageImpl> = ArrayDeque()



    fun attach(dumpController: DumpController) {

        dumpController.registerDumpable(name, onDump)

    }



    /**

     * Logs a message to the log buffer

     *

     * May also log the message to logcat if echoing is enabled for this buffer or tag.

     *

     * The actual string of the log message is not constructed until it is needed. To accomplish

     * this, logging a message is a two-step process. First, a fresh instance  of [LogMessage] is

     * obtained and is passed to the [initializer]. The initializer stores any relevant data on the

     * message's fields. The message is then inserted into the buffer where it waits until it is

     * either pushed out by newer messages or it needs to printed. If and when this latter moment

     * occurs, the [printer] function is called on the message. It reads whatever data the

     * initializer stored and converts it to a human-readable log message.

     *

     * @param tag A string of at most 23 characters, used for grouping logs into categories or

     * subjects. If this message is echoed to logcat, this will be the tag that is used.

     * @param level Which level to log the message at, both to the buffer and to logcat if it's

     * echoed. In general, a module should split most of its logs into either INFO or DEBUG level.

     * INFO level should be reserved for information that other parts of the system might care

     * about, leaving the specifics of code's day-to-day operations to DEBUG.

     * @param initializer A function that will be called immediately to store relevant data on the

     * log message. The value of `this` will be the LogMessage to be initialized.

     * @param printer A function that will be called if and when the message needs to be dumped to

     * logcat or a bug report. It should read the data stored by the initializer and convert it to

     * a human-readable string. The value of `this` will be the LogMessage to be printed.

     * **IMPORTANT:** The printer should ONLY ever reference fields on the LogMessage and NEVER any

     * variables in its enclosing scope. Otherwise, the runtime will need to allocate a new instance

     * of the printer for each call, thwarting our attempts at avoiding any sort of allocation.

     */

    inline fun log(

        tag: String,

        level: LogLevel,

        initializer: LogMessage.() -> Unit,

        noinline printer: LogMessage.() -> String

    ) {

        val message = obtain(tag, level, printer)

        initializer(message)

        push(message)

    }



    /**

     * Same as [log], but doesn't push the message to the buffer. Useful if you need to supply a

     * "reason" for doing something (the thing you supply the reason to will presumably call [push]

     * on that message at some point).

     */

    inline fun document(

        tag: String,

        level: LogLevel,

        initializer: LogMessage.() -> Unit,

        noinline printer: LogMessage.() -> String

    ): LogMessage {

        val message = obtain(tag, level, printer)

        initializer(message)

        return message

    }



    /**

     * Obtains an instance of [LogMessageImpl], usually from the object pool. If the pool has been

     * exhausted, creates a new instance.

     *

     * In general, you should call [log] or [document] instead of this method.

     */

    fun obtain(

        tag: String,

        level: LogLevel,

        printer: (LogMessage) -> String

    ): LogMessageImpl {

        val message = synchronized(buffer) {

            if (buffer.size > maxLogs - poolSize) {

                buffer.removeFirst()

            } else {

                LogMessageImpl.create()

            }

        }

        message.reset(tag, level, System.currentTimeMillis(), printer)

        return message

    }



    /**

     * Pushes a message into buffer, possibly evicting an older message if the buffer is full.

     */

    fun push(message: LogMessage) {

        synchronized(buffer) {

            if (buffer.size == maxLogs) {

                Log.e(TAG, "LogBuffer $name has exceeded its pool size")

                buffer.removeFirst()

            }

            buffer.add(message as LogMessageImpl)

            if (logcatEchoTracker.isBufferLoggable(name, message.level) ||

                    logcatEchoTracker.isTagLoggable(message.tag, message.level)) {

                echoToLogcat(message)

            }

        }

    }



    /** Converts the entire buffer to a newline-delimited string */

    fun dump(): String {

        synchronized(buffer) {

            val sb = StringBuilder()

            for (message in buffer) {

                dumpMessage(message, sb)

            }

            return sb.toString()

        }

    }



    private fun dumpMessage(message: LogMessage, sb: StringBuilder) {

        sb.append(DATE_FORMAT.format(message.timestamp))

                .append(" ").append(message.level)

                .append(" ").append(message.tag)

                .append(" ").append(message.printer(message))

                .append("\n")

    }



    private fun echoToLogcat(message: LogMessage) {

        val strMessage = message.printer(message)

        when (message.level) {

            LogLevel.VERBOSE -> Log.v(message.tag, strMessage)

            LogLevel.DEBUG -> Log.d(message.tag, strMessage)

            LogLevel.INFO -> Log.i(message.tag, strMessage)

            LogLevel.WARNING -> Log.w(message.tag, strMessage)

            LogLevel.ERROR -> Log.e(message.tag, strMessage)

            LogLevel.WTF -> Log.wtf(message.tag, strMessage)

        }

    }



    private val onDump = Dumpable { _, pw, _ ->

        pw.println(dump())

    }

}



private const val TAG = "LogBuffer"

private val DATE_FORMAT = SimpleDateFormat("MM-dd HH:mm:ss.S", Locale.US)

packages/SystemUI/src/com/android/systemui/log/LogLevel.kt

0 → 100644
+31 −0
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.util.Log



/**

 * Enum version of @Log.Level

 */

enum class LogLevel(@Log.Level val nativeLevel: Int) {

    VERBOSE(Log.VERBOSE),

    DEBUG(Log.DEBUG),

    INFO(Log.INFO),

    WARNING(Log.WARN),

    ERROR(Log.ERROR),

    WTF(Log.ASSERT)

}

packages/SystemUI/src/com/android/systemui/log/LogMessage.kt

0 → 100644
+47 −0
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



/**

 * Generic data class for storing messages logged to a [LogBuffer]

 *

 * Each LogMessage has a few standard fields ([level], [tag], and [timestamp]). The rest are generic

 * data slots that may or may not be used, depending on the nature of the specific message being

 * logged.

 *

 * When a message is logged, the code doing the logging stores data in one or more of the generic

 * fields ([str1], [int1], etc). When it comes time to dump the message to logcat/bugreport/etc, the

 * [printer] function reads the data stored in the generic fields and converts that to a human-

 * readable string. Thus, for every log type there must be a specialized initializer function that

 * stores data specific to that log type and a specialized printer function that prints that data.

 *

 * See [LogBuffer.log] for more information.

 */

interface LogMessage {

    val level: LogLevel

    val tag: String

    val timestamp: Long

    val printer: LogMessage.() -> String



    var str1: String?

    var str2: String?

    var str3: String?

    var int1: Int

    var int2: Int

    var long1: Long

    var double1: Double

}

packages/SystemUI/src/com/android/systemui/log/LogMessageImpl.kt

0 → 100644
+74 −0
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



/**

 * Recyclable implementation of [LogMessage].

 */

data class LogMessageImpl(

    override var level: LogLevel,

    override var tag: String,

    override var timestamp: Long,

    override var printer: LogMessage.() -> String,

    override var str1: String?,

    override var str2: String?,

    override var str3: String?,

    override var int1: Int,

    override var int2: Int,

    override var long1: Long,

    override var double1: Double

) : LogMessage {



    fun reset(

        tag: String,

        level: LogLevel,

        timestamp: Long,

        renderer: LogMessage.() -> String

    ) {

        this.level = level

        this.tag = tag

        this.timestamp = timestamp

        this.printer = renderer

        str1 = null

        str2 = null

        str3 = null

        int1 = 0

        int2 = 0

        long1 = 0

        double1 = 0.0

    }



    companion object Factory {

        fun create(): LogMessageImpl {

            return LogMessageImpl(

                    LogLevel.DEBUG,

                    DEFAULT_TAG,

                    0,

                    DEFAULT_RENDERER,

                    null,

                    null,

                    null,

                    0,

                    0,

                    0,

                    0.0)

        }

    }

}



private const val DEFAULT_TAG = "UnknownTag"

private val DEFAULT_RENDERER: LogMessage.() -> String = { "Unknown message: $this" }