Merge changes I48a0acc7,I57fbba0a into tm-qpr-dev

* changes:
  [Table Logging] Save the last evicted value per column.
  [Table logging] Add tracing to the log methods.

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

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)
         }

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")
+    }
 }

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()