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