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