/* * Copyright (C) 2022 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package com.android.systemui.log.table import android.os.Trace import com.android.systemui.Dumpable import com.android.systemui.plugins.util.RingBuffer import com.android.systemui.util.time.SystemClock import java.io.PrintWriter import java.text.SimpleDateFormat import java.util.Locale /** * A logger that logs changes in table format. * * Some parts of System UI maintain a lot of pieces of state at once. * [com.android.systemui.plugins.log.LogBuffer] allows us to easily log change events: * - 10-10 10:10:10.456: state2 updated to newVal2 * - 10-10 10:11:00.000: stateN updated to StateN(val1=true, val2=1) * - 10-10 10:11:02.123: stateN updated to StateN(val1=true, val2=2) * - 10-10 10:11:05.123: state1 updated to newVal1 * - 10-10 10:11:06.000: stateN updated to StateN(val1=false, val2=3) * * However, it can sometimes be more useful to view the state changes in table format: * - timestamp--------- | state1- | state2- | ... | stateN.val1 | stateN.val2 * - ------------------------------------------------------------------------- * - 10-10 10:10:10.123 | val1--- | val2--- | ... | false------ | 0----------- * - 10-10 10:10:10.456 | val1--- | newVal2 | ... | false------ | 0----------- * - 10-10 10:11:00.000 | val1--- | newVal2 | ... | true------- | 1----------- * - 10-10 10:11:02.123 | val1--- | newVal2 | ... | true------- | 2----------- * - 10-10 10:11:05.123 | newVal1 | newVal2 | ... | true------- | 2----------- * - 10-10 10:11:06.000 | newVal1 | newVal2 | ... | false------ | 3----------- * * This class enables easy logging of the state changes in both change event format and table * format. * * This class also enables easy logging of states that are a collection of fields. For example, * stateN in the above example consists of two fields -- val1 and val2. It's useful to put each * field into its own column so that ABT (Android Bug Tool) can easily highlight changes to * individual fields. * * How it works: * 1) Create an instance of this buffer via [TableLogBufferFactory]. * 2) For any states being logged, implement [Diffable]. Implementing [Diffable] allows the state to * only log the fields that have *changed* since the previous update, instead of always logging * all fields. * 3) Each time a change in a state happens, call [logDiffs]. If your state is emitted using a * [Flow], you should use the [logDiffsForTable] extension function to automatically log diffs * any time your flow emits a new value. * * When a dump occurs, there will be two dumps: * 1) The change events under the dumpable name "$name-changes". * 2) This class will coalesce all the diffs into a table format and log them under the dumpable * name "$name-table". * * @param maxSize the maximum size of the buffer. Must be > 0. */ class TableLogBuffer( maxSize: Int, private val name: String, private val systemClock: SystemClock, ) : Dumpable { init { if (maxSize <= 0) { throw IllegalArgumentException("maxSize must be > 0") } } private val buffer = RingBuffer(maxSize) { TableChange() } // Stores the most recently evicted value for each column name (indexed on column name). // // Why it's necessary: Because we use a RingBuffer of a fixed size, it's possible that a column // that's logged infrequently will eventually get pushed out by a different column that's // logged more frequently. Then, that infrequently-logged column isn't present in the RingBuffer // at all and we have no logs that the column ever existed. This is a problem because the // column's information is still relevant, valid, and may be critical to debugging issues. // // Fix: When a change is being evicted from the RingBuffer, we store it in this map (based on // its [TableChange.getName()]. This ensures that we always have at least one value for every // column ever logged. See b/272016422 for more details. private val lastEvictedValues = mutableMapOf() // A [TableRowLogger] object, re-used each time [logDiffs] is called. // (Re-used to avoid object allocation.) private val tempRow = TableRowLoggerImpl(0, columnPrefix = "", this) /** * Log the differences between [prevVal] and [newVal]. * * The [newVal] object's method [Diffable.logDiffs] will be used to fetch the diffs. * * @param columnPrefix a prefix that will be applied to every column name that gets logged. This * ensures that all the columns related to the same state object will be grouped together in * the table. * @throws IllegalArgumentException if [columnPrefix] or column name contain "|". "|" is used as * the separator token for parsing, so it can't be present in any part of the column name. */ @Synchronized fun > logDiffs(columnPrefix: String, prevVal: T, newVal: T) { val row = tempRow row.timestamp = systemClock.currentTimeMillis() row.columnPrefix = columnPrefix newVal.logDiffs(prevVal, row) } /** * Logs change(s) to the buffer using [rowInitializer]. * * @param rowInitializer a function that will be called immediately to store relevant data on * the row. */ @Synchronized fun logChange(columnPrefix: String, rowInitializer: (TableRowLogger) -> Unit) { val row = tempRow row.timestamp = systemClock.currentTimeMillis() row.columnPrefix = columnPrefix rowInitializer(row) } /** Logs a String? change. */ fun logChange(prefix: String, columnName: String, value: String?) { logChange(systemClock.currentTimeMillis(), prefix, columnName, value) } /** Logs a boolean change. */ fun logChange(prefix: String, columnName: String, value: Boolean) { logChange(systemClock.currentTimeMillis(), prefix, columnName, value) } /** Logs a Int change. */ fun logChange(prefix: String, columnName: String, value: Int?) { logChange(systemClock.currentTimeMillis(), prefix, columnName, value) } // Keep these individual [logChange] methods private (don't let clients give us their own // timestamps.) private fun logChange(timestamp: Long, prefix: String, columnName: String, value: String?) { Trace.beginSection("TableLogBuffer#logChange(string)") val change = obtain(timestamp, prefix, columnName) change.set(value) Trace.endSection() } private fun logChange(timestamp: Long, prefix: String, columnName: String, value: Boolean) { Trace.beginSection("TableLogBuffer#logChange(boolean)") val change = obtain(timestamp, prefix, columnName) change.set(value) Trace.endSection() } private fun logChange(timestamp: Long, prefix: String, columnName: String, value: Int?) { Trace.beginSection("TableLogBuffer#logChange(int)") val change = obtain(timestamp, prefix, columnName) change.set(value) Trace.endSection() } // TODO(b/259454430): Add additional change types here. @Synchronized private fun obtain(timestamp: Long, prefix: String, columnName: String): TableChange { verifyValidName(prefix, columnName) val tableChange = buffer.advance() if (tableChange.hasData()) { saveEvictedValue(tableChange) } tableChange.reset(timestamp, prefix, columnName) return tableChange } private fun verifyValidName(prefix: String, columnName: String) { if (prefix.contains(SEPARATOR)) { throw IllegalArgumentException("columnPrefix cannot contain $SEPARATOR but was $prefix") } if (columnName.contains(SEPARATOR)) { throw IllegalArgumentException( "columnName cannot contain $SEPARATOR but was $columnName" ) } } private fun saveEvictedValue(change: TableChange) { Trace.beginSection("TableLogBuffer#saveEvictedValue") val name = change.getName() val previouslyEvicted = lastEvictedValues[name] ?: TableChange().also { lastEvictedValues[name] = it } // For recycling purposes, update the existing object in the map with the new information // instead of creating a new object. previouslyEvicted.updateTo(change) Trace.endSection() } @Synchronized override fun dump(pw: PrintWriter, args: Array) { pw.println(HEADER_PREFIX + name) pw.println("version $VERSION") lastEvictedValues.values.sortedBy { it.timestamp }.forEach { it.dump(pw) } for (i in 0 until buffer.size) { buffer[i].dump(pw) } pw.println(FOOTER_PREFIX + name) } /** Dumps an individual [TableChange]. */ private fun TableChange.dump(pw: PrintWriter) { if (!this.hasData()) { return } val formattedTimestamp = TABLE_LOG_DATE_FORMAT.format(timestamp) pw.print(formattedTimestamp) pw.print(SEPARATOR) pw.print(this.getName()) pw.print(SEPARATOR) pw.print(this.getVal()) pw.println() } /** * A private implementation of [TableRowLogger]. * * Used so that external clients can't modify [timestamp]. */ private class TableRowLoggerImpl( var timestamp: Long, var columnPrefix: String, val tableLogBuffer: TableLogBuffer, ) : TableRowLogger { /** Logs a change to a string value. */ override fun logChange(columnName: String, value: String?) { tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value) } /** Logs a change to a boolean value. */ override fun logChange(columnName: String, value: Boolean) { tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value) } /** Logs a change to an int value. */ override fun logChange(columnName: String, value: Int) { tableLogBuffer.logChange(timestamp, columnPrefix, columnName, value) } } } val TABLE_LOG_DATE_FORMAT = SimpleDateFormat("MM-dd HH:mm:ss.SSS", Locale.US) private const val HEADER_PREFIX = "SystemUI StateChangeTableSection START: " private const val FOOTER_PREFIX = "SystemUI StateChangeTableSection END: " private const val SEPARATOR = "|" private const val VERSION = "1"