1 /* 2 * Copyright (C) 2020 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.log 18 19 import android.os.Trace 20 import android.util.Log 21 import com.android.systemui.common.buffer.RingBuffer 22 import com.android.systemui.log.core.LogLevel 23 import com.android.systemui.log.core.LogMessage 24 import com.android.systemui.log.core.MessageBuffer 25 import com.android.systemui.log.core.MessageInitializer 26 import com.android.systemui.log.core.MessagePrinter 27 import com.google.errorprone.annotations.CompileTimeConstant 28 import java.io.PrintWriter 29 import kotlin.math.max 30 31 /** 32 * A simple ring buffer of recyclable log messages 33 * 34 * The goal of this class is to enable logging that is both extremely chatty and extremely 35 * lightweight. If done properly, logging a message will not result in any heap allocations or 36 * string generation. Messages are only converted to strings if the log is actually dumped (usually 37 * as the result of taking a bug report). 38 * 39 * You can dump the entire buffer at any time by running: 40 * ``` 41 * $ adb shell dumpsys activity service com.android.systemui/.SystemUIService <bufferName> 42 * ``` 43 * 44 * ...where `bufferName` is the (case-sensitive) [name] passed to the constructor. 45 * 46 * By default, only messages of WARN level or higher are echoed to logcat, but this can be adjusted 47 * locally (usually for debugging purposes). 48 * 49 * To enable logcat echoing for an entire buffer: 50 * ``` 51 * $ adb shell cmd statusbar echo -b <bufferName>:<level> 52 * ``` 53 * 54 * To enable logcat echoing for a specific tag: 55 * ``` 56 * $ adb shell cmd statusbar echo -t <tagName>:<level> 57 * ``` 58 * 59 * In either case, `level` can be any of `verbose`, `debug`, `info`, `warn`, `error`, `assert`, or 60 * the first letter of any of the previous. 61 * 62 * In SystemUI, buffers are provided by LogModule. Instances should be created using a SysUI 63 * LogBufferFactory. 64 * 65 * @param name The name of this buffer, printed when the buffer is dumped and in some other 66 * situations. 67 * @param maxSize The maximum number of messages to keep in memory at any one time. Buffers start 68 * out empty and grow up to [maxSize] as new messages are logged. Once the buffer's size reaches 69 * the maximum, it behaves like a ring buffer. 70 */ 71 class LogBuffer 72 @JvmOverloads 73 constructor( 74 private val name: String, 75 private val maxSize: Int, 76 private val logcatEchoTracker: LogcatEchoTracker, 77 private val systrace: Boolean = true, 78 private val systraceTrackName: String = DEFAULT_LOGBUFFER_TRACK_NAME, 79 ) : MessageBuffer { <lambda>null80 private val buffer = RingBuffer(maxSize) { LogMessageImpl.create() } 81 82 var frozen = false 83 private set 84 85 private val mutable 86 get() = !frozen && maxSize > 0 87 88 /** 89 * Logs a message to the log buffer 90 * 91 * May also log the message to logcat if echoing is enabled for this buffer or tag. 92 * 93 * The actual string of the log message is not constructed until it is needed. To accomplish 94 * this, logging a message is a two-step process. First, a fresh instance of [LogMessage] is 95 * obtained and is passed to the [messageInitializer]. The initializer stores any relevant data 96 * on the message's fields. The message is then inserted into the buffer where it waits until it 97 * is either pushed out by newer messages or it needs to printed. If and when this latter moment 98 * occurs, the [messagePrinter] function is called on the message. It reads whatever data the 99 * initializer stored and converts it to a human-readable log message. 100 * 101 * @param tag A string of at most 23 characters, used for grouping logs into categories or 102 * subjects. If this message is echoed to logcat, this will be the tag that is used. 103 * @param level Which level to log the message at, both to the buffer and to logcat if it's 104 * echoed. In general, a module should split most of its logs into either INFO or DEBUG level. 105 * INFO level should be reserved for information that other parts of the system might care 106 * about, leaving the specifics of code's day-to-day operations to DEBUG. 107 * @param messageInitializer A function that will be called immediately to store relevant data 108 * on the log message. The value of `this` will be the LogMessage to be initialized. 109 * @param messagePrinter A function that will be called if and when the message needs to be 110 * dumped to logcat or a bug report. It should read the data stored by the initializer and 111 * convert it to a human-readable string. The value of `this` will be the LogMessage to be 112 * printed. **IMPORTANT:** The printer should ONLY ever reference fields on the LogMessage and 113 * NEVER any variables in its enclosing scope. Otherwise, the runtime will need to allocate a 114 * new instance of the printer for each call, thwarting our attempts at avoiding any sort of 115 * allocation. 116 * @param exception Provide any exception that need to be logged. This is saved as 117 * [LogMessage.exception] 118 */ 119 @JvmOverloads lognull120 inline fun log( 121 tag: String, 122 level: LogLevel, 123 messageInitializer: MessageInitializer, 124 noinline messagePrinter: MessagePrinter, 125 exception: Throwable? = null, 126 ) { 127 val message = obtain(tag, level, messagePrinter, exception) 128 messageInitializer(message) 129 commit(message) 130 } 131 132 /** 133 * Logs a compile-time string constant [message] to the log buffer. Use sparingly. 134 * 135 * May also log the message to logcat if echoing is enabled for this buffer or tag. This is for 136 * simpler use-cases where [message] is a compile time string constant. For use-cases where the 137 * log message is built during runtime, use the [LogBuffer.log] overloaded method that takes in 138 * an initializer and a message printer. 139 * 140 * Log buffers are limited by the number of entries, so logging more frequently will limit the 141 * time window that the LogBuffer covers in a bug report. Richer logs, on the other hand, make a 142 * bug report more actionable, so using the [log] with a messagePrinter to add more detail to 143 * every log may do more to improve overall logging than adding more logs with this method. 144 */ 145 @JvmOverloads lognull146 fun log( 147 tag: String, 148 level: LogLevel, 149 @CompileTimeConstant message: String, 150 exception: Throwable? = null, 151 ) = log(tag, level, { str1 = message }, { str1!! }, exception) 152 153 /** 154 * You should call [log] instead of this method. 155 * 156 * Obtains the next [LogMessage] from the ring buffer. If the buffer is not yet at max size, 157 * grows the buffer by one. 158 * 159 * After calling [obtain], the message will now be at the end of the buffer. The caller must 160 * store any relevant data on the message and then call [commit]. 161 */ 162 @Synchronized obtainnull163 override fun obtain( 164 tag: String, 165 level: LogLevel, 166 messagePrinter: MessagePrinter, 167 exception: Throwable?, 168 ): LogMessage { 169 if (!mutable) { 170 return FROZEN_MESSAGE 171 } 172 val message = buffer.advance() 173 message.reset(tag, level, System.currentTimeMillis(), messagePrinter, exception) 174 return message 175 } 176 177 /** 178 * You should call [log] instead of this method. 179 * 180 * After acquiring a message via [obtain], call this method to signal to the buffer that you 181 * have finished filling in its data fields. The message will be echoed to logcat if necessary. 182 */ 183 @Synchronized commitnull184 override fun commit(message: LogMessage) { 185 if (!mutable) { 186 return 187 } 188 echoToDesiredEndpoints(message) 189 } 190 191 /** Sends message to echo after determining whether to use Logcat and/or systrace. */ echoToDesiredEndpointsnull192 private fun echoToDesiredEndpoints(message: LogMessage) { 193 val includeInLogcat = 194 logcatEchoTracker.isBufferLoggable(name, message.level) || 195 logcatEchoTracker.isTagLoggable(message.tag, message.level) 196 197 val includeInSystrace = systrace && Trace.isTagEnabled(Trace.TRACE_TAG_APP) 198 199 if (includeInLogcat || includeInSystrace) { 200 val strMessage = message.messagePrinter(message) 201 if (includeInLogcat) { 202 echoToLogcat(message, strMessage) 203 } 204 if (includeInSystrace) { 205 echoToSystrace(message.level, message.tag, strMessage) 206 } 207 } 208 } 209 210 /** Converts the entire buffer to a newline-delimited string */ 211 @Synchronized dumpnull212 fun dump(pw: PrintWriter, tailLength: Int) { 213 val iterationStart = 214 if (tailLength <= 0) { 215 0 216 } else { 217 max(0, buffer.size - tailLength) 218 } 219 220 for (i in iterationStart until buffer.size) { 221 buffer[i].dump(pw) 222 } 223 } 224 225 /** 226 * "Freezes" the contents of the buffer, making it immutable until [unfreeze] is called. Calls 227 * to [log], [obtain], and [commit] will not affect the buffer and will return dummy values if 228 * necessary. 229 */ 230 @Synchronized freezenull231 fun freeze() { 232 if (!frozen) { 233 log(TAG, LogLevel.DEBUG, { str1 = name }, { "$str1 frozen" }) 234 frozen = true 235 } 236 } 237 238 /** Undoes the effects of calling [freeze]. */ 239 @Synchronized unfreezenull240 fun unfreeze() { 241 if (frozen) { 242 frozen = false 243 log(TAG, LogLevel.DEBUG, { str1 = name }, { "$str1 unfrozen" }) 244 } 245 } 246 echoToSystracenull247 private fun echoToSystrace(level: LogLevel, tag: String, strMessage: String) { 248 if (!Trace.isEnabled()) return 249 Trace.instantForTrack( 250 Trace.TRACE_TAG_APP, 251 systraceTrackName, 252 "$name - ${level.shortString} $tag: $strMessage", 253 ) 254 } 255 echoToLogcatnull256 private fun echoToLogcat(message: LogMessage, strMessage: String) { 257 when (message.level) { 258 LogLevel.VERBOSE -> Log.v(message.tag, strMessage, message.exception) 259 LogLevel.DEBUG -> Log.d(message.tag, strMessage, message.exception) 260 LogLevel.INFO -> Log.i(message.tag, strMessage, message.exception) 261 LogLevel.WARNING -> Log.w(message.tag, strMessage, message.exception) 262 LogLevel.ERROR -> Log.e(message.tag, strMessage, message.exception) 263 LogLevel.WTF -> Log.wtf(message.tag, strMessage, message.exception) 264 } 265 } 266 267 companion object { 268 const val DEFAULT_LOGBUFFER_TRACK_NAME = "UI Events" 269 } 270 } 271 272 private const val TAG = "LogBuffer" 273 private val FROZEN_MESSAGE = LogMessageImpl.create() 274