diff --git a/src/com/android/launcher3/Launcher.java b/src/com/android/launcher3/Launcher.java index 3e6287e8a1..927c93b1fb 100644 --- a/src/com/android/launcher3/Launcher.java +++ b/src/com/android/launcher3/Launcher.java @@ -49,16 +49,13 @@ import static com.android.launcher3.LauncherConstants.SavedInstanceKeys.RUNTIME_ import static com.android.launcher3.LauncherConstants.SavedInstanceKeys.RUNTIME_STATE_PENDING_REQUEST_CODE; import static com.android.launcher3.LauncherConstants.SavedInstanceKeys.RUNTIME_STATE_RECREATE_TO_UPDATE_THEME; import static com.android.launcher3.LauncherConstants.SavedInstanceKeys.RUNTIME_STATE_WIDGET_PANEL; -import static com.android.launcher3.LauncherConstants.TraceEvents.COLD_STARTUP_TRACE_COOKIE; -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_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; import static com.android.launcher3.LauncherConstants.TraceEvents.ON_START_EVT; +import static com.android.launcher3.LauncherConstants.TraceEvents.SINGLE_TRACE_COOKIE; import static com.android.launcher3.LauncherPrefs.FIXED_LANDSCAPE_MODE; import static com.android.launcher3.LauncherSettings.Favorites.CONTAINER_DESKTOP; import static com.android.launcher3.LauncherSettings.Favorites.ITEM_TYPE_APPLICATION; @@ -90,11 +87,7 @@ import static com.android.launcher3.logging.StatsLogManager.LauncherEvent.LAUNCH 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.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; @@ -103,7 +96,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.testing.shared.TestProtocol.LAUNCHER_ACTIVITY_STOPPED_MESSAGE; -import static com.android.launcher3.util.Executors.MAIN_EXECUTOR; import static com.android.launcher3.util.ItemInfoMatcher.forFolderMatch; import static com.android.launcher3.util.SettingsCache.TOUCHPAD_NATURAL_SCROLLING; import static com.android.launcher3.util.WallpaperThemeManager.setWallpaperDependentTheme; @@ -194,13 +186,11 @@ 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; import com.android.launcher3.logging.StartupLatencyLogger; import com.android.launcher3.logging.StatsLogManager; -import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent; import com.android.launcher3.model.BgDataModel.Callbacks; import com.android.launcher3.model.ItemInstallQueue; import com.android.launcher3.model.ModelWriter; @@ -236,7 +226,6 @@ import com.android.launcher3.util.IntSet; import com.android.launcher3.util.ItemInflater; import com.android.launcher3.util.KeyboardShortcutsDelegate; import com.android.launcher3.util.LauncherBindableItemsContainer; -import com.android.launcher3.util.LockedUserState; import com.android.launcher3.util.PackageUserKey; import com.android.launcher3.util.PendingRequestArgs; import com.android.launcher3.util.PluginManagerWrapper; @@ -410,20 +399,20 @@ public class Launcher extends StatefulActivity // session on the server side. protected InstanceId mAllAppsSessionLogId; private LauncherState mPrevLauncherState; - private StartupLatencyLogger mStartupLatencyLogger; private CellPosMapper mCellPosMapper = CellPosMapper.DEFAULT; private final CannedAnimationCoordinator mAnimationCoordinator = new CannedAnimationCoordinator(this); private final List mBackPressedHandlers = new ArrayList<>(); - private boolean mIsColdStartupAfterReboot; private boolean mIsNaturalScrollingEnabled; private final SettingsCache.OnChangeListener mNaturalScrollingChangedListener = enabled -> mIsNaturalScrollingEnabled = enabled; + private StartupLatencyLogger mStartupLatencyLogger; + public static Launcher getLauncher(Context context) { return fromContext(context); } @@ -431,34 +420,12 @@ public class Launcher extends StatefulActivity @Override @TargetApi(Build.VERSION_CODES.S) protected void onCreate(Bundle savedInstanceState) { - mStartupLatencyLogger = createStartupLatencyLogger( - sIsNewProcess - ? LockedUserState.get(this).isUserUnlockedAtLauncherStartup() - ? COLD - : COLD_DEVICE_REBOOTING - : WARM); - - mIsColdStartupAfterReboot = sIsNewProcess - && !LockedUserState.get(this).isUserUnlockedAtLauncherStartup(); - if (mIsColdStartupAfterReboot) { - /* - * This trace is used to calculate the time from create to the point that icons are - * visible. - */ - Trace.beginAsyncSection( - COLD_STARTUP_TRACE_METHOD_NAME, COLD_STARTUP_TRACE_COOKIE); - } - - 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. - Trace.beginAsyncSection( - DISPLAY_WORKSPACE_TRACE_METHOD_NAME, DISPLAY_WORKSPACE_TRACE_COOKIE); - Trace.beginAsyncSection(DISPLAY_ALL_APPS_TRACE_METHOD_NAME, - DISPLAY_ALL_APPS_TRACE_COOKIE); TraceHelper.INSTANCE.beginSection(ON_CREATE_EVT); + Trace.beginAsyncSection(DISPLAY_WORKSPACE_TRACE_METHOD_NAME, SINGLE_TRACE_COOKIE); + Trace.beginAsyncSection(DISPLAY_ALL_APPS_TRACE_METHOD_NAME, SINGLE_TRACE_COOKIE); + mStartupLatencyLogger = StartupLatencyLogger.getLogger(this); + mStartupLatencyLogger.logStart(LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE); + if (DEBUG_STRICT_MODE || (FeatureFlags.IS_STUDIO_BUILD && enableStrictMode())) { StrictMode.setThreadPolicy(new StrictMode.ThreadPolicy.Builder() @@ -602,13 +569,13 @@ 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); if (BuildCompat.isAtLeastV() && com.android.launcher3.Flags.enableTwoPaneLauncherSettings()) { RuleController.getInstance(this).setRules( RuleController.parseRules(this, R.xml.split_configuration)); } + mStartupLatencyLogger.logEnd(LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE); TestEventEmitter.sendEvent(TestEvent.LAUNCHER_ON_CREATE); } @@ -616,27 +583,6 @@ public class Launcher extends StatefulActivity return new ModelCallbacks(this); } - /** - * We only log startup latency in {@link COLD_DEVICE_REBOOTING} type. For other latency types, - * create a no op implementation. - */ - private StartupLatencyLogger createStartupLatencyLogger( - StatsLogManager.StatsLatencyLogger.LatencyType 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(); - } - @NonNull View getAccessibilityActionView() { return findViewById(R.id.accessibility_action_view); } @@ -2338,20 +2284,10 @@ public class Launcher extends StatefulActivity getRootView().getViewTreeObserver().removeOnPreDrawListener(mOnInitialBindListener); mOnInitialBindListener = null; } - if (!isBindSync) { - mStartupLatencyLogger - .logCardinality(workspaceItemCount) - .logEnd(LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC); - } - MAIN_EXECUTOR.getHandler().postAtFrontOfQueue(() -> - mStartupLatencyLogger - .logEnd(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION) - .log() - .reset()); - if (mIsColdStartupAfterReboot) { - Trace.endAsyncSection(COLD_STARTUP_TRACE_METHOD_NAME, - COLD_STARTUP_TRACE_COOKIE); - } + + mStartupLatencyLogger = mStartupLatencyLogger.finishLogs(workspaceItemCount, isBindSync); + + } /** @@ -2449,8 +2385,7 @@ public class Launcher extends StatefulActivity public void bindAllApplications(AppInfo[] apps, int flags, Map packageUserKeytoUidMap) { mModelCallbacks.bindAllApplications(apps, flags, packageUserKeytoUidMap); - Trace.endAsyncSection(DISPLAY_ALL_APPS_TRACE_METHOD_NAME, - DISPLAY_ALL_APPS_TRACE_COOKIE); + Trace.endAsyncSection(DISPLAY_ALL_APPS_TRACE_METHOD_NAME, SINGLE_TRACE_COOKIE); } /** diff --git a/src/com/android/launcher3/LauncherConstants.java b/src/com/android/launcher3/LauncherConstants.java index 5cba82fc3d..198097669f 100644 --- a/src/com/android/launcher3/LauncherConstants.java +++ b/src/com/android/launcher3/LauncherConstants.java @@ -23,15 +23,16 @@ public class LauncherConstants { public static class TraceEvents { public static final String DISPLAY_ALL_APPS_TRACE_METHOD_NAME = "DisplayAllApps"; - public static final int DISPLAY_WORKSPACE_TRACE_COOKIE = 0; - public static final int DISPLAY_ALL_APPS_TRACE_COOKIE = 1; - public static final int COLD_STARTUP_TRACE_COOKIE = 2; + + // Only use a hard-coded cookie since we only want to trace this once. + public static final int SINGLE_TRACE_COOKIE = 0; public static final String ON_CREATE_EVT = "Launcher.onCreate"; public static final String ON_START_EVT = "Launcher.onStart"; public static final String ON_RESUME_EVT = "Launcher.onResume"; public static final String ON_NEW_INTENT_EVT = "Launcher.onNewIntent"; - static final String DISPLAY_WORKSPACE_TRACE_METHOD_NAME = "DisplayWorkspaceFirstFrame"; - static final String COLD_STARTUP_TRACE_METHOD_NAME = "LauncherColdStartup"; + public static final String DISPLAY_WORKSPACE_TRACE_METHOD_NAME = + "DisplayWorkspaceFirstFrame"; + public static final String COLD_STARTUP_TRACE_METHOD_NAME = "LauncherColdStartup"; } /** diff --git a/src/com/android/launcher3/ModelCallbacks.kt b/src/com/android/launcher3/ModelCallbacks.kt index 9245891078..407e126215 100644 --- a/src/com/android/launcher3/ModelCallbacks.kt +++ b/src/com/android/launcher3/ModelCallbacks.kt @@ -8,7 +8,8 @@ import android.util.Pair import androidx.annotation.AnyThread import androidx.annotation.UiThread import androidx.annotation.VisibleForTesting -import com.android.launcher3.LauncherConstants.TraceEvents +import com.android.launcher3.LauncherConstants.TraceEvents.DISPLAY_WORKSPACE_TRACE_METHOD_NAME +import com.android.launcher3.LauncherConstants.TraceEvents.SINGLE_TRACE_COOKIE import com.android.launcher3.LauncherSettings.Favorites.CONTAINER_DESKTOP import com.android.launcher3.LauncherSettings.Favorites.CONTAINER_HOTSEAT import com.android.launcher3.WorkspaceLayoutManager.FIRST_SCREEN_ID @@ -96,10 +97,7 @@ class ModelCallbacks(private var launcher: Launcher) : BgDataModel.Callbacks { workspaceItemCount: Int, isBindSync: Boolean, ) { - Trace.endAsyncSection( - TraceEvents.DISPLAY_WORKSPACE_TRACE_METHOD_NAME, - TraceEvents.DISPLAY_WORKSPACE_TRACE_COOKIE, - ) + Trace.endAsyncSection(DISPLAY_WORKSPACE_TRACE_METHOD_NAME, SINGLE_TRACE_COOKIE) synchronouslyBoundPages = boundPages pagesToBindSynchronously = LIntSet() clearPendingBinds() diff --git a/src/com/android/launcher3/logging/ColdRebootStartupLatencyLogger.kt b/src/com/android/launcher3/logging/ColdRebootStartupLatencyLogger.kt deleted file mode 100644 index bfc1d3a378..0000000000 --- a/src/com/android/launcher3/logging/ColdRebootStartupLatencyLogger.kt +++ /dev/null @@ -1,192 +0,0 @@ -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 - } -} diff --git a/src/com/android/launcher3/logging/StartupLatencyLogger.kt b/src/com/android/launcher3/logging/StartupLatencyLogger.kt index 493cd29b8f..4b4db8e022 100644 --- a/src/com/android/launcher3/logging/StartupLatencyLogger.kt +++ b/src/com/android/launcher3/logging/StartupLatencyLogger.kt @@ -1,5 +1,5 @@ /* - * Copyright (C) 2023 The Android Open Source Project + * Copyright (C) 2025 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. @@ -16,42 +16,112 @@ package com.android.launcher3.logging -import androidx.annotation.MainThread +import android.os.SystemClock +import android.os.Trace +import android.util.SparseLongArray +import androidx.annotation.VisibleForTesting +import com.android.launcher3.LauncherConstants.TraceEvents.COLD_STARTUP_TRACE_METHOD_NAME +import com.android.launcher3.LauncherConstants.TraceEvents.SINGLE_TRACE_COOKIE +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC +import com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LAUNCHER_LATENCY_PACKAGE_ID +import com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LatencyType +import com.android.launcher3.util.Executors +import com.android.launcher3.util.LockedUserState +import com.android.launcher3.views.ActivityContext /** Interface to log launcher startup latency metrics. */ -interface StartupLatencyLogger { +sealed interface StartupLatencyLogger { - @MainThread fun log(): StartupLatencyLogger = this + fun logWorkspaceLoadStartTime() {} - @MainThread fun logWorkspaceLoadStartTime(): StartupLatencyLogger = this + /** Notes the end of an event. Final logs are pushed on [finishLogs] */ + fun logStart(event: LauncherLatencyEvent) {} + + /** Notes the start of an event. Final logs are pushed on [finishLogs] */ + fun logEnd(event: LauncherLatencyEvent) {} /** - * Log size of workspace. Larger number of workspace items (icons, folders, widgets) means - * longer latency to initialize workspace. + * Finishes the current logging session and returns a new logger to be used for the next session */ - @MainThread fun logCardinality(cardinality: Int): StartupLatencyLogger = this + fun finishLogs(workspaceCount: Int, isBindSync: Boolean): StartupLatencyLogger = this - @MainThread - fun logStart(event: StatsLogManager.LauncherLatencyEvent): StartupLatencyLogger = this + object NoOpLogger : StartupLatencyLogger - @MainThread - fun logStart( - event: StatsLogManager.LauncherLatencyEvent, - startTimeMs: Long - ): StartupLatencyLogger = this + @VisibleForTesting + class ColdRebootStartupLogger( + private val ctx: ActivityContext, + private val timeProvider: () -> Long, + ) : StartupLatencyLogger { - @MainThread fun logEnd(event: StatsLogManager.LauncherLatencyEvent): StartupLatencyLogger = this + @VisibleForTesting val startTimeByEvent = SparseLongArray() + @VisibleForTesting val endTimeByEvent = SparseLongArray() - @MainThread - fun logEnd(event: StatsLogManager.LauncherLatencyEvent, endTimeMs: Long): StartupLatencyLogger = - this + private var cardinality: Int = -1 - @MainThread fun reset() + init { + Trace.beginAsyncSection(COLD_STARTUP_TRACE_METHOD_NAME, SINGLE_TRACE_COOKIE) + logStart(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION) + } + + override fun logWorkspaceLoadStartTime() = + logStart(LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC) + + override fun logStart(event: LauncherLatencyEvent) = + startTimeByEvent.put(event.id, timeProvider.invoke()) + + override fun logEnd(event: LauncherLatencyEvent) = + endTimeByEvent.put(event.id, timeProvider.invoke()) + + override fun finishLogs(workspaceCount: Int, isBindSync: Boolean): StartupLatencyLogger { + if (!isBindSync) { + cardinality = workspaceCount + logEnd(LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC) + } + + Executors.MAIN_EXECUTOR.handler.postAtFrontOfQueue { + logEnd(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION) + commitLogs() + } + Trace.endAsyncSection(COLD_STARTUP_TRACE_METHOD_NAME, SINGLE_TRACE_COOKIE) + return NoOpLogger + } + + private fun commitLogs() { + val instanceId = InstanceIdSequence().newInstanceId() + val logger = ctx.statsLogManager + for (event in LauncherLatencyEvent.entries) { + val start = startTimeByEvent.get(event.id) + val end = endTimeByEvent.get(event.id) + val duration = end - start + if (start != 0L && end != 0L) { + logger + .latencyLogger() + .withType(LatencyType.COLD_DEVICE_REBOOTING) + .withInstanceId(instanceId) + .withLatency(duration) + .withPackageId(LAUNCHER_LATENCY_PACKAGE_ID) + .withCardinality(cardinality) + .log(event) + } + } + } + } companion object { - val NO_OP: StartupLatencyLogger = - object : StartupLatencyLogger { - override fun reset() {} - } + + private var isNewProcess: Boolean = true + + @JvmStatic + fun getLogger(ctx: ActivityContext): StartupLatencyLogger { + val isColdStartupAfterReboot = + isNewProcess && + !LockedUserState.get(ctx.asContext()).isUserUnlockedAtLauncherStartup + isNewProcess = false + return if (isColdStartupAfterReboot) + ColdRebootStartupLogger(ctx) { SystemClock.elapsedRealtime() } + else NoOpLogger + } } } diff --git a/src/com/android/launcher3/logging/StatsLogManager.java b/src/com/android/launcher3/logging/StatsLogManager.java index f7678559b5..8ea5fb9b62 100644 --- a/src/com/android/launcher3/logging/StatsLogManager.java +++ b/src/com/android/launcher3/logging/StatsLogManager.java @@ -1143,6 +1143,9 @@ public class StatsLogManager { */ public interface StatsLatencyLogger { + /** Package Id for Launcher */ + int LAUNCHER_LATENCY_PACKAGE_ID = 3; + /** * Should be in sync with: * google3/wireless/android/sysui/aster/asterstats/launcher_event_processed.proto diff --git a/tests/multivalentTests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt b/tests/multivalentTests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt index 713d4d5df7..3630e8f506 100644 --- a/tests/multivalentTests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt +++ b/tests/multivalentTests/src/com/android/launcher3/logging/StartupLatencyLoggerTest.kt @@ -1,291 +1,180 @@ +/* + * Copyright (C) 2025 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 androidx.core.util.isEmpty -import androidx.test.annotation.UiThreadTest import androidx.test.filters.SmallTest +import com.android.launcher3.logging.StartupLatencyLogger.ColdRebootStartupLogger +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION +import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC +import com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger +import com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LAUNCHER_LATENCY_PACKAGE_ID +import com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LatencyType +import com.android.launcher3.util.Executors.MAIN_EXECUTOR import com.android.launcher3.util.LauncherMultivalentJUnit +import com.android.launcher3.util.TestUtil +import com.android.launcher3.views.ActivityContext import com.google.common.truth.Truth.assertThat import org.junit.Before import org.junit.Test import org.junit.runner.RunWith +import org.mockito.Answers.RETURNS_SELF +import org.mockito.Mock +import org.mockito.MockitoAnnotations +import org.mockito.kotlin.any +import org.mockito.kotlin.doAnswer +import org.mockito.kotlin.doReturn +import org.mockito.kotlin.mock +import org.mockito.kotlin.verify +import org.mockito.kotlin.whenever -/** Unit test for [ColdRebootStartupLatencyLogger]. */ +/** Unit test for [ColdRebootStartupLogger]. */ @SmallTest @RunWith(LauncherMultivalentJUnit::class) class StartupLatencyLoggerTest { - private val underTest = ColdRebootStartupLatencyLogger() + @Mock lateinit var ctx: ActivityContext + @Mock lateinit var timeProvider: () -> Long + @Mock lateinit var statsLogManager: StatsLogManager + + private val trackedLoggers = mutableMapOf() + + private val underTest by lazy { ColdRebootStartupLogger(ctx, timeProvider) } @Before fun setup() { - underTest.setIsInTest() + MockitoAnnotations.initMocks(this) + doReturn(statsLogManager).whenever(ctx).statsLogManager + doAnswer { + mock(defaultAnswer = RETURNS_SELF).apply { + doAnswer { invocation -> trackedLoggers[invocation.getArgument(0)] = this } + .whenever(this) + .log(any()) + } + } + .whenever(statsLogManager) + .latencyLogger() } @Test - @UiThreadTest fun logTotalDurationStart() { - underTest.logStart( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, - 100 - ) + doReturn(100).whenever(timeProvider).invoke() - val startTime = - underTest.startTimeByEvent.get( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id - ) + val startTime = underTest.startTimeByEvent.get(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 - ) + whenever(timeProvider.invoke()).thenReturn(100).thenReturn(101) - underTest.logEnd( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, - 100 - ) + underTest.logEnd(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION) - val endTime = - underTest.endTimeByEvent.get( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id - ) - assertThat(endTime).isEqualTo(100) + val endTime = underTest.endTimeByEvent.get(LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id) + assertThat(endTime).isEqualTo(101) } @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 - ) + whenever(timeProvider.invoke()) + .thenReturn(100) + .thenReturn(101) + .thenReturn(102) + .thenReturn(103) - 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 - ) + underTest.apply { + logStart(LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE) + logStart(LAUNCHER_LATENCY_STARTUP_VIEW_INFLATION) + logStart(LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC) + } assertThat(underTest.startTimeByEvent.size()).isEqualTo(4) } @Test - @UiThreadTest - fun logDuplicatedStartEvent_2ndEvent_notLogged() { - underTest.logStart( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, - 100 - ) + fun finishLogs_commits_logs() { + whenever(timeProvider.invoke()).thenReturn(100).thenReturn(102) + underTest.finishLogs(10, true) + TestUtil.runOnExecutorSync(MAIN_EXECUTOR) {} - 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) + assertThat(trackedLoggers).hasSize(1) + LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.verifyLoggedEvent(2) } @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) + fun finishLogs_returns_noop_for_followup() { + whenever(timeProvider.invoke()).thenReturn(100) + val followup = underTest.finishLogs(10, true) + TestUtil.runOnExecutorSync(MAIN_EXECUTOR) {} + assertThat(followup).isEqualTo(StartupLatencyLogger.NoOpLogger) } @Test - @UiThreadTest - fun logEndOfEvent_withoutStartEvent_notLogged() { - underTest.logStart( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, - 100 - ) + fun finishLogs_commits_all_sent_events() { + whenever(timeProvider.invoke()) + .thenReturn(100) + .thenReturn(200) + .thenReturn(210) + .thenReturn(230) + underTest.logStart(LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE) + underTest.logEnd(LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE) - underTest.logEnd( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, - 120 - ) + underTest.finishLogs(10, true) + TestUtil.runOnExecutorSync(MAIN_EXECUTOR) {} - assertThat(underTest.endTimeByEvent.size()).isEqualTo(0) - assertThat( - underTest.endTimeByEvent.get( - StatsLogManager.LauncherLatencyEvent - .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC - .id - ) - ) - .isEqualTo(0) + assertThat(trackedLoggers).hasSize(2) + LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.verifyLoggedEvent(130) + LAUNCHER_LATENCY_STARTUP_ACTIVITY_ON_CREATE.verifyLoggedEvent(10) } @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 - ) + fun finishLogs_logs_workspace_async_load_on_async_bind() { + whenever(timeProvider.invoke()).thenReturn(100).thenReturn(200).thenReturn(250) + underTest.logWorkspaceLoadStartTime() - underTest.logEnd( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC, - 121 - ) + underTest.finishLogs(30, false) + TestUtil.runOnExecutorSync(MAIN_EXECUTOR) {} - assertThat(underTest.endTimeByEvent.size()).isEqualTo(1) - assertThat( - underTest.endTimeByEvent.get( - StatsLogManager.LauncherLatencyEvent - .LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC - .id - ) - ) - .isEqualTo(0) + assertThat(trackedLoggers).hasSize(2) + LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.verifyLoggedEvent(150, 30) + LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.verifyLoggedEvent(50, 30) } @Test - @UiThreadTest - fun logCardinality_setCardinality() { - underTest.logCardinality(-1) - underTest.logStart( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, - 100 - ) + fun finishLogs_does_not_log_workspace_async_load_on_sync_bind() { + whenever(timeProvider.invoke()).thenReturn(100).thenReturn(200).thenReturn(250) + underTest.logWorkspaceLoadStartTime() - underTest.logCardinality(235) + underTest.finishLogs(30, true) + TestUtil.runOnExecutorSync(MAIN_EXECUTOR) {} - assertThat(underTest.cardinality).isEqualTo(235) + assertThat(trackedLoggers).hasSize(1) + LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.verifyLoggedEvent(150) } - @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) - assertThat(underTest.isTornDown).isFalse() - - underTest.reset() - - assertThat(underTest.startTimeByEvent.isEmpty()).isTrue() - assertThat(underTest.endTimeByEvent.isEmpty()).isTrue() - assertThat(underTest.cardinality).isEqualTo(ColdRebootStartupLatencyLogger.UNSET_INT) - assertThat(underTest.workspaceLoadStartTime) - .isEqualTo(ColdRebootStartupLatencyLogger.UNSET_LONG) - assertThat(underTest.isTornDown).isTrue() - } - - @Test - @UiThreadTest - fun tornDown_rejectLogs() { - underTest.reset() - - underTest - .logStart( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, - 100 - ) - .logEnd( - StatsLogManager.LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION, - 200 - ) - .logCardinality(123) - assertThat(underTest.startTimeByEvent.isEmpty()).isTrue() - assertThat(underTest.endTimeByEvent.isEmpty()).isTrue() - assertThat(underTest.cardinality).isEqualTo(ColdRebootStartupLatencyLogger.UNSET_INT) + private fun LauncherLatencyEvent.verifyLoggedEvent(latency: Long, cardinality: Int = -1) { + val logger = trackedLoggers[this]!! + verify(logger).withLatency(latency) + verify(logger).withPackageId(LAUNCHER_LATENCY_PACKAGE_ID) + verify(logger).withType(LatencyType.COLD_DEVICE_REBOOTING) + verify(logger).withCardinality(cardinality) } }