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

Commit 5a36c17a authored by Fengjiang Li's avatar Fengjiang Li
Browse files

[1/n] Launcher Startup Latency: add StartupLatencyLogger to launcher3 and log startup latency 

More details at "Log Startup Latency" section in go/launcher-startup-latency

Test: tested on phone, foldable and tablet, print latency logs in logcat
Bug: 278092752
Change-Id: Ibf269b0ecd6007d29b95e36f65ab6f02c45deb3a
parent 5f456635

quickstep/src/com/android/launcher3/uioverrides/QuickstepLauncher.java

+3 −2
Original line number Diff line number Diff line
@@ -1063,7 +1063,8 @@ public class QuickstepLauncher extends Launcher { 
    }



    @Override

    public void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks) {

    public void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks,

            int workspaceItemCount, boolean isBindSync) {

        pendingTasks.add(() -> {

            // This is added in pending task as we need to wait for views to be positioned

            // correctly before registering them for the animation.
@@ -1073,7 +1074,7 @@ public class QuickstepLauncher extends Launcher { 
                mLauncherUnfoldAnimationController.updateRegisteredViewsIfNeeded();

            }

        });

        super.onInitialBindComplete(boundPages, pendingTasks);

        super.onInitialBindComplete(boundPages, pendingTasks, workspaceItemCount, isBindSync);

    }



    @Override

src/com/android/launcher3/Launcher.java

+61 −3
Original line number Diff line number Diff line
@@ -56,6 +56,14 @@ import static com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCH 
import static com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCHER_SWIPELEFT;

import static com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCHER_SWIPERIGHT;

import static com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCHER_WIDGET_RECONFIGURED;

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

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;

import static com.android.launcher3.model.ItemInstallQueue.FLAG_ACTIVITY_PAUSED;

import static com.android.launcher3.model.ItemInstallQueue.FLAG_DRAG_AND_DROP;

import static com.android.launcher3.popup.SystemShortcut.APP_INFO;
@@ -64,7 +72,6 @@ import static com.android.launcher3.popup.SystemShortcut.WIDGETS; 
import static com.android.launcher3.states.RotationHelper.REQUEST_LOCK;

import static com.android.launcher3.states.RotationHelper.REQUEST_NONE;

import static com.android.launcher3.util.Executors.MAIN_EXECUTOR;

import static com.android.launcher3.util.Executors.MODEL_EXECUTOR;

import static com.android.launcher3.util.ItemInfoMatcher.forFolderMatch;



import android.animation.Animator;
@@ -111,6 +118,7 @@ import android.view.Menu; 
import android.view.MotionEvent;

import android.view.View;

import android.view.ViewGroup;

import android.view.ViewTreeObserver;

import android.view.ViewTreeObserver.OnPreDrawListener;

import android.view.WindowManager.LayoutParams;

import android.view.accessibility.AccessibilityEvent;
@@ -157,6 +165,7 @@ import com.android.launcher3.logger.LauncherAtom.WorkspaceContainer; 
import com.android.launcher3.logging.FileLog;

import com.android.launcher3.logging.InstanceId;

import com.android.launcher3.logging.InstanceIdSequence;

import com.android.launcher3.logging.StartupLatencyLogger;

import com.android.launcher3.logging.StatsLogManager;

import com.android.launcher3.model.BgDataModel.Callbacks;

import com.android.launcher3.model.ItemInstallQueue;
@@ -190,6 +199,7 @@ import com.android.launcher3.util.ActivityTracker; 
import com.android.launcher3.util.ComponentKey;

import com.android.launcher3.util.IntArray;

import com.android.launcher3.util.IntSet;

import com.android.launcher3.util.LockedUserState;

import com.android.launcher3.util.OnboardingPrefs;

import com.android.launcher3.util.PackageUserKey;

import com.android.launcher3.util.PendingRequestArgs;
@@ -293,6 +303,8 @@ public class Launcher extends StatefulActivity<LauncherState> 
    public static final String ON_RESUME_EVT = "Launcher.onResume";

    public static final String ON_NEW_INTENT_EVT = "Launcher.onNewIntent";



    private static boolean sIsNewProcess = true;



    private StateManager<LauncherState> mStateManager;



    private static final int ON_ACTIVITY_RESULT_ANIMATION_DELAY = 500;
@@ -404,12 +416,22 @@ public class Launcher extends StatefulActivity<LauncherState> 


    private StringCache mStringCache;

    private BaseSearchConfig mBaseSearchConfig;



    private StartupLatencyLogger mStartupLatencyLogger;

    private CellPosMapper mCellPosMapper = CellPosMapper.DEFAULT;



    @Override

    @TargetApi(Build.VERSION_CODES.S)

    protected void onCreate(Bundle savedInstanceState) {

        mStartupLatencyLogger = createStartupLatencyLogger(

                sIsNewProcess

                        ? LockedUserState.get(this).isUserUnlockedAtLauncherStartup()

                            ? COLD

                            : COLD_DEVICE_REBOOTING

                        : WARM);

        sIsNewProcess = false;

        mStartupLatencyLogger

                .logStart(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION)

                .logStart(LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE);

        // Only use a hard-coded cookie since we only want to trace this once.

        if (Utilities.ATLEAST_S) {

            Trace.beginAsyncSection(
@@ -518,6 +540,7 @@ public class Launcher extends StatefulActivity<LauncherState> 
            }

        }



        mStartupLatencyLogger.logWorkspaceLoadStartTime();

        if (!mModel.addCallbacksAndLoad(this)) {

            if (!internalStateHandled) {

                // If we are not binding synchronously, pause drawing until initial bind complete,
@@ -557,6 +580,17 @@ public class Launcher extends StatefulActivity<LauncherState> 
            getWindow().setSoftInputMode(LayoutParams.SOFT_INPUT_ADJUST_NOTHING);

        }

        setTitle(R.string.home_screen);

        mStartupLatencyLogger.logEnd(LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE);

    }



    /**

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

     */

    protected StartupLatencyLogger createStartupLatencyLogger(

            StatsLogManager.StatsLatencyLogger.LatencyType latencyType) {

        return new StartupLatencyLogger(latencyType);

    }



    /**
@@ -1290,7 +1324,10 @@ public class Launcher extends StatefulActivity<LauncherState> 
     * Finds all the views we need and configure them properly.

     */

    protected void setupViews() {

        mStartupLatencyLogger.logStart(LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION);

        inflateRootView(R.layout.launcher);

        mStartupLatencyLogger.logEnd(LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION);



        mDragLayer = findViewById(R.id.drag_layer);

        mFocusHandler = mDragLayer.getFocusIndicatorHelper();

        mWorkspace = mDragLayer.findViewById(R.id.workspace);
@@ -2695,7 +2732,8 @@ public class Launcher extends StatefulActivity<LauncherState> 


    @Override

    @TargetApi(Build.VERSION_CODES.S)

    public void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks) {

    public void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks,

            int workspaceItemCount, boolean isBindSync) {

        mSynchronouslyBoundPages = boundPages;

        mPagesToBindSynchronously = new IntSet();
@@ -2719,6 +2757,26 @@ public class Launcher extends StatefulActivity<LauncherState> 
            Trace.endAsyncSection(DISPLAY_WORKSPACE_TRACE_METHOD_NAME,

                    DISPLAY_WORKSPACE_TRACE_COOKIE);

        }

        mStartupLatencyLogger

                .logCardinality(workspaceItemCount)

                .logEnd(isBindSync

                        ? LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC

                        : LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC);

        // In the first rootview's onDraw after onInitialBindComplete(), log end of startup latency.

        getRootView().getViewTreeObserver().addOnDrawListener(

                new ViewTreeObserver.OnDrawListener() {



                    @Override

                    public void onDraw() {

                        mStartupLatencyLogger

                                .logEnd(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION)

                                .log()

                                .reset();

                        MAIN_EXECUTOR.getHandler().postAtFrontOfQueue(

                                () -> getRootView().getViewTreeObserver()

                                        .removeOnDrawListener(this));

                    }

                });

    }



    /**

src/com/android/launcher3/LauncherModel.java

+1 −1
Original line number Diff line number Diff line
@@ -417,7 +417,7 @@ public class LauncherModel extends LauncherApps.Callback implements InstallSessi 
                if (bindDirectly) {

                    // Divide the set of loaded items into those that we are binding synchronously,

                    // and everything else that is to be bound normally (asynchronously).

                    launcherBinder.bindWorkspace(bindAllCallbacks);

                    launcherBinder.bindWorkspace(bindAllCallbacks, /* isBindSync= */ true);

                    // For now, continue posting the binding of AllApps as there are other

                    // issues that arise from that.

                    launcherBinder.bindAllApps();

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

0 → 100644
+203 −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.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 val startTimeByEvent = SparseLongArray()

    @VisibleForTesting val endTimeByEvent = SparseLongArray()



    @VisibleForTesting var cardinality: Int = UNSET_INT

    @VisibleForTesting var workspaceLoadStartTime: Long = UNSET_LONG



    private var isInTest = false



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

    @MainThread

    open fun log(): StartupLatencyLogger {

        return this

    }



    @MainThread

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



    @VisibleForTesting

    @MainThread

    fun logWorkspaceLoadStartTime(startTimeMs: Long): StartupLatencyLogger {

        Preconditions.assertUIThread()

        workspaceLoadStartTime = startTimeMs

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

        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 (validateLoggingEventAtStart(event)) {

            startTimeByEvent.put(event.id, startTimeMs)

        }

        return this

    }



    @MainThread

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



    @MainThread

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

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

        Preconditions.assertUIThread()

        maybeLogStartOfWorkspaceLoadTime(event)

        if (validateLoggingEventAtEnd(event)) {

            endTimeByEvent.put(event.id, endTimeMs)

        }



        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

    }



    @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

        }

    }



    /** @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, String.format("Cannot restart same %s event", event.name))

            return false

        } else if (

            startTimeByEvent.isEmpty() &&

                event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION

        ) {

            Log.e(

                TAG,

                String.format(

                    "The first log start event must be %s.",

                    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,

                String.format(

                    "Cannot start %s event after %s starts",

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.name,

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.name

                )

            )

            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,

                String.format(

                    "Cannot start %s event after %s starts",

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.name,

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.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, String.format("Cannot end %s event before starting it", event.name))

            return false

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

            Log.e(TAG, String.format("Cannot end same %s event again", event.name))

            return false

        } else if (

            event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION &&

                endTimeByEvent.contains(

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id

                )

        ) {

            Log.e(

                TAG,

                String.format(

                    "Cannot end %s event after %s",

                    event.name,

                    LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name

                )

            )

            return false

        }

        return true

    }



    @VisibleForTesting

    fun setIsInTest() {

        isInTest = true

    }

}

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

+37 −1
Original line number Diff line number Diff line
@@ -657,6 +657,39 @@ public class StatsLogManager implements ResourceBasedOverride { 
        }

    }



    /** Launcher's latency events. */

    public enum LauncherLatencyEvent implements EventEnum {

        // Details of below 6 events with prefix of "LAUNCHER_LATENCY_STARTUP_" are discussed in

        // go/launcher-startup-latency

        @UiEvent(doc = "The total duration of launcher startup latency.")

        LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION(1362),



        @UiEvent(doc = "The duration of launcher activity's onCreate().")

        LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE(1363),



        @UiEvent(doc =

                "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),

        ;



        private final int mId;



        LauncherLatencyEvent(int id) {

            mId = id;

        }



        @Override

        public int getId() {

            return mId;

        }

    }



    /**

     * Launcher specific ranking related events.

     */
@@ -807,7 +840,10 @@ public class StatsLogManager implements ResourceBasedOverride { 
            CONTROLLED(7),

            CACHED(8),

            // example: device is rebooting via power key or shell command `adb reboot`

            COLD_DEVICE_REBOOTING(9);

            COLD_DEVICE_REBOOTING(9),

            // Tracking warm startup latency:

            // https://developer.android.com/topic/performance/vitals/launch-time#warm

            WARM(10);

            private final int mId;



            LatencyType(int id) {