1 /* 2 * Copyright (C) 2022 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.table 18 19 import android.icu.text.SimpleDateFormat 20 import android.os.Trace 21 import com.android.systemui.Dumpable 22 import com.android.systemui.common.buffer.RingBuffer 23 import com.android.systemui.dagger.qualifiers.Background 24 import com.android.systemui.log.LogcatEchoTracker 25 import com.android.systemui.log.core.LogLevel 26 import com.android.systemui.plugins.log.TableLogBufferBase 27 import com.android.systemui.util.time.SystemClock 28 import java.io.PrintWriter 29 import java.util.Locale 30 import kotlinx.coroutines.CoroutineDispatcher 31 import kotlinx.coroutines.CoroutineScope 32 import kotlinx.coroutines.channels.Channel 33 import kotlinx.coroutines.launch 34 35 /** 36 * A logger that logs changes in table format. 37 * 38 * Some parts of System UI maintain a lot of pieces of state at once. 39 * [com.android.systemui.log.LogBuffer] allows us to easily log change events: 40 * - 10-10 10:10:10.456: state2 updated to newVal2 41 * - 10-10 10:11:00.000: stateN updated to StateN(val1=true, val2=1) 42 * - 10-10 10:11:02.123: stateN updated to StateN(val1=true, val2=2) 43 * - 10-10 10:11:05.123: state1 updated to newVal1 44 * - 10-10 10:11:06.000: stateN updated to StateN(val1=false, val2=3) 45 * 46 * However, it can sometimes be more useful to view the state changes in table format: 47 * - timestamp--------- | state1- | state2- | ... | stateN.val1 | stateN.val2 48 * - ------------------------------------------------------------------------- 49 * - 10-10 10:10:10.123 | val1--- | val2--- | ... | false------ | 0----------- 50 * - 10-10 10:10:10.456 | val1--- | newVal2 | ... | false------ | 0----------- 51 * - 10-10 10:11:00.000 | val1--- | newVal2 | ... | true------- | 1----------- 52 * - 10-10 10:11:02.123 | val1--- | newVal2 | ... | true------- | 2----------- 53 * - 10-10 10:11:05.123 | newVal1 | newVal2 | ... | true------- | 2----------- 54 * - 10-10 10:11:06.000 | newVal1 | newVal2 | ... | false------ | 3----------- 55 * 56 * This class enables easy logging of the state changes in both change event format and table 57 * format. 58 * 59 * This class also enables easy logging of states that are a collection of fields. For example, 60 * stateN in the above example consists of two fields -- val1 and val2. It's useful to put each 61 * field into its own column so that ABT (Android Bug Tool) can easily highlight changes to 62 * individual fields. 63 * 64 * How it works: 65 * 1) Create an instance of this buffer via [TableLogBufferFactory]. 66 * 2) For any states being logged, implement [Diffable]. Implementing [Diffable] allows the state to 67 * only log the fields that have *changed* since the previous update, instead of always logging 68 * all fields. 69 * 3) Each time a change in a state happens, call [logDiffs]. If your state is emitted using a 70 * [Flow], you should use the [logDiffsForTable] extension function to automatically log diffs 71 * any time your flow emits a new value. 72 * 73 * When a dump occurs, there will be two dumps: 74 * 1) The change events under the dumpable name "$name-changes". 75 * 2) This class will coalesce all the diffs into a table format and log them under the dumpable 76 * name "$name-table". 77 * 78 * @param maxSize the maximum size of the buffer. Must be > 0. 79 */ 80 class TableLogBuffer( 81 maxSize: Int, 82 private val name: String, 83 private val systemClock: SystemClock, 84 private val logcatEchoTracker: LogcatEchoTracker, 85 @Background private val bgDispatcher: CoroutineDispatcher, 86 private val coroutineScope: CoroutineScope, 87 private val localLogcat: LogProxy = LogProxyDefault(), 88 ) : Dumpable, TableLogBufferBase { 89 init { 90 if (maxSize <= 0) { 91 throw IllegalArgumentException("maxSize must be > 0") 92 } 93 } 94 // For local logcat, send messages across this channel so the background job can process them 95 private val logMessageChannel = Channel<TableChange>(capacity = 10) 96 97 private val buffer = RingBuffer(maxSize) { TableChange() } 98 99 // Stores the most recently evicted value for each column name (indexed on column name). 100 // 101 // Why it's necessary: Because we use a RingBuffer of a fixed size, it's possible that a column 102 // that's logged infrequently will eventually get pushed out by a different column that's 103 // logged more frequently. Then, that infrequently-logged column isn't present in the RingBuffer 104 // at all and we have no logs that the column ever existed. This is a problem because the 105 // column's information is still relevant, valid, and may be critical to debugging issues. 106 // 107 // Fix: When a change is being evicted from the RingBuffer, we store it in this map (based on 108 // its [TableChange.getName()]. This ensures that we always have at least one value for every 109 // column ever logged. See b/272016422 for more details. 110 private val lastEvictedValues = mutableMapOf<String, TableChange>() 111 112 // A [TableRowLogger] object, re-used each time [logDiffs] is called. 113 // (Re-used to avoid object allocation.) 114 private val tempRow = 115 TableRowLoggerImpl( 116 timestamp = 0, 117 columnPrefix = "", 118 isInitial = false, 119 tableLogBuffer = this, 120 ) 121 122 /** Start this log buffer logging in the background */ 123 internal fun init() { 124 coroutineScope.launch(bgDispatcher) { 125 while (!logMessageChannel.isClosedForReceive) { 126 val log = logMessageChannel.receive() 127 echoToDesiredEndpoints(log) 128 } 129 } 130 } 131 132 /** 133 * Log the differences between [prevVal] and [newVal]. 134 * 135 * The [newVal] object's method [Diffable.logDiffs] will be used to fetch the diffs. 136 * 137 * @param columnPrefix a prefix that will be applied to every column name that gets logged. This 138 * ensures that all the columns related to the same state object will be grouped together in 139 * the table. 140 * @throws IllegalArgumentException if [columnPrefix] or column name contain "|". "|" is used as 141 * the separator token for parsing, so it can't be present in any part of the column name. 142 */ 143 @Synchronized 144 fun <T : Diffable<T>> logDiffs(columnPrefix: String, prevVal: T, newVal: T) { 145 val row = tempRow 146 row.timestamp = systemClock.currentTimeMillis() 147 row.columnPrefix = columnPrefix 148 // Because we have a prevVal and a newVal, we know that this isn't the initial log. 149 row.isInitial = false 150 newVal.logDiffs(prevVal, row) 151 } 152 153 /** 154 * Logs change(s) to the buffer using [rowInitializer]. 155 * 156 * @param rowInitializer a function that will be called immediately to store relevant data on 157 * the row. 158 * @param isInitial true if this change represents the starting value for a particular column 159 * (as opposed to a value that was updated after receiving new information). This is used to 160 * help us identify which values were just default starting values, and which values were 161 * derived from updated information. Most callers should use false for this value. 162 */ 163 @Synchronized 164 fun logChange( 165 columnPrefix: String, 166 isInitial: Boolean = false, 167 rowInitializer: (TableRowLogger) -> Unit 168 ) { 169 val row = tempRow 170 row.timestamp = systemClock.currentTimeMillis() 171 row.columnPrefix = columnPrefix 172 row.isInitial = isInitial 173 rowInitializer(row) 174 } 175 176 /** 177 * Logs a String? change. 178 * 179 * @param isInitial see [TableLogBuffer.logChange(String, Boolean, (TableRowLogger) -> Unit]. 180 */ 181 override fun logChange(prefix: String, columnName: String, value: String?, isInitial: Boolean) { 182 logChange(systemClock.currentTimeMillis(), prefix, columnName, value, isInitial) 183 } 184 185 /** 186 * Logs a boolean change. 187 * 188 * @param isInitial see [TableLogBuffer.logChange(String, Boolean, (TableRowLogger) -> Unit]. 189 */ 190 override fun logChange(prefix: String, columnName: String, value: Boolean, isInitial: Boolean) { 191 logChange(systemClock.currentTimeMillis(), prefix, columnName, value, isInitial) 192 } 193 194 /** 195 * Logs a Int change. 196 * 197 * @param isInitial see [TableLogBuffer.logChange(String, Boolean, (TableRowLogger) -> Unit]. 198 */ 199 override fun logChange(prefix: String, columnName: String, value: Int?, isInitial: Boolean) { 200 logChange(systemClock.currentTimeMillis(), prefix, columnName, value, isInitial) 201 } 202 203 // Keep these individual [logChange] methods private (don't let clients give us their own 204 // timestamps.) 205 206 private fun logChange( 207 timestamp: Long, 208 prefix: String, 209 columnName: String, 210 value: String?, 211 isInitial: Boolean, 212 ) { 213 Trace.beginSection("TableLogBuffer#logChange(string)") 214 val change = obtain(timestamp, prefix, columnName, isInitial) 215 change.set(value) 216 tryAddMessage(change) 217 Trace.endSection() 218 } 219 220 private fun logChange( 221 timestamp: Long, 222 prefix: String, 223 columnName: String, 224 value: Boolean, 225 isInitial: Boolean, 226 ) { 227 Trace.beginSection("TableLogBuffer#logChange(boolean)") 228 val change = obtain(timestamp, prefix, columnName, isInitial) 229 change.set(value) 230 tryAddMessage(change) 231 Trace.endSection() 232 } 233 234 private fun logChange( 235 timestamp: Long, 236 prefix: String, 237 columnName: String, 238 value: Int?, 239 isInitial: Boolean, 240 ) { 241 Trace.beginSection("TableLogBuffer#logChange(int)") 242 val change = obtain(timestamp, prefix, columnName, isInitial) 243 change.set(value) 244 tryAddMessage(change) 245 Trace.endSection() 246 } 247 248 private fun tryAddMessage(change: TableChange) { 249 logMessageChannel.trySend(change) 250 } 251 252 // TODO(b/259454430): Add additional change types here. 253 254 @Synchronized 255 private fun obtain( 256 timestamp: Long, 257 prefix: String, 258 columnName: String, 259 isInitial: Boolean, 260 ): TableChange { 261 verifyValidName(prefix, columnName) 262 val tableChange = buffer.advance() 263 if (tableChange.hasData()) { 264 saveEvictedValue(tableChange) 265 } 266 tableChange.reset(timestamp, prefix, columnName, isInitial) 267 return tableChange 268 } 269 270 private fun verifyValidName(prefix: String, columnName: String) { 271 if (prefix.contains(SEPARATOR)) { 272 throw IllegalArgumentException("columnPrefix cannot contain $SEPARATOR but was $prefix") 273 } 274 if (columnName.contains(SEPARATOR)) { 275 throw IllegalArgumentException( 276 "columnName cannot contain $SEPARATOR but was $columnName" 277 ) 278 } 279 } 280 281 private fun saveEvictedValue(change: TableChange) { 282 Trace.beginSection("TableLogBuffer#saveEvictedValue") 283 val name = change.getName() 284 val previouslyEvicted = 285 lastEvictedValues[name] ?: TableChange().also { lastEvictedValues[name] = it } 286 // For recycling purposes, update the existing object in the map with the new information 287 // instead of creating a new object. 288 previouslyEvicted.updateTo(change) 289 Trace.endSection() 290 } 291 292 private fun echoToDesiredEndpoints(change: TableChange) { 293 if ( 294 logcatEchoTracker.isBufferLoggable(bufferName = name, LogLevel.DEBUG) || 295 logcatEchoTracker.isTagLoggable(change.getColumnName(), LogLevel.DEBUG) 296 ) { 297 if (change.hasData()) { 298 localLogcat.d(name, change.logcatRepresentation()) 299 } 300 } 301 } 302 303 @Synchronized 304 override fun dump(pw: PrintWriter, args: Array<out String>) { 305 pw.append(HEADER_PREFIX).println(name) 306 pw.append("version ").println(VERSION) 307 308 lastEvictedValues.values.sortedBy { it.timestamp }.forEach { it.dump(pw) } 309 for (i in 0 until buffer.size) { 310 buffer[i].dump(pw) 311 } 312 pw.append(FOOTER_PREFIX).println(name) 313 } 314 315 /** Dumps an individual [TableChange]. */ 316 private fun TableChange.dump(pw: PrintWriter) { 317 if (!this.hasData()) { 318 return 319 } 320 val formattedTimestamp = TABLE_LOG_DATE_FORMAT.format(timestamp) 321 pw.print(formattedTimestamp) 322 pw.print(SEPARATOR) 323 pw.print(this.getName()) 324 pw.print(SEPARATOR) 325 pw.print(this.getVal()) 326 pw.println() 327 } 328 329 /** Transforms an individual [TableChange] into a String for logcat */ 330 private fun TableChange.logcatRepresentation(): String { 331 val formattedTimestamp = TABLE_LOG_DATE_FORMAT.format(timestamp) 332 return "$formattedTimestamp$SEPARATOR${getName()}$SEPARATOR${getVal()}" 333 } 334 335 /** 336 * A private implementation of [TableRowLogger]. 337 * 338 * Used so that external clients can't modify [timestamp]. 339 */ 340 private class TableRowLoggerImpl( 341 var timestamp: Long, 342 var columnPrefix: String, 343 var isInitial: Boolean, 344 val tableLogBuffer: TableLogBuffer, 345 ) : TableRowLogger { 346 /** Logs a change to a string value. */ 347 override fun logChange(columnName: String, value: String?) { 348 tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value, isInitial) 349 } 350 351 /** Logs a change to a boolean value. */ 352 override fun logChange(columnName: String, value: Boolean) { 353 tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value, isInitial) 354 } 355 356 /** Logs a change to an int value. */ 357 override fun logChange(columnName: String, value: Int) { 358 tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value, isInitial) 359 } 360 } 361 } 362 363 val TABLE_LOG_DATE_FORMAT = SimpleDateFormat("MM-dd HH:mm:ss.SSS", Locale.US) 364 365 private const val HEADER_PREFIX = "SystemUI StateChangeTableSection START: " 366 private const val FOOTER_PREFIX = "SystemUI StateChangeTableSection END: " 367 private const val SEPARATOR = "|" 368 private const val VERSION = "1" 369