Merge "[1/n] Launcher Startup Latency: add StartupLatencyLogger to launcher3... (c15679d5) · Commits · e / os / android_packages_apps_Trebuchet

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) {