diff options
4 files changed, 361 insertions, 2 deletions
diff --git a/packages/SystemUI/src/com/android/systemui/log/table/TableChange.kt b/packages/SystemUI/src/com/android/systemui/log/table/TableChange.kt index 4880f80e7716..b73ddc50f831 100644 --- a/packages/SystemUI/src/com/android/systemui/log/table/TableChange.kt +++ b/packages/SystemUI/src/com/android/systemui/log/table/TableChange.kt @@ -59,6 +59,17 @@ data class TableChange( int = value } + /** Updates this to store the same value as [change]. */ + fun updateTo(change: TableChange) { + reset(change.timestamp, change.columnPrefix, change.columnName) + when (change.type) { + DataType.STRING -> set(change.str) + DataType.INT -> set(change.int) + DataType.BOOLEAN -> set(change.bool) + DataType.EMPTY -> {} + } + } + /** Returns true if this object has a change. */ fun hasData(): Boolean { return columnName.isNotBlank() && type != DataType.EMPTY diff --git a/packages/SystemUI/src/com/android/systemui/log/table/TableLogBuffer.kt b/packages/SystemUI/src/com/android/systemui/log/table/TableLogBuffer.kt index 29f273a5ed41..a0f1c959aed6 100644 --- a/packages/SystemUI/src/com/android/systemui/log/table/TableLogBuffer.kt +++ b/packages/SystemUI/src/com/android/systemui/log/table/TableLogBuffer.kt @@ -16,13 +16,13 @@ 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 -import kotlinx.coroutines.flow.Flow /** * A logger that logs changes in table format. @@ -82,6 +82,19 @@ class TableLogBuffer( 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<String, TableChange>() + // A [TableRowLogger] object, re-used each time [logDiffs] is called. // (Re-used to avoid object allocation.) private val tempRow = TableRowLoggerImpl(0, columnPrefix = "", this) @@ -138,18 +151,24 @@ class TableLogBuffer( // 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. @@ -158,6 +177,9 @@ class TableLogBuffer( 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 } @@ -173,10 +195,23 @@ class TableLogBuffer( } } + 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<out String>) { 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) } diff --git a/packages/SystemUI/tests/src/com/android/systemui/log/table/TableChangeTest.kt b/packages/SystemUI/tests/src/com/android/systemui/log/table/TableChangeTest.kt index c7f3fa0830cd..fb20bacee64c 100644 --- a/packages/SystemUI/tests/src/com/android/systemui/log/table/TableChangeTest.kt +++ b/packages/SystemUI/tests/src/com/android/systemui/log/table/TableChangeTest.kt @@ -121,4 +121,92 @@ class TableChangeTest : SysuiTestCase() { assertThat(underTest.getName()).doesNotContain("original") assertThat(underTest.getVal()).isEqualTo("8900") } + + @Test + fun updateTo_emptyToString_isString() { + val underTest = TableChange(columnPrefix = "fakePrefix", columnName = "fakeName") + + val new = TableChange(columnPrefix = "newPrefix", columnName = "newName") + new.set("newString") + underTest.updateTo(new) + + assertThat(underTest.hasData()).isTrue() + assertThat(underTest.getName()).contains("newPrefix") + assertThat(underTest.getName()).contains("newName") + assertThat(underTest.getVal()).isEqualTo("newString") + } + + @Test + fun updateTo_intToEmpty_isEmpty() { + val underTest = TableChange(columnPrefix = "fakePrefix", columnName = "fakeName") + underTest.set(42) + + val new = TableChange(columnPrefix = "newPrefix", columnName = "newName") + underTest.updateTo(new) + + assertThat(underTest.hasData()).isFalse() + assertThat(underTest.getName()).contains("newPrefix") + assertThat(underTest.getName()).contains("newName") + assertThat(underTest.getVal()).isEqualTo("null") + } + + @Test + fun updateTo_stringToBool_isBool() { + val underTest = TableChange(columnPrefix = "fakePrefix", columnName = "fakeName") + underTest.set("oldString") + + val new = TableChange(columnPrefix = "newPrefix", columnName = "newName") + new.set(true) + underTest.updateTo(new) + + assertThat(underTest.hasData()).isTrue() + assertThat(underTest.getName()).contains("newPrefix") + assertThat(underTest.getName()).contains("newName") + assertThat(underTest.getVal()).isEqualTo("true") + } + + @Test + fun updateTo_intToString_isString() { + val underTest = TableChange(columnPrefix = "fakePrefix", columnName = "fakeName") + underTest.set(43) + + val new = TableChange(columnPrefix = "newPrefix", columnName = "newName") + new.set("newString") + underTest.updateTo(new) + + assertThat(underTest.hasData()).isTrue() + assertThat(underTest.getName()).contains("newPrefix") + assertThat(underTest.getName()).contains("newName") + assertThat(underTest.getVal()).isEqualTo("newString") + } + + @Test + fun updateTo_boolToInt_isInt() { + val underTest = TableChange(columnPrefix = "fakePrefix", columnName = "fakeName") + underTest.set(false) + + val new = TableChange(columnPrefix = "newPrefix", columnName = "newName") + new.set(44) + underTest.updateTo(new) + + assertThat(underTest.hasData()).isTrue() + assertThat(underTest.getName()).contains("newPrefix") + assertThat(underTest.getName()).contains("newName") + assertThat(underTest.getVal()).isEqualTo("44") + } + + @Test + fun updateTo_boolToNewBool_isNewBool() { + val underTest = TableChange(columnPrefix = "fakePrefix", columnName = "fakeName") + underTest.set(false) + + val new = TableChange(columnPrefix = "newPrefix", columnName = "newName") + new.set(true) + underTest.updateTo(new) + + assertThat(underTest.hasData()).isTrue() + assertThat(underTest.getName()).contains("newPrefix") + assertThat(underTest.getName()).contains("newName") + assertThat(underTest.getVal()).isEqualTo("true") + } } diff --git a/packages/SystemUI/tests/src/com/android/systemui/log/table/TableLogBufferTest.kt b/packages/SystemUI/tests/src/com/android/systemui/log/table/TableLogBufferTest.kt index 2c8d7abd4f4a..949fa1cce0cb 100644 --- a/packages/SystemUI/tests/src/com/android/systemui/log/table/TableLogBufferTest.kt +++ b/packages/SystemUI/tests/src/com/android/systemui/log/table/TableLogBufferTest.kt @@ -435,11 +435,236 @@ class TableLogBufferTest : SysuiTestCase() { assertThat(dumpedString).doesNotContain("testString[0]") assertThat(dumpedString).doesNotContain("testString[1]") - assertThat(dumpedString).doesNotContain("testString[2]") + // The buffer should contain [MAX_SIZE + 1] entries since we also save the most recently + // evicted value. + assertThat(dumpedString).contains("testString[2]") assertThat(dumpedString).contains("testString[3]") assertThat(dumpedString).contains("testString[${MAX_SIZE + 2}]") } + @Test + fun columnEvicted_lastKnownColumnValueInDump() { + systemClock.setCurrentTimeMillis(100L) + underTest.logChange(prefix = "", columnName = "willBeEvicted", value = "evictedValue") + + // Exactly fill the buffer so that "willBeEvicted" is evicted + for (i in 0 until MAX_SIZE) { + systemClock.advanceTime(100L) + val dumpString = "fillString[$i]" + underTest.logChange(prefix = "", columnName = "fillingColumn", value = dumpString) + } + + val dumpedString = dumpChanges() + + // Expect that we'll have both the evicted column entry... + val evictedColumnLog = + TABLE_LOG_DATE_FORMAT.format(100L) + + SEPARATOR + + "willBeEvicted" + + SEPARATOR + + "evictedValue" + assertThat(dumpedString).contains(evictedColumnLog) + + // ... *and* all of the fillingColumn entries. + val firstFillingColumnLog = + TABLE_LOG_DATE_FORMAT.format(200L) + + SEPARATOR + + "fillingColumn" + + SEPARATOR + + "fillString[0]" + val lastFillingColumnLog = + TABLE_LOG_DATE_FORMAT.format(1100L) + + SEPARATOR + + "fillingColumn" + + SEPARATOR + + "fillString[9]" + assertThat(dumpedString).contains(firstFillingColumnLog) + assertThat(dumpedString).contains(lastFillingColumnLog) + } + + @Test + fun multipleColumnsEvicted_allColumnsInDump() { + systemClock.setCurrentTimeMillis(100L) + underTest.logChange(prefix = "", columnName = "willBeEvictedString", value = "evictedValue") + systemClock.advanceTime(100L) + underTest.logChange(prefix = "", columnName = "willBeEvictedInt", value = 45) + systemClock.advanceTime(100L) + underTest.logChange(prefix = "", columnName = "willBeEvictedBool", value = true) + + // Exactly fill the buffer so that all the above columns will be evicted + for (i in 0 until MAX_SIZE) { + systemClock.advanceTime(100L) + val dumpString = "fillString[$i]" + underTest.logChange(prefix = "", columnName = "fillingColumn", value = dumpString) + } + + val dumpedString = dumpChanges() + + // Expect that we'll have all the evicted column entries... + val evictedColumnLogString = + TABLE_LOG_DATE_FORMAT.format(100L) + + SEPARATOR + + "willBeEvictedString" + + SEPARATOR + + "evictedValue" + val evictedColumnLogInt = + TABLE_LOG_DATE_FORMAT.format(200L) + SEPARATOR + "willBeEvictedInt" + SEPARATOR + "45" + val evictedColumnLogBool = + TABLE_LOG_DATE_FORMAT.format(300L) + + SEPARATOR + + "willBeEvictedBool" + + SEPARATOR + + "true" + assertThat(dumpedString).contains(evictedColumnLogString) + assertThat(dumpedString).contains(evictedColumnLogInt) + assertThat(dumpedString).contains(evictedColumnLogBool) + + // ... *and* all of the fillingColumn entries. + val firstFillingColumnLog = + TABLE_LOG_DATE_FORMAT.format(400) + + SEPARATOR + + "fillingColumn" + + SEPARATOR + + "fillString[0]" + val lastFillingColumnLog = + TABLE_LOG_DATE_FORMAT.format(1300) + + SEPARATOR + + "fillingColumn" + + SEPARATOR + + "fillString[9]" + assertThat(dumpedString).contains(firstFillingColumnLog) + assertThat(dumpedString).contains(lastFillingColumnLog) + } + + @Test + fun multipleColumnsEvicted_differentPrefixSameName_allColumnsInDump() { + systemClock.setCurrentTimeMillis(100L) + underTest.logChange(prefix = "prefix1", columnName = "sameName", value = "value1") + systemClock.advanceTime(100L) + underTest.logChange(prefix = "prefix2", columnName = "sameName", value = "value2") + systemClock.advanceTime(100L) + underTest.logChange(prefix = "prefix3", columnName = "sameName", value = "value3") + + // Exactly fill the buffer so that all the above columns will be evicted + for (i in 0 until MAX_SIZE) { + systemClock.advanceTime(100L) + val dumpString = "fillString[$i]" + underTest.logChange(prefix = "", columnName = "fillingColumn", value = dumpString) + } + + val dumpedString = dumpChanges() + + // Expect that we'll have all the evicted column entries + val evictedColumn1 = + TABLE_LOG_DATE_FORMAT.format(100L) + + SEPARATOR + + "prefix1.sameName" + + SEPARATOR + + "value1" + val evictedColumn2 = + TABLE_LOG_DATE_FORMAT.format(200L) + + SEPARATOR + + "prefix2.sameName" + + SEPARATOR + + "value2" + val evictedColumn3 = + TABLE_LOG_DATE_FORMAT.format(300L) + + SEPARATOR + + "prefix3.sameName" + + SEPARATOR + + "value3" + assertThat(dumpedString).contains(evictedColumn1) + assertThat(dumpedString).contains(evictedColumn2) + assertThat(dumpedString).contains(evictedColumn3) + } + + @Test + fun multipleColumnsEvicted_dumpSortedByTimestamp() { + systemClock.setCurrentTimeMillis(100L) + underTest.logChange(prefix = "", columnName = "willBeEvictedFirst", value = "evictedValue") + systemClock.advanceTime(100L) + underTest.logChange(prefix = "", columnName = "willBeEvictedSecond", value = 45) + systemClock.advanceTime(100L) + underTest.logChange(prefix = "", columnName = "willBeEvictedThird", value = true) + + // Exactly fill the buffer with so that all the above columns will be evicted + for (i in 0 until MAX_SIZE) { + systemClock.advanceTime(100L) + val dumpString = "fillString[$i]" + underTest.logChange(prefix = "", columnName = "fillingColumn", value = dumpString) + } + + val dumpedString = dumpChanges() + + // Expect that we'll have all the evicted column entries in timestamp order + val firstEvictedLog = + TABLE_LOG_DATE_FORMAT.format(100L) + + SEPARATOR + + "willBeEvictedFirst" + + SEPARATOR + + "evictedValue" + val secondEvictedLog = + TABLE_LOG_DATE_FORMAT.format(200L) + + SEPARATOR + + "willBeEvictedSecond" + + SEPARATOR + + "45" + val thirdEvictedLog = + TABLE_LOG_DATE_FORMAT.format(300L) + + SEPARATOR + + "willBeEvictedThird" + + SEPARATOR + + "true" + assertThat(dumpedString).contains(firstEvictedLog) + val stringAfterFirst = dumpedString.substringAfter(firstEvictedLog) + assertThat(stringAfterFirst).contains(secondEvictedLog) + val stringAfterSecond = stringAfterFirst.substringAfter(secondEvictedLog) + assertThat(stringAfterSecond).contains(thirdEvictedLog) + } + + @Test + fun sameColumnEvictedMultipleTimes_onlyLastEvictionInDump() { + systemClock.setCurrentTimeMillis(0L) + + for (i in 1 until 4) { + systemClock.advanceTime(100L) + val dumpString = "evicted[$i]" + underTest.logChange(prefix = "", columnName = "evictedColumn", value = dumpString) + } + + // Exactly fill the buffer so that all the entries for "evictedColumn" will be evicted. + for (i in 0 until MAX_SIZE) { + systemClock.advanceTime(100L) + val dumpString = "fillString[$i]" + underTest.logChange(prefix = "", columnName = "fillingColumn", value = dumpString) + } + + val dumpedString = dumpChanges() + + // Expect that we only have the most recent evicted column entry + val evictedColumnLog1 = + TABLE_LOG_DATE_FORMAT.format(100L) + + SEPARATOR + + "evictedColumn" + + SEPARATOR + + "evicted[1]" + val evictedColumnLog2 = + TABLE_LOG_DATE_FORMAT.format(200L) + + SEPARATOR + + "evictedColumn" + + SEPARATOR + + "evicted[2]" + val evictedColumnLog3 = + TABLE_LOG_DATE_FORMAT.format(300L) + + SEPARATOR + + "evictedColumn" + + SEPARATOR + + "evicted[3]" + assertThat(dumpedString).doesNotContain(evictedColumnLog1) + assertThat(dumpedString).doesNotContain(evictedColumnLog2) + assertThat(dumpedString).contains(evictedColumnLog3) + } + private fun dumpChanges(): String { underTest.dump(PrintWriter(outputWriter), arrayOf()) return outputWriter.toString() |