From 5a36c17a3240459296065eaed3ac2f1ffba252ee Mon Sep 17 00:00:00 2001 From: Fengjiang Li Date: Thu, 13 Apr 2023 18:18:27 +0000 Subject: [PATCH] [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 --- .../uioverrides/QuickstepLauncher.java | 5 +- src/com/android/launcher3/Launcher.java | 64 ++- src/com/android/launcher3/LauncherModel.java | 2 +- .../launcher3/logging/StartupLatencyLogger.kt | 203 ++++++++++ .../launcher3/logging/StatsLogManager.java | 38 +- .../launcher3/model/BaseLauncherBinder.java | 28 +- .../android/launcher3/model/BgDataModel.java | 4 +- .../android/launcher3/model/LoaderTask.java | 2 +- .../android/launcher3/util/LockedUserState.kt | 8 + .../logging/StartupLatencyLoggerTest.kt | 368 ++++++++++++++++++ .../model/ModelMultiCallbacksTest.java | 3 +- 11 files changed, 703 insertions(+), 22 deletions(-) create mode 100644 src/com/android/launcher3/logging/StartupLatencyLogger.kt create mode 100644 tests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt diff --git a/quickstep/src/com/android/launcher3/uioverrides/QuickstepLauncher.java b/quickstep/src/com/android/launcher3/uioverrides/QuickstepLauncher.java index d67dbaec09..eab44c4787 100644 --- a/quickstep/src/com/android/launcher3/uioverrides/QuickstepLauncher.java +++ b/quickstep/src/com/android/launcher3/uioverrides/QuickstepLauncher.java @@ -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 diff --git a/src/com/android/launcher3/Launcher.java b/src/com/android/launcher3/Launcher.java index 4dfd91820c..86a5f9f2a9 100644 --- a/src/com/android/launcher3/Launcher.java +++ b/src/com/android/launcher3/Launcher.java @@ -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 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 mStateManager; private static final int ON_ACTIVITY_RESULT_ANIMATION_DELAY = 500; @@ -404,12 +416,22 @@ public class Launcher extends StatefulActivity 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 } } + 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 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 * 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 @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 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)); + } + }); } /** diff --git a/src/com/android/launcher3/LauncherModel.java b/src/com/android/launcher3/LauncherModel.java index 6798667d64..d3e94e13e8 100644 --- a/src/com/android/launcher3/LauncherModel.java +++ b/src/com/android/launcher3/LauncherModel.java @@ -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(); diff --git a/src/com/android/launcher3/logging/StartupLatencyLogger.kt b/src/com/android/launcher3/logging/StartupLatencyLogger.kt new file mode 100644 index 0000000000..435f798216 --- /dev/null +++ b/src/com/android/launcher3/logging/StartupLatencyLogger.kt @@ -0,0 +1,203 @@ +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 + } +} diff --git a/src/com/android/launcher3/logging/StatsLogManager.java b/src/com/android/launcher3/logging/StatsLogManager.java index 5b4a02b296..8197b7322b 100644 --- a/src/com/android/launcher3/logging/StatsLogManager.java +++ b/src/com/android/launcher3/logging/StatsLogManager.java @@ -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) { diff --git a/src/com/android/launcher3/model/BaseLauncherBinder.java b/src/com/android/launcher3/model/BaseLauncherBinder.java index c946e2c2e2..ba9eb20073 100644 --- a/src/com/android/launcher3/model/BaseLauncherBinder.java +++ b/src/com/android/launcher3/model/BaseLauncherBinder.java @@ -78,14 +78,14 @@ public abstract class BaseLauncherBinder { /** * Binds all loaded data to actual views on the main thread. */ - public void bindWorkspace(boolean incrementBindId) { + public void bindWorkspace(boolean incrementBindId, boolean isBindSync) { if (FeatureFlags.ENABLE_WORKSPACE_LOADING_OPTIMIZATION.get()) { DisjointWorkspaceBinder workspaceBinder = initWorkspaceBinder(incrementBindId, mBgDataModel.collectWorkspaceScreens()); - workspaceBinder.bindCurrentWorkspacePages(); + workspaceBinder.bindCurrentWorkspacePages(isBindSync); workspaceBinder.bindOtherWorkspacePages(); } else { - bindWorkspaceAllAtOnce(incrementBindId); + bindWorkspaceAllAtOnce(incrementBindId, isBindSync); } } @@ -108,13 +108,13 @@ public abstract class BaseLauncherBinder { } } - private void bindWorkspaceAllAtOnce(boolean incrementBindId) { + private void bindWorkspaceAllAtOnce(boolean incrementBindId, boolean isBindSync) { // Save a copy of all the bg-thread collections ArrayList workspaceItems = new ArrayList<>(); ArrayList appWidgets = new ArrayList<>(); final IntArray orderedScreenIds = new IntArray(); ArrayList extraItems = new ArrayList<>(); - + final int workspaceItemCount; synchronized (mBgDataModel) { workspaceItems.addAll(mBgDataModel.workspaceItems); appWidgets.addAll(mBgDataModel.appWidgets); @@ -124,11 +124,13 @@ public abstract class BaseLauncherBinder { mBgDataModel.lastBindId++; } mMyBindingId = mBgDataModel.lastBindId; + workspaceItemCount = mBgDataModel.itemsIdMap.size(); } for (Callbacks cb : mCallbacksList) { new UnifiedWorkspaceBinder(cb, mUiExecutor, mApp, mBgDataModel, mMyBindingId, - workspaceItems, appWidgets, extraItems, orderedScreenIds).bind(); + workspaceItems, appWidgets, extraItems, orderedScreenIds) + .bind(isBindSync, workspaceItemCount); } } @@ -246,7 +248,7 @@ public abstract class BaseLauncherBinder { mOrderedScreenIds = orderedScreenIds; } - private void bind() { + private void bind(boolean isBindSync, int workspaceItemCount) { final IntSet currentScreenIds = mCallbacks.getPagesToBindSynchronously(mOrderedScreenIds); Objects.requireNonNull(currentScreenIds, "Null screen ids provided by " + mCallbacks); @@ -297,7 +299,8 @@ public abstract class BaseLauncherBinder { executeCallbacksTask( c -> { MODEL_EXECUTOR.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND); - c.onInitialBindComplete(currentScreenIds, pendingTasks); + c.onInitialBindComplete( + currentScreenIds, pendingTasks, workspaceItemCount, isBindSync); }, mUiExecutor); mCallbacks.bindStringCache(mBgDataModel.stringCache.clone()); @@ -361,18 +364,19 @@ public abstract class BaseLauncherBinder { * loaded, it will bind all workspace items immediately, and bindOtherWorkspacePages() will * not bind any items. */ - protected void bindCurrentWorkspacePages() { + protected void bindCurrentWorkspacePages(boolean isBindSync) { // Save a copy of all the bg-thread collections ArrayList workspaceItems; ArrayList appWidgets; ArrayList fciList = new ArrayList<>(); - + final int workspaceItemCount; synchronized (mBgDataModel) { workspaceItems = new ArrayList<>(mBgDataModel.workspaceItems); appWidgets = new ArrayList<>(mBgDataModel.appWidgets); if (!FeatureFlags.CHANGE_MODEL_DELEGATE_LOADING_ORDER.get()) { mBgDataModel.extraItems.forEach(fciList::add); } + workspaceItemCount = mBgDataModel.itemsIdMap.size(); } workspaceItems.forEach(it -> mBoundItemIds.add(it.id)); @@ -395,10 +399,10 @@ public abstract class BaseLauncherBinder { bindWorkspaceItems(workspaceItems); bindAppWidgets(appWidgets); - executeCallbacksTask(c -> { MODEL_EXECUTOR.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND); - c.onInitialBindComplete(mCurrentScreenIds, new RunnableList()); + c.onInitialBindComplete( + mCurrentScreenIds, new RunnableList(), workspaceItemCount, isBindSync); }, mUiExecutor); } diff --git a/src/com/android/launcher3/model/BgDataModel.java b/src/com/android/launcher3/model/BgDataModel.java index 0e3b06c20f..0861e9d51a 100644 --- a/src/com/android/launcher3/model/BgDataModel.java +++ b/src/com/android/launcher3/model/BgDataModel.java @@ -484,7 +484,9 @@ public class BgDataModel { default void bindWorkspaceComponentsRemoved(Predicate matcher) { } default void bindAllWidgets(List widgets) { } - default void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks) { + /** Called when workspace has been bound. */ + default void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks, + int workspaceItemCount, boolean isBindSync) { pendingTasks.executeAllAndDestroy(); } diff --git a/src/com/android/launcher3/model/LoaderTask.java b/src/com/android/launcher3/model/LoaderTask.java index 481cc6e322..9053d19f84 100644 --- a/src/com/android/launcher3/model/LoaderTask.java +++ b/src/com/android/launcher3/model/LoaderTask.java @@ -232,7 +232,7 @@ public class LoaderTask implements Runnable { } verifyNotStopped(); - mLauncherBinder.bindWorkspace(true /* incrementBindId */); + mLauncherBinder.bindWorkspace(true /* incrementBindId */, /* isBindSync= */ false); logASplit(timingLogger, "bindWorkspace"); mModelDelegate.workspaceLoadComplete(); diff --git a/src/com/android/launcher3/util/LockedUserState.kt b/src/com/android/launcher3/util/LockedUserState.kt index f5e13d2487..1231604780 100644 --- a/src/com/android/launcher3/util/LockedUserState.kt +++ b/src/com/android/launcher3/util/LockedUserState.kt @@ -7,6 +7,7 @@ import android.os.UserManager import androidx.annotation.VisibleForTesting class LockedUserState(private val mContext: Context) : SafeCloseable { + val isUserUnlockedAtLauncherStartup: Boolean var isUserUnlocked: Boolean private set private val mUserUnlockedActions: RunnableList = RunnableList() @@ -20,10 +21,17 @@ class LockedUserState(private val mContext: Context) : SafeCloseable { } init { + // 1) when user reboots devices, launcher process starts at lock screen and both + // isUserUnlocked and isUserUnlockedAtLauncherStartup are init as false. After user unlocks + // screen, isUserUnlocked will be updated to true via Intent.ACTION_USER_UNLOCKED, + // yet isUserUnlockedAtLauncherStartup will remains as false. + // 2) when launcher process restarts after user has unlocked screen, both variable are + // init as true and will not change. isUserUnlocked = mContext .getSystemService(UserManager::class.java)!! .isUserUnlocked(Process.myUserHandle()) + isUserUnlockedAtLauncherStartup = isUserUnlocked if (isUserUnlocked) { notifyUserUnlocked() } else { diff --git a/tests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt b/tests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt new file mode 100644 index 0000000000..fffa6d7b08 --- /dev/null +++ b/tests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt @@ -0,0 +1,368 @@ +package com.android.launcher3.logging + +import androidx.core.util.isEmpty +import androidx.test.annotation.UiThreadTest +import androidx.test.ext.junit.runners.AndroidJUnit4 +import androidx.test.filters.SmallTest +import com.google.common.truth.Truth.assertThat +import org.junit.Before +import org.junit.Test +import org.junit.runner.RunWith + +/** Unit test for [StartupLatencyLogger]. */ +@SmallTest +@RunWith(AndroidJUnit4::class) +class StartupLatencyLoggerTest { + + private val underTest: StartupLatencyLogger = + StartupLatencyLogger(StatsLogManager.StatsLatencyLogger.LatencyType.COLD) + + @Before + fun setup() { + underTest.setIsInTest() + } + + @Test + @UiThreadTest + fun logTotalDurationStart() { + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + + val startTime = + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id + ) + assertThat(startTime).isEqualTo(100) + assertThat(underTest.endTimeByEvent.isEmpty()).isTrue() + } + + @Test + @UiThreadTest + fun logTotalDurationEnd() { + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + + underTest.logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + + val endTime = + underTest.endTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id + ) + assertThat(endTime).isEqualTo(100) + } + + @Test + @UiThreadTest + fun logStartOfOtherEvents_withoutLogStartOfTotalDuration_noOp() { + underTest + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE, + 100 + ) + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION, + 101 + ) + .logStart( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, + 102 + ) + + assertThat(underTest.startTimeByEvent.isEmpty()).isTrue() + } + + @Test + @UiThreadTest + fun logStartOfOtherEvents_afterLogStartOfTotalDuration_logged() { + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + + underTest + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE, + 100 + ) + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION, + 101 + ) + .logStart( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, + 102 + ) + + assertThat(underTest.startTimeByEvent.size()).isEqualTo(4) + } + + @Test + @UiThreadTest + fun logDuplicatedStartEvent_2ndEvent_notLogged() { + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 101 + ) + + assertThat(underTest.startTimeByEvent.size()).isEqualTo(1) + assertThat( + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id + ) + ) + .isEqualTo(100) + } + + @Test + @UiThreadTest + fun loadStartOfWorkspace_thenEndWithAsync_logAsyncStart() { + underTest + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + .logWorkspaceLoadStartTime(111) + + underTest.logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, + 120 + ) + + assertThat(underTest.startTimeByEvent.size()).isEqualTo(2) + assertThat( + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC + .id + ) + ) + .isEqualTo(111) + } + + @Test + @UiThreadTest + fun loadStartOfWorkspace_thenEndWithSync_logSyncStart() { + underTest + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + .logWorkspaceLoadStartTime(111) + + underTest.logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC, + 120 + ) + + assertThat(underTest.startTimeByEvent.size()).isEqualTo(2) + assertThat( + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC + .id + ) + ) + .isEqualTo(111) + } + + @Test + @UiThreadTest + fun loadStartOfWorkspaceLoadSync_thenAsync_asyncNotLogged() { + underTest + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC, + 110 + ) + + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, + 111 + ) + + assertThat(underTest.startTimeByEvent.size()).isEqualTo(2) + assertThat( + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC + .id + ) + ) + .isEqualTo(110) + assertThat( + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC + .id + ) + ) + .isEqualTo(0) + } + + @Test + @UiThreadTest + fun loadStartOfWorkspaceLoadAsync_thenSync_syncNotLogged() { + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, + 111 + ) + + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC, + 112 + ) + + assertThat(underTest.startTimeByEvent.size()).isEqualTo(2) + assertThat( + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC + .id + ) + ) + .isEqualTo(111) + assertThat( + underTest.startTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC + .id + ) + ) + .isEqualTo(0) + } + + @Test + @UiThreadTest + fun logEndOfEvent_withoutStartEvent_notLogged() { + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + + underTest.logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC, + 120 + ) + + assertThat(underTest.endTimeByEvent.size()).isEqualTo(0) + assertThat( + underTest.endTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC + .id + ) + ) + .isEqualTo(0) + } + + @Test + @UiThreadTest + fun logEndOfEvent_afterEndOfTotalDuration_notLogged() { + underTest + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + .logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 120 + ) + + underTest.logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC, + 121 + ) + + assertThat(underTest.endTimeByEvent.size()).isEqualTo(1) + assertThat( + underTest.endTimeByEvent.get( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC + .id + ) + ) + .isEqualTo(0) + } + + @Test + @UiThreadTest + fun logCardinality_setCardinality() { + underTest.logCardinality(-1) + underTest.logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + + underTest.logCardinality(235) + + assertThat(underTest.cardinality).isEqualTo(235) + } + + @Test + @UiThreadTest + fun reset_clearState() { + underTest + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 100 + ) + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE, + 100 + ) + .logStart( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION, + 110 + ) + .logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION, + 115 + ) + .logWorkspaceLoadStartTime(120) + .logCardinality(235) + .logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE, + 100 + ) + .logEnd( + StatsLogManager.LauncherLatencyEvent + .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, + 140 + ) + .logEnd( + StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, + 160 + ) + assertThat(underTest.startTimeByEvent.size()).isEqualTo(4) + assertThat(underTest.endTimeByEvent.size()).isEqualTo(4) + assertThat(underTest.cardinality).isEqualTo(235) + + underTest.reset() + + assertThat(underTest.startTimeByEvent.isEmpty()).isTrue() + assertThat(underTest.endTimeByEvent.isEmpty()).isTrue() + assertThat(underTest.cardinality).isEqualTo(StartupLatencyLogger.UNSET_INT) + assertThat(underTest.workspaceLoadStartTime).isEqualTo(StartupLatencyLogger.UNSET_LONG) + } +} diff --git a/tests/src/com/android/launcher3/model/ModelMultiCallbacksTest.java b/tests/src/com/android/launcher3/model/ModelMultiCallbacksTest.java index 42c9f11a52..b9da16ac41 100644 --- a/tests/src/com/android/launcher3/model/ModelMultiCallbacksTest.java +++ b/tests/src/com/android/launcher3/model/ModelMultiCallbacksTest.java @@ -180,7 +180,8 @@ public class ModelMultiCallbacksTest { } @Override - public void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks) { + public void onInitialBindComplete(IntSet boundPages, RunnableList pendingTasks, + int workspaceItemCount, boolean isBindSync) { mPageBoundSync = boundPages; mPendingTasks = pendingTasks; }