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 columnPrefix see [logDiffs]. 140 * @param rowInitializer a function that will be called immediately to store relevant data on 141 * the row. 142 * @param isInitial true if this change represents the starting value for a particular column 143 * (as opposed to a value that was updated after receiving new information). This is used to 144 * help us identify which values were just default starting values, and which values were 145 * derived from updated information. Most callers should use false for this value. 146 */ 147 @Synchronized logChangenull148 fun logChange( 149 columnPrefix: String = "", 150 isInitial: Boolean = false, 151 rowInitializer: (TableRowLogger) -> Unit, 152 ) { 153 val row = tempRow 154 row.timestamp = systemClock.currentTimeMillis() 155 row.columnPrefix = columnPrefix 156 row.isInitial = isInitial 157 rowInitializer(row) 158 } 159 160 /** 161 * Logs a String? change. 162 * 163 * @param isInitial see [TableLogBuffer.logChange(String, Boolean, (TableRowLogger) -> Unit]. 164 */ logChangenull165 override fun logChange(prefix: String, columnName: String, value: String?, isInitial: Boolean) { 166 logChange(systemClock.currentTimeMillis(), prefix, columnName, value, isInitial) 167 } 168 169 /** 170 * Logs a boolean change. 171 * 172 * @param isInitial see [TableLogBuffer.logChange(String, Boolean, (TableRowLogger) -> Unit]. 173 */ logChangenull174 override fun logChange(prefix: String, columnName: String, value: Boolean, isInitial: Boolean) { 175 logChange(systemClock.currentTimeMillis(), prefix, columnName, value, isInitial) 176 } 177 178 /** 179 * Logs a Int change. 180 * 181 * @param isInitial see [TableLogBuffer.logChange(String, Boolean, (TableRowLogger) -> Unit]. 182 */ logChangenull183 override fun logChange(prefix: String, columnName: String, value: Int?, isInitial: Boolean) { 184 logChange(systemClock.currentTimeMillis(), prefix, columnName, value, isInitial) 185 } 186 187 // Keep these individual [logChange] methods private (don't let clients give us their own 188 // timestamps.) 189 logChangenull190 private fun logChange( 191 timestamp: Long, 192 prefix: String, 193 columnName: String, 194 value: String?, 195 isInitial: Boolean, 196 ) { 197 Trace.beginSection("TableLogBuffer#logChange(string)") 198 val change = obtain(timestamp, prefix, columnName, isInitial) 199 change.set(value) 200 echoToDesiredEndpoints(change) 201 Trace.endSection() 202 } 203 logChangenull204 private fun logChange( 205 timestamp: Long, 206 prefix: String, 207 columnName: String, 208 value: Boolean, 209 isInitial: Boolean, 210 ) { 211 Trace.beginSection("TableLogBuffer#logChange(boolean)") 212 val change = obtain(timestamp, prefix, columnName, isInitial) 213 change.set(value) 214 echoToDesiredEndpoints(change) 215 Trace.endSection() 216 } 217 logChangenull218 private fun logChange( 219 timestamp: Long, 220 prefix: String, 221 columnName: String, 222 value: Int?, 223 isInitial: Boolean, 224 ) { 225 Trace.beginSection("TableLogBuffer#logChange(int)") 226 val change = obtain(timestamp, prefix, columnName, isInitial) 227 change.set(value) 228 echoToDesiredEndpoints(change) 229 Trace.endSection() 230 } 231 232 // TODO(b/259454430): Add additional change types here. 233 234 @Synchronized obtainnull235 private fun obtain( 236 timestamp: Long, 237 prefix: String, 238 columnName: String, 239 isInitial: Boolean, 240 ): TableChange { 241 verifyValidName(prefix, columnName) 242 val tableChange = buffer.advance() 243 if (tableChange.hasData()) { 244 saveEvictedValue(tableChange) 245 } 246 tableChange.reset(timestamp, prefix, columnName, isInitial) 247 return tableChange 248 } 249 verifyValidNamenull250 private fun verifyValidName(prefix: String, columnName: String) { 251 if (prefix.contains(SEPARATOR)) { 252 throw IllegalArgumentException("columnPrefix cannot contain $SEPARATOR but was $prefix") 253 } 254 if (columnName.contains(SEPARATOR)) { 255 throw IllegalArgumentException( 256 "columnName cannot contain $SEPARATOR but was $columnName" 257 ) 258 } 259 } 260 saveEvictedValuenull261 private fun saveEvictedValue(change: TableChange) { 262 Trace.beginSection("TableLogBuffer#saveEvictedValue") 263 val name = change.getName() 264 val previouslyEvicted = 265 lastEvictedValues[name] ?: TableChange().also { lastEvictedValues[name] = it } 266 // For recycling purposes, update the existing object in the map with the new information 267 // instead of creating a new object. 268 previouslyEvicted.updateTo(change) 269 Trace.endSection() 270 } 271 echoToDesiredEndpointsnull272 private fun echoToDesiredEndpoints(change: TableChange) { 273 if ( 274 logcatEchoTracker.isBufferLoggable(bufferName = name, LogLevel.DEBUG) || 275 logcatEchoTracker.isTagLoggable(change.getColumnName(), LogLevel.DEBUG) 276 ) { 277 if (change.hasData()) { 278 localLogcat.d(name, change.logcatRepresentation()) 279 } 280 } 281 } 282 283 @Synchronized dumpnull284 override fun dump(pw: PrintWriter, args: Array<out String>) { 285 pw.append(HEADER_PREFIX).println(name) 286 pw.append("version ").println(VERSION) 287 288 lastEvictedValues.values.sortedBy { it.timestamp }.forEach { it.dump(pw) } 289 for (i in 0 until buffer.size) { 290 buffer[i].dump(pw) 291 } 292 pw.append(FOOTER_PREFIX).println(name) 293 } 294 295 /** Dumps an individual [TableChange]. */ dumpnull296 private fun TableChange.dump(pw: PrintWriter) { 297 if (!this.hasData()) { 298 return 299 } 300 val formattedTimestamp = TABLE_LOG_DATE_FORMAT.format(timestamp) 301 pw.print(formattedTimestamp) 302 pw.print(SEPARATOR) 303 pw.print(this.getName()) 304 pw.print(SEPARATOR) 305 pw.print(this.getVal()) 306 pw.println() 307 } 308 309 /** Transforms an individual [TableChange] into a String for logcat */ logcatRepresentationnull310 private fun TableChange.logcatRepresentation(): String { 311 val formattedTimestamp = TABLE_LOG_DATE_FORMAT.format(timestamp) 312 return "$formattedTimestamp$SEPARATOR${getName()}$SEPARATOR${getVal()}" 313 } 314 315 /** 316 * A private implementation of [TableRowLogger]. 317 * 318 * Used so that external clients can't modify [timestamp]. 319 */ 320 private class TableRowLoggerImpl( 321 var timestamp: Long, 322 var columnPrefix: String, 323 var isInitial: Boolean, 324 val tableLogBuffer: TableLogBuffer, 325 ) : TableRowLogger { 326 /** Logs a change to a string value. */ logChangenull327 override fun logChange(columnName: String, value: String?) { 328 tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value, isInitial) 329 } 330 331 /** Logs a change to a boolean value. */ logChangenull332 override fun logChange(columnName: String, value: Boolean) { 333 tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value, isInitial) 334 } 335 336 /** Logs a change to an int value. */ logChangenull337 override fun logChange(columnName: String, value: Int) { 338 tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value, isInitial) 339 } 340 } 341 } 342 343 val TABLE_LOG_DATE_FORMAT = SimpleDateFormat("MM-dd HH:mm:ss.SSS", Locale.US) 344 345 private const val HEADER_PREFIX = "SystemUI StateChangeTableSection START: " 346 private const val FOOTER_PREFIX = "SystemUI StateChangeTableSection END: " 347 private const val SEPARATOR = "|" 348 private const val VERSION = "1" 349