Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 9f0b5bb6 authored by Caitlin Shkuratov's avatar Caitlin Shkuratov
Browse files

[Table Logging] Save the last evicted value per column. 

Fixes: 272016422

Test: atest TableLogBufferTest TableChangeTest

Test: systraces to verify the saving doesn't vastly increase log time.
Verify that `wifiEnabled` still shows up in the table log.

Test: Keep changing wifi networks (but leave wifi enabled always).
See bug for more information, but tl;dr: Average log takes 35us.

Change-Id: I48a0acc7b1191e3b3262e0401991afe76099b1a4
parent 46da9999

packages/SystemUI/src/com/android/systemui/log/table/TableChange.kt

+11 −0
Original line number Original line Diff line number Diff line
@@ -59,6 +59,17 @@ data class TableChange( 
        int = value

        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. */

    /** Returns true if this object has a change. */

    fun hasData(): Boolean {

    fun hasData(): Boolean {

        return columnName.isNotBlank() && type != DataType.EMPTY

        return columnName.isNotBlank() && type != DataType.EMPTY

packages/SystemUI/src/com/android/systemui/log/table/TableLogBuffer.kt

+29 −0
Original line number Original line Diff line number Diff line
@@ -82,6 +82,19 @@ class TableLogBuffer( 




    private val buffer = RingBuffer(maxSize) { TableChange() }

    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.

    // A [TableRowLogger] object, re-used each time [logDiffs] is called.

    // (Re-used to avoid object allocation.)

    // (Re-used to avoid object allocation.)

    private val tempRow = TableRowLoggerImpl(0, columnPrefix = "", this)

    private val tempRow = TableRowLoggerImpl(0, columnPrefix = "", this)
@@ -164,6 +177,9 @@ class TableLogBuffer( 
    private fun obtain(timestamp: Long, prefix: String, columnName: String): TableChange {

    private fun obtain(timestamp: Long, prefix: String, columnName: String): TableChange {

        verifyValidName(prefix, columnName)

        verifyValidName(prefix, columnName)

        val tableChange = buffer.advance()

        val tableChange = buffer.advance()

        if (tableChange.hasData()) {

            saveEvictedValue(tableChange)

        }

        tableChange.reset(timestamp, prefix, columnName)

        tableChange.reset(timestamp, prefix, columnName)

        return tableChange

        return tableChange

    }

    }
@@ -179,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

    @Synchronized

    override fun dump(pw: PrintWriter, args: Array<out String>) {

    override fun dump(pw: PrintWriter, args: Array<out String>) {

        pw.println(HEADER_PREFIX + name)

        pw.println(HEADER_PREFIX + name)

        pw.println("version $VERSION")

        pw.println("version $VERSION")



        lastEvictedValues.values.sortedBy { it.timestamp }.forEach { it.dump(pw) }

        for (i in 0 until buffer.size) {

        for (i in 0 until buffer.size) {

            buffer[i].dump(pw)

            buffer[i].dump(pw)

        }

        }

packages/SystemUI/tests/src/com/android/systemui/log/table/TableChangeTest.kt

+88 −0
Original line number Original line Diff line number Diff line
@@ -121,4 +121,92 @@ class TableChangeTest : SysuiTestCase() { 
        assertThat(underTest.getName()).doesNotContain("original")

        assertThat(underTest.getName()).doesNotContain("original")

        assertThat(underTest.getVal()).isEqualTo("8900")

        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

+226 −1
Original line number Original line Diff line number Diff line
@@ -435,11 +435,236 @@ class TableLogBufferTest : SysuiTestCase() { 




        assertThat(dumpedString).doesNotContain("testString[0]")

        assertThat(dumpedString).doesNotContain("testString[0]")

        assertThat(dumpedString).doesNotContain("testString[1]")

        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[3]")

        assertThat(dumpedString).contains("testString[${MAX_SIZE + 2}]")

        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 {

    private fun dumpChanges(): String {

        underTest.dump(PrintWriter(outputWriter), arrayOf())

        underTest.dump(PrintWriter(outputWriter), arrayOf())

        return outputWriter.toString()

        return outputWriter.toString()