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

Commit e5f91a4c authored by Fengjiang Li's avatar Fengjiang Li
Browse files

Only log COLD_DEVICE_REBOOTING startup latency logs 

Fix: 305391017
Test: Unit test
Flag: NA
Change-Id: I976add25ea14d49e2ea84e395985edb9f559370c
parent 7056e2d2

src/com/android/launcher3/Launcher.java

+24 −12
Original line number Diff line number Diff line
@@ -49,8 +49,8 @@ import static com.android.launcher3.LauncherConstants.TraceEvents.COLD_STARTUP_T 
import static com.android.launcher3.LauncherConstants.TraceEvents.COLD_STARTUP_TRACE_METHOD_NAME;

import static com.android.launcher3.LauncherConstants.TraceEvents.DISPLAY_ALL_APPS_TRACE_COOKIE;

import static com.android.launcher3.LauncherConstants.TraceEvents.DISPLAY_ALL_APPS_TRACE_METHOD_NAME;

import static com.android.launcher3.LauncherConstants.TraceEvents.DISPLAY_WORKSPACE_TRACE_METHOD_NAME;

import static com.android.launcher3.LauncherConstants.TraceEvents.DISPLAY_WORKSPACE_TRACE_COOKIE;

import static com.android.launcher3.LauncherConstants.TraceEvents.DISPLAY_WORKSPACE_TRACE_METHOD_NAME;

import static com.android.launcher3.LauncherConstants.TraceEvents.ON_CREATE_EVT;

import static com.android.launcher3.LauncherConstants.TraceEvents.ON_NEW_INTENT_EVT;

import static com.android.launcher3.LauncherConstants.TraceEvents.ON_RESUME_EVT;
@@ -86,7 +86,6 @@ import static com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent 
import static com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION;

import static com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION;

import static com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC;

import static com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC;

import static com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LatencyType.COLD;

import static com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LatencyType.COLD_DEVICE_REBOOTING;

import static com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LatencyType.WARM;
@@ -188,6 +187,7 @@ import com.android.launcher3.keyboard.ViewGroupFocusHelper; 
import com.android.launcher3.logger.LauncherAtom;

import com.android.launcher3.logger.LauncherAtom.ContainerInfo;

import com.android.launcher3.logger.LauncherAtom.WorkspaceContainer;

import com.android.launcher3.logging.ColdRebootStartupLatencyLogger;

import com.android.launcher3.logging.FileLog;

import com.android.launcher3.logging.InstanceId;

import com.android.launcher3.logging.InstanceIdSequence;
@@ -598,13 +598,24 @@ public class Launcher extends StatefulActivity<LauncherState> 
    }



    /**

     * Create {@link StartupLatencyLogger} that only collects launcher startup latency metrics

     * without sending them anywhere. Child class can override this method to create logger

     * that overrides {@link StartupLatencyLogger#log()} to report those metrics.

     * We only log startup latency in {@link COLD_DEVICE_REBOOTING} type. For other latency types,

     * create a no op implementation.

     */

    protected StartupLatencyLogger createStartupLatencyLogger(

    private StartupLatencyLogger createStartupLatencyLogger(

            StatsLogManager.StatsLatencyLogger.LatencyType latencyType) {

        return new StartupLatencyLogger(latencyType);

        if (latencyType == COLD_DEVICE_REBOOTING) {

            return createColdRebootStartupLatencyLogger();

        }

        return StartupLatencyLogger.Companion.getNO_OP();

    }



    /**

     * Create {@link ColdRebootStartupLatencyLogger} that only collects launcher startup latency

     * metrics without sending them anywhere. Child class can override this method to create logger

     * that overrides {@link StartupLatencyLogger#log()} to report those metrics.

     */

    protected ColdRebootStartupLatencyLogger createColdRebootStartupLatencyLogger() {

        return new ColdRebootStartupLatencyLogger();

    }



    /**
@@ -2592,11 +2603,12 @@ public class Launcher extends StatefulActivity<LauncherState> 
            Trace.endAsyncSection(DISPLAY_WORKSPACE_TRACE_METHOD_NAME,

                    DISPLAY_WORKSPACE_TRACE_COOKIE);

        }

        if (!isBindSync) {

            mStartupLatencyLogger

                    .logCardinality(workspaceItemCount)

                .logEnd(isBindSync

                        ? LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC

                        : LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC);

                    .logEnd(LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC);

        }



        MAIN_EXECUTOR.getHandler().postAtFrontOfQueue(() -> {

            mStartupLatencyLogger

                    .logEnd(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION)

src/com/android/launcher3/logging/ColdRebootStartupLatencyLogger.kt

0 → 100644
+192 −0
Original line number Diff line number Diff line 
package com.android.launcher3.logging



import android.os.SystemClock

import android.util.Log

import android.util.SparseLongArray

import androidx.annotation.MainThread

import androidx.annotation.VisibleForTesting

import androidx.core.util.contains

import androidx.core.util.isEmpty

import com.android.launcher3.BuildConfig

import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent

import com.android.launcher3.util.Preconditions



/** Logger for logging Launcher activity's startup latency. */

open class ColdRebootStartupLatencyLogger : StartupLatencyLogger {



    companion object {

        const val TAG = "ColdRebootStartupLatencyLogger"

        const val UNSET_INT = -1

        const val UNSET_LONG = -1L

    }



    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)

    val startTimeByEvent = SparseLongArray()

    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)

    val endTimeByEvent = SparseLongArray()



    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED) var cardinality: Int = UNSET_INT

    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)

    var workspaceLoadStartTime: Long = UNSET_LONG



    // ColdRebootStartupLatencyLogger should only send launcher startup logs once in each launcher

    // activity lifecycle. After launcher activity startup is completed, the logger should be torn

    // down and reject all logging calls. This flag should be checked at all APIs to prevent logging

    // invalid startup metrics (such as loading workspace in screen rotation).

    var isTornDown = false

    private var isInTest = false



    /** Subclass can override this method to handle collected latency metrics. */

    @MainThread

    override fun log(): ColdRebootStartupLatencyLogger {

        return this

    }



    @MainThread

    override fun logWorkspaceLoadStartTime() =

        logWorkspaceLoadStartTime(SystemClock.elapsedRealtime())



    @VisibleForTesting

    @MainThread

    fun logWorkspaceLoadStartTime(startTimeMs: Long): ColdRebootStartupLatencyLogger {

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        workspaceLoadStartTime = startTimeMs

        return this

    }



    /**

     * Log size of workspace. Larger number of workspace items (icons, folders, widgets) means

     * longer latency to initialize workspace.

     */

    @MainThread

    override fun logCardinality(cardinality: Int): ColdRebootStartupLatencyLogger {

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        this.cardinality = cardinality

        return this

    }



    @MainThread

    override fun logStart(event: LauncherLatencyEvent) =

        logStart(event, SystemClock.elapsedRealtime())



    @MainThread

    override fun logStart(

        event: LauncherLatencyEvent,

        startTimeMs: Long

    ): ColdRebootStartupLatencyLogger {

        // In unit test no looper is attached to current thread

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        if (validateLoggingEventAtStart(event)) {

            startTimeByEvent.put(event.id, startTimeMs)

        }

        return this

    }



    @MainThread

    override fun logEnd(event: LauncherLatencyEvent) = logEnd(event, SystemClock.elapsedRealtime())



    @MainThread

    override fun logEnd(

        event: LauncherLatencyEvent,

        endTimeMs: Long

    ): ColdRebootStartupLatencyLogger {

        // In unit test no looper is attached to current thread

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        maybeLogStartOfWorkspaceLoadTime(event)

        if (validateLoggingEventAtEnd(event)) {

            endTimeByEvent.put(event.id, endTimeMs)

        }



        return this

    }



    @MainThread

    override fun reset() {

        // In unit test no looper is attached to current thread

        Preconditions.assertUIThread()

        startTimeByEvent.clear()

        endTimeByEvent.clear()

        cardinality = UNSET_INT

        workspaceLoadStartTime = UNSET_LONG

        isTornDown = true

    }



    @MainThread

    private fun maybeLogStartOfWorkspaceLoadTime(event: LauncherLatencyEvent) {

        if (workspaceLoadStartTime == UNSET_LONG) {

            return

        }

        if (event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC) {

            logStart(event, workspaceLoadStartTime)

            workspaceLoadStartTime = UNSET_LONG

        }

    }



    /** @return true if we can log start of [LauncherLatencyEvent] and vice versa. */

    @MainThread

    private fun validateLoggingEventAtStart(event: LauncherLatencyEvent): Boolean {

        if (!BuildConfig.IS_STUDIO_BUILD && !isInTest) {

            return true

        }

        if (startTimeByEvent.contains(event.id)) {

            Log.e(TAG, "Cannot restart same ${event.name} event")

            return false

        } else if (

            startTimeByEvent.isEmpty() &&

                event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION

        ) {

            Log.e(

                TAG,

                "The first log start event must be " +

                    "${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name}.",

            )

            return false

        }



        return true

    }



    /** @return true if we can log end of [LauncherLatencyEvent] and vice versa. */

    @MainThread

    private fun validateLoggingEventAtEnd(event: LauncherLatencyEvent): Boolean {

        if (!BuildConfig.IS_STUDIO_BUILD && !isInTest) {

            return true

        }

        if (!startTimeByEvent.contains(event.id)) {

            Log.e(TAG, "Cannot end ${event.name} event before starting it")

            return false

        } else if (endTimeByEvent.contains(event.id)) {

            Log.e(TAG, "Cannot end same ${event.name} event again")

            return false

        } else if (

            event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION &&

                endTimeByEvent.contains(

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id

                )

        ) {

            Log.e(

                TAG,

                "Cannot end ${event.name} event after ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name}",

            )

            return false

        }

        return true

    }



    @VisibleForTesting

    fun setIsInTest() {

        isInTest = true

    }

}

src/com/android/launcher3/logging/StartupLatencyLogger.kt

+35 −197
Original line number Diff line number Diff line 
/*

 * Copyright (C) 2023 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.launcher3.logging



import android.os.SystemClock

import android.util.Log

import android.util.SparseLongArray

import androidx.annotation.MainThread

import androidx.annotation.VisibleForTesting

import androidx.core.util.contains

import androidx.core.util.isEmpty

import com.android.launcher3.BuildConfig

import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent

import com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LatencyType

import com.android.launcher3.util.Preconditions



/** Logger for logging Launcher activity's startup latency. */

open class StartupLatencyLogger(val latencyType: LatencyType) {



    companion object {

        const val TAG = "LauncherStartupLatencyLogger"

        const val UNSET_INT = -1

        const val UNSET_LONG = -1L

    }



    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)

    val startTimeByEvent = SparseLongArray()

    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)

    val endTimeByEvent = SparseLongArray()



    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED) var cardinality: Int = UNSET_INT

    @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)

    var workspaceLoadStartTime: Long = UNSET_LONG



    // StartupLatencyLogger should only send launcher startup logs once in each launcher activity

    // lifecycle. After launcher activity startup is completed, the logger should be torn down and

    // reject all logging calls. This flag should be checked at all APIs to prevent logging invalid

    // startup metrics (such as loading workspace in screen rotation).

    var isTornDown = false

    private var isInTest = false



    /** Subclass can override this method to handle collected latency metrics. */

    @MainThread

    open fun log(): StartupLatencyLogger {

        return this

    }

/** Interface to log launcher startup latency metrics. */

interface StartupLatencyLogger {



    @MainThread

    fun logWorkspaceLoadStartTime() = logWorkspaceLoadStartTime(SystemClock.elapsedRealtime())

    @MainThread fun log(): StartupLatencyLogger = this



    @VisibleForTesting

    @MainThread

    fun logWorkspaceLoadStartTime(startTimeMs: Long): StartupLatencyLogger {

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        workspaceLoadStartTime = startTimeMs

        return this

    }

    @MainThread fun logWorkspaceLoadStartTime(): StartupLatencyLogger = this



    /**

     * Log size of workspace. Larger number of workspace items (icons, folders, widgets) means

     * longer latency to initialize workspace.

     */

    @MainThread

    fun logCardinality(cardinality: Int): StartupLatencyLogger {

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        this.cardinality = cardinality

        return this

    }



    @MainThread

    fun logStart(event: LauncherLatencyEvent) = logStart(event, SystemClock.elapsedRealtime())



    @MainThread

    fun logStart(event: LauncherLatencyEvent, startTimeMs: Long): StartupLatencyLogger {

        // In unit test no looper is attached to current thread

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        if (validateLoggingEventAtStart(event)) {

            startTimeByEvent.put(event.id, startTimeMs)

        }

        return this

    }

    @MainThread fun logCardinality(cardinality: Int): StartupLatencyLogger = this



    @MainThread

    fun logEnd(event: LauncherLatencyEvent) = logEnd(event, SystemClock.elapsedRealtime())

    fun logStart(event: StatsLogManager.LauncherLatencyEvent): StartupLatencyLogger = this



    @MainThread

    fun logEnd(event: LauncherLatencyEvent, endTimeMs: Long): StartupLatencyLogger {

        // In unit test no looper is attached to current thread

        Preconditions.assertUIThread()

        if (isTornDown) {

            return this

        }

        maybeLogStartOfWorkspaceLoadTime(event)

        if (validateLoggingEventAtEnd(event)) {

            endTimeByEvent.put(event.id, endTimeMs)

        }

    fun logStart(

        event: StatsLogManager.LauncherLatencyEvent,

        startTimeMs: Long

    ): StartupLatencyLogger = this



        return this

    }



    @MainThread

    fun reset() {

        // In unit test no looper is attached to current thread

        Preconditions.assertUIThread()

        startTimeByEvent.clear()

        endTimeByEvent.clear()

        cardinality = UNSET_INT

        workspaceLoadStartTime = UNSET_LONG

        isTornDown = true

    }



    @MainThread

    private fun maybeLogStartOfWorkspaceLoadTime(event: LauncherLatencyEvent) {

        if (workspaceLoadStartTime == UNSET_LONG) {

            return

        }

        if (

            event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC ||

                event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC

        ) {

            logStart(event, workspaceLoadStartTime)

            workspaceLoadStartTime = UNSET_LONG

        }

    }

    @MainThread fun logEnd(event: StatsLogManager.LauncherLatencyEvent): StartupLatencyLogger = this



    /** @return true if we can log start of [LauncherLatencyEvent] and vice versa. */

    @MainThread

    private fun validateLoggingEventAtStart(event: LauncherLatencyEvent): Boolean {

        if (!BuildConfig.IS_STUDIO_BUILD && !isInTest) {

            return true

        }

        if (startTimeByEvent.contains(event.id)) {

            Log.e(TAG, "Cannot restart same ${event.name} event")

            return false

        } else if (

            startTimeByEvent.isEmpty() &&

                event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION

        ) {

            Log.e(

                TAG,

                "The first log start event must be " +

                    "${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name}.",

            )

            return false

        } else if (

            event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC &&

                startTimeByEvent.get(

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.id

                ) != 0L

        ) {

            Log.e(

                TAG,

                "Cannot start ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.name} event after ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.name} starts",

            )

            return false

        } else if (

            event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC &&

                startTimeByEvent.get(

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.id

                ) != 0L

        ) {

            Log.e(

                TAG,

                "Cannot start ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.name} event after ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.name} starts",

            )

            return false

        }

    fun logEnd(event: StatsLogManager.LauncherLatencyEvent, endTimeMs: Long): StartupLatencyLogger =

        this



        return true

    }

    @MainThread fun reset()



    /** @return true if we can log end of [LauncherLatencyEvent] and vice versa. */

    @MainThread

    private fun validateLoggingEventAtEnd(event: LauncherLatencyEvent): Boolean {

        if (!BuildConfig.IS_STUDIO_BUILD && !isInTest) {

            return true

        }

        if (!startTimeByEvent.contains(event.id)) {

            Log.e(TAG, "Cannot end ${event.name} event before starting it")

            return false

        } else if (endTimeByEvent.contains(event.id)) {

            Log.e(TAG, "Cannot end same ${event.name} event again")

            return false

        } else if (

            event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION &&

                endTimeByEvent.contains(

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id

                )

        ) {

            Log.e(

                TAG,

                "Cannot end ${event.name} event after ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name}",

            )

            return false

        } else if (

            latencyType == LatencyType.COLD_DEVICE_REBOOTING &&

                event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC

        ) {

            Log.e(

                TAG,

                "Cannot have ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.name} in ${LatencyType.COLD_DEVICE_REBOOTING.name} startup type"

            )

            return false

        }

        return true

    companion object {

        val NO_OP: StartupLatencyLogger =

            object : StartupLatencyLogger {

                override fun reset() {}

            }



    @VisibleForTesting

    fun setIsInTest() {

        isInTest = true

    }

}

src/com/android/launcher3/logging/StatsLogManager.java

+0 −3
Original line number Diff line number Diff line
@@ -696,9 +696,6 @@ public class StatsLogManager implements ResourceBasedOverride { 
                "The duration to inflate launcher root view in launcher activity's onCreate().")

        LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION(1364),



        @UiEvent(doc = "The duration of synchronous loading workspace")

        LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC(1366),



        @UiEvent(doc = "The duration of asynchronous loading workspace")

        LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC(1367),

        ;

tests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt

+10 −109

File changed.

Preview size limit exceeded, changes collapsed.