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