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

Commit d4d755e3 authored by Michal Brzezinski's avatar Michal Brzezinski Committed by Michał Brzeziński
Browse files

Sending display switch event even if something went wrong 

Until now display switch event was sent only in happy path but now it will be sent also after timeout and entering corrupted state - that way we can track how often these corner cases happen.
To distinguish these cases, new field "tracking result" was introduced to the event.

Bug: 390649568
Flag: com.android.systemui.unfold_latency_tracking_fix
Test: DisplaySwitchLatencyTrackerTest
Change-Id: I8043279e4c5e2053b3f0c29ecfe570d2fcbc6d1f
parent 1c2633f9

packages/SystemUI/multivalentTests/src/com/android/systemui/unfold/DisplaySwitchLatencyTrackerTest.kt

+65 −24
Original line number Diff line number Diff line
@@ -173,15 +173,13 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
            runCurrent()

            setDeviceState(UNFOLDED)



            verify(displaySwitchLatencyLogger).log(capture(loggerArgumentCaptor))

            val loggedEvent = loggerArgumentCaptor.value

            val expectedLoggedEvent =

                DisplaySwitchLatencyEvent(

                successfulEvent(

                    latencyMs = 250,

                    fromFoldableDeviceState = FOLDABLE_DEVICE_STATE_CLOSED,

                    toFoldableDeviceState = FOLDABLE_DEVICE_STATE_HALF_OPEN,

                )

            assertThat(loggedEvent).isEqualTo(expectedLoggedEvent)

            assertThat(capturedLogEvent()).isEqualTo(expectedLoggedEvent)

        }

    }
@@ -225,15 +223,13 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
            runCurrent()

            setDeviceState(UNFOLDED)



            verify(displaySwitchLatencyLogger).log(capture(loggerArgumentCaptor))

            val loggedEvent = loggerArgumentCaptor.value

            val expectedLoggedEvent =

                DisplaySwitchLatencyEvent(

                successfulEvent(

                    latencyMs = 50,

                    fromFoldableDeviceState = FOLDABLE_DEVICE_STATE_CLOSED,

                    toFoldableDeviceState = FOLDABLE_DEVICE_STATE_HALF_OPEN,

                )

            assertThat(loggedEvent).isEqualTo(expectedLoggedEvent)

            assertThat(capturedLogEvent()).isEqualTo(expectedLoggedEvent)

        }

    }
@@ -258,15 +254,13 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
            runCurrent()

            setDeviceState(UNFOLDED)



            verify(displaySwitchLatencyLogger).log(capture(loggerArgumentCaptor))

            val loggedEvent = loggerArgumentCaptor.value

            val expectedLoggedEvent =

                DisplaySwitchLatencyEvent(

                successfulEvent(

                    latencyMs = 50,

                    fromFoldableDeviceState = FOLDABLE_DEVICE_STATE_CLOSED,

                    toFoldableDeviceState = FOLDABLE_DEVICE_STATE_HALF_OPEN,

                )

            assertThat(loggedEvent).isEqualTo(expectedLoggedEvent)

            assertThat(capturedLogEvent()).isEqualTo(expectedLoggedEvent)

        }

    }
@@ -287,15 +281,13 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
            powerInteractor.setScreenPowerState(SCREEN_ON)

            runCurrent()



            verify(displaySwitchLatencyLogger).log(capture(loggerArgumentCaptor))

            val loggedEvent = loggerArgumentCaptor.value

            val expectedLoggedEvent =

                DisplaySwitchLatencyEvent(

                successfulEvent(

                    latencyMs = 200,

                    fromFoldableDeviceState = FOLDABLE_DEVICE_STATE_HALF_OPEN,

                    toFoldableDeviceState = FOLDABLE_DEVICE_STATE_CLOSED,

                )

            assertThat(loggedEvent).isEqualTo(expectedLoggedEvent)

            assertThat(capturedLogEvent()).isEqualTo(expectedLoggedEvent)

        }

    }
@@ -317,16 +309,14 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
            powerInteractor.setScreenPowerState(SCREEN_ON)

            runCurrent()



            verify(displaySwitchLatencyLogger).log(capture(loggerArgumentCaptor))

            val loggedEvent = loggerArgumentCaptor.value

            val expectedLoggedEvent =

                DisplaySwitchLatencyEvent(

                successfulEvent(

                    latencyMs = 200,

                    fromFoldableDeviceState = FOLDABLE_DEVICE_STATE_HALF_OPEN,

                    toFoldableDeviceState = FOLDABLE_DEVICE_STATE_CLOSED,

                    toState = SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TO_STATE__AOD,

                )

            assertThat(loggedEvent).isEqualTo(expectedLoggedEvent)

            assertThat(capturedLogEvent()).isEqualTo(expectedLoggedEvent)

        }

    }
@@ -369,16 +359,14 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
            powerInteractor.setScreenPowerState(SCREEN_OFF)

            runCurrent()



            verify(displaySwitchLatencyLogger).log(capture(loggerArgumentCaptor))

            val loggedEvent = loggerArgumentCaptor.value

            val expectedLoggedEvent =

                DisplaySwitchLatencyEvent(

                successfulEvent(

                    latencyMs = 0,

                    fromFoldableDeviceState = FOLDABLE_DEVICE_STATE_HALF_OPEN,

                    toFoldableDeviceState = FOLDABLE_DEVICE_STATE_CLOSED,

                    toState = SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TO_STATE__SCREEN_OFF,

                )

            assertThat(loggedEvent).isEqualTo(expectedLoggedEvent)

            assertThat(capturedLogEvent()).isEqualTo(expectedLoggedEvent)

        }

    }
@@ -554,6 +542,23 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
        }

    }



    @Test

    fun interruptedDisplaySwitchFinished_coolDownPassed_eventWithCorruptedResultSent() {

        testScope.runTest {

            startInFoldedState(displaySwitchLatencyTracker)



            startUnfolding()

            startFolding()

            systemClock.advanceTime(5000) // clock for measuring latency

            advanceTimeBy(COOL_DOWN_DURATION.plus(10.milliseconds)) // clock for triggering timeout



            val event = capturedLogEvent()

            assertThat(event.trackingResult)

                .isEqualTo(SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TRACKING_RESULT__CORRUPTED)

            assertThat(event.latencyMs).isEqualTo(5000)

        }

    }



    @Test

    fun displaySwitchInterrupted_coolDownExtendedByStartEvents() {

        testScope.runTest {
@@ -604,6 +609,27 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
        }

    }



    @Test

    fun displaySwitchTimedOut_eventLoggedWithTimeOut() {

        testScope.runTest {

            startInFoldedState(displaySwitchLatencyTracker)



            startUnfolding()

            advanceTimeBy(SCREEN_EVENT_TIMEOUT + 10.milliseconds)

            finishUnfolding()



            val event = capturedLogEvent()

            assertThat(event.trackingResult)

                .isEqualTo(SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TRACKING_RESULT__TIMED_OUT)

            assertThat(event.latencyMs).isEqualTo(SCREEN_EVENT_TIMEOUT.inWholeMilliseconds)

        }

    }



    private fun capturedLogEvent(): DisplaySwitchLatencyEvent {

        verify(displaySwitchLatencyLogger).log(capture(loggerArgumentCaptor))

        return loggerArgumentCaptor.value

    }



    @Test

    fun foldingStarted_screenStillOn_eventSentOnlyAfterScreenSwitches() {

        // can happen for both folding and unfolding (with animations off) but it's more likely to
@@ -625,6 +651,21 @@ class DisplaySwitchLatencyTrackerTest : SysuiTestCase() { 
        }

    }



    private fun successfulEvent(

        latencyMs: Int,

        fromFoldableDeviceState: Int,

        toFoldableDeviceState: Int,

        toState: Int = SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__FROM_STATE__UNKNOWN,

    ): DisplaySwitchLatencyEvent {

        return DisplaySwitchLatencyEvent(

            latencyMs = latencyMs,

            fromFoldableDeviceState = fromFoldableDeviceState,

            toFoldableDeviceState = toFoldableDeviceState,

            toState = toState,

            trackingResult = SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TRACKING_RESULT__SUCCESS,

        )

    }



    private suspend fun TestScope.startInFoldedState(tracker: DisplaySwitchLatencyTracker) {

        setDeviceState(FOLDED)

        tracker.start()

packages/SystemUI/src/com/android/systemui/unfold/DisplaySwitchLatencyLogger.kt

+1 −0
Original line number Diff line number Diff line
@@ -49,6 +49,7 @@ class DisplaySwitchLatencyLogger { 
                hallSensorToDeviceStateChangeMs,

                onScreenTurningOnToOnDrawnMs,

                onDrawnToOnScreenTurnedOnMs,

                trackingResult,

            )

        }

    }

packages/SystemUI/src/com/android/systemui/unfold/DisplaySwitchLatencyTracker.kt

+54 −16
Original line number Diff line number Diff line
@@ -37,12 +37,16 @@ import com.android.systemui.power.shared.model.WakefulnessModel 
import com.android.systemui.power.shared.model.WakefulnessState

import com.android.systemui.shared.system.SysUiStatsLog

import com.android.systemui.unfold.DisplaySwitchLatencyTracker.DisplaySwitchLatencyEvent

import com.android.systemui.unfold.DisplaySwitchLatencyTracker.TrackingResult.CORRUPTED

import com.android.systemui.unfold.DisplaySwitchLatencyTracker.TrackingResult.SUCCESS

import com.android.systemui.unfold.DisplaySwitchLatencyTracker.TrackingResult.TIMED_OUT

import com.android.systemui.unfold.dagger.UnfoldSingleThreadBg

import com.android.systemui.unfold.data.repository.UnfoldTransitionStatus.TransitionStarted

import com.android.systemui.unfold.domain.interactor.UnfoldTransitionInteractor

import com.android.systemui.util.Compile

import com.android.systemui.util.Utils.isDeviceFoldable

import com.android.systemui.util.animation.data.repository.AnimationStatusRepository

import com.android.systemui.util.kotlin.WithPrev

import com.android.systemui.util.kotlin.pairwise

import com.android.systemui.util.kotlin.race

import com.android.systemui.util.time.SystemClock
@@ -56,7 +60,6 @@ import kotlinx.coroutines.FlowPreview 
import kotlinx.coroutines.TimeoutCancellationException

import kotlinx.coroutines.asCoroutineDispatcher

import kotlinx.coroutines.flow.Flow

import kotlinx.coroutines.flow.collect

import kotlinx.coroutines.flow.collectLatest

import kotlinx.coroutines.flow.drop

import kotlinx.coroutines.flow.filter
@@ -116,10 +119,9 @@ constructor( 
                    latencyTracker.onActionStart(ACTION_SWITCH_DISPLAY_UNFOLD)

                    instantForTrack(TAG) { "unfold latency tracking started" }

                }

                val event = DisplaySwitchLatencyEvent().withBeforeFields(previousState.toStatsInt())

                try {

                    withTimeout(SCREEN_EVENT_TIMEOUT) {

                        val event =

                            DisplaySwitchLatencyEvent().withBeforeFields(previousState.toStatsInt())

                        val displaySwitchTimeMs =

                            measureTimeMillis(systemClock) {

                                traceAsync(TAG, "displaySwitch") {
@@ -134,27 +136,43 @@ constructor( 
                } catch (e: TimeoutCancellationException) {

                    instantForTrack(TAG) { "tracking timed out" }

                    latencyTracker.onActionCancel(ACTION_SWITCH_DISPLAY_UNFOLD)

                    logDisplaySwitchEvent(

                        event = event,

                        toFoldableDeviceState = newState,

                        displaySwitchTimeMs = SCREEN_EVENT_TIMEOUT.inWholeMilliseconds,

                        trackingResult = TIMED_OUT,

                    )

                } catch (e: CancellationException) {

                    instantForTrack(TAG) { "new state interrupted, entering cool down" }

                    latencyTracker.onActionCancel(ACTION_SWITCH_DISPLAY_UNFOLD)

                    startCoolDown()

                    startCoolDown(event)

                }

            }

        }

    }



    @OptIn(FlowPreview::class)

    private fun startCoolDown() {

    private fun startCoolDown(event: DisplaySwitchLatencyEvent) {

        if (isCoolingDown) return

        isCoolingDown = true

        applicationScope.launch(context = backgroundDispatcher) {

            val startTime = systemClock.elapsedRealtime()

            var lastState: DeviceState? = null

            try {

                startOrEndEvent.timeout(COOL_DOWN_DURATION).collect()

            } catch (e: TimeoutCancellationException) {

                instantForTrack(TAG) {

                    "cool down finished, lasted ${systemClock.elapsedRealtime() - startTime} ms"

                startOrEndEvent.timeout(COOL_DOWN_DURATION).collect {

                    if (it is WithPrev<*, *>) {

                        lastState = it.newValue as? DeviceState

                    }

                }

            } catch (e: TimeoutCancellationException) {

                val totalCooldownTime = systemClock.elapsedRealtime() - startTime

                logDisplaySwitchEvent(

                    event = event,

                    toFoldableDeviceState = lastState ?: DeviceState.UNKNOWN,

                    displaySwitchTimeMs = totalCooldownTime,

                    trackingResult = CORRUPTED,

                )

                instantForTrack(TAG) { "cool down finished, lasted $totalCooldownTime ms" }

                isCoolingDown = false

            }

        }
@@ -164,12 +182,14 @@ constructor( 
        event: DisplaySwitchLatencyEvent,

        toFoldableDeviceState: DeviceState,

        displaySwitchTimeMs: Long,

        trackingResult: TrackingResult = SUCCESS,

    ) {

        displaySwitchLatencyLogger.log(

            event.withAfterFields(

                toFoldableDeviceState.toStatsInt(),

                displaySwitchTimeMs.toInt(),

                toFoldableDeviceState,

                displaySwitchTimeMs,

                getCurrentState(),

                trackingResult,

            )

        )

    }
@@ -183,6 +203,13 @@ constructor( 
            else -> FOLDABLE_DEVICE_STATE_UNKNOWN

        }



    private fun TrackingResult.toStatsInt(): Int =

        when (this) {

            SUCCESS -> SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TRACKING_RESULT__SUCCESS

            CORRUPTED -> SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TRACKING_RESULT__CORRUPTED

            TIMED_OUT -> SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TRACKING_RESULT__TIMED_OUT

        }



    private suspend fun waitForDisplaySwitch(toFoldableDeviceState: Int) {

        val isTransitionEnabled =

            unfoldTransitionInteractor.isAvailable &&
@@ -264,11 +291,13 @@ constructor( 
    }



    private fun DisplaySwitchLatencyEvent.withAfterFields(

        toFoldableDeviceState: Int,

        displaySwitchTimeMs: Int,

        toFoldableDeviceState: DeviceState,

        displaySwitchTimeMs: Long,

        toState: Int,

        trackingResult: TrackingResult,

    ): DisplaySwitchLatencyEvent {

        log {

            "trackingResult=$trackingResult, " +

                "toFoldableDeviceState=$toFoldableDeviceState, " +

                "toState=$toState, " +

                "latencyMs=$displaySwitchTimeMs"
@@ -276,9 +305,10 @@ constructor( 
        instantForTrack(TAG) { "toFoldableDeviceState=$toFoldableDeviceState, toState=$toState" }



        return copy(

            toFoldableDeviceState = toFoldableDeviceState,

            latencyMs = displaySwitchTimeMs,

            toFoldableDeviceState = toFoldableDeviceState.toStatsInt(),

            latencyMs = displaySwitchTimeMs.toInt(),

            toState = toState,

            trackingResult = trackingResult.toStatsInt(),

        )

    }
@@ -312,8 +342,16 @@ constructor( 
        val hallSensorToDeviceStateChangeMs: Int = VALUE_UNKNOWN,

        val onScreenTurningOnToOnDrawnMs: Int = VALUE_UNKNOWN,

        val onDrawnToOnScreenTurnedOnMs: Int = VALUE_UNKNOWN,

        val trackingResult: Int =

            SysUiStatsLog.DISPLAY_SWITCH_LATENCY_TRACKED__TRACKING_RESULT__UNKNOWN_RESULT,

    )



    enum class TrackingResult {

        SUCCESS,

        CORRUPTED,

        TIMED_OUT,

    }



    companion object {

        private const val VALUE_UNKNOWN = -1

        private const val TAG = "DisplaySwitchLatency"