Merge changes from topic "reportFullyDrawn" (6bc75fcb) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/am/ActivityManagerService.java

+6 −2

Original line number	Diff line number	Diff line
		@@ -900,7 +900,7 @@ public class ActivityManagerService extends IActivityManager.Stub

		// The other observer methods are unused
		@Override
		public void onIntentStarted(Intent intent) {
		public void onIntentStarted(Intent intent, long timestampNs) {
		}

		@Override
		@@ -912,7 +912,11 @@ public class ActivityManagerService extends IActivityManager.Stub
		}

		@Override
		public void onActivityLaunchFinished(byte[] finalActivity) {
		public void onActivityLaunchFinished(byte[] finalActivity, long timestampNs) {
		}

		@Override
		public void onReportFullyDrawn(byte[] finalActivity, long timestampNs) {
		}
		};

services/core/java/com/android/server/wm/ActivityMetricsLaunchObserver.java

+38 −13

Original line number	Diff line number	Diff line
		@@ -39,8 +39,13 @@ import java.lang.annotation.RetentionPolicy;
		* If an activity is successfully started, the launch sequence's state will transition into
		* {@code STARTED} via {@link #onActivityLaunched}. This is a transient state.
		*
		* It must then transition to either {@code CANCELLED} with {@link #onActivityLaunchCancelled}
		* or into {@code FINISHED} with {@link #onActivityLaunchFinished}. These are terminal states.
		* It must then transition to either {@code CANCELLED} with {@link #onActivityLaunchCancelled},
		* which is a terminal state or into {@code FINISHED} with {@link #onActivityLaunchFinished}.
		*
		* The {@code FINISHED} with {@link #onActivityLaunchFinished} then may transition to
		* {@code FULLY_DRAWN} with {@link #onReportFullyDrawn}, which is a terminal state.
		* Note this transition may not happen if the reportFullyDrawn event is not receivied,
		* in which case {@code FINISHED} is terminal.
		*
		* Note that the {@code ActivityRecordProto} provided as a parameter to some state transitions isn't
		* necessarily the same within a single launch sequence: it is only the top-most activity at the
		@@ -51,15 +56,15 @@ import java.lang.annotation.RetentionPolicy;
		* until a subsequent transition into {@code INTENT_STARTED} initiates a new launch sequence.
		*
		* <pre>
		* ┌⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┐ ┌⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┐ ╔══════════════════════════╗
		* ╴╴▶ ⋮ INTENT_STARTED ⋮ ──▶ ⋮ ACTIVITY_LAUNCHED ⋮ ──▶ ║ ACTIVITY_LAUNCH_FINISHED ║
		* └⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┘ └⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┘ ╚══════════════════════════╝
		* : :
		* : :
		* ▼ ▼
		* ╔════════════════╗ ╔═══════════════════════════╗
		* ║ INTENT_FAILED ║ ║ ACTIVITY_LAUNCH_CANCELLED ║
		* ╚════════════════╝ ╚═══════════════════════════╝
		* ┌⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┐ ┌⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┐ ┌--------------------------┐
		* ╴╴▶ INTENT_STARTED ──▶ ACTIVITY_LAUNCHED ──▶ ACTIVITY_LAUNCH_FINISHED
		* └⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┘ └⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯⋯┘ └--------------------------┘
		* : : :
		* : : :
		* ▼ ▼ ▼
		* ╔════════════════╗ ╔═══════════════════════════╗ ╔═══════════════════════════╗
		* ║ INTENT_FAILED ║ ║ ACTIVITY_LAUNCH_CANCELLED ║ ║ REPORT_FULLY_DRAWN ║
		* ╚════════════════╝ ╚═══════════════════════════╝ ╚═══════════════════════════╝
		* </pre>
		*/
		public interface ActivityMetricsLaunchObserver {
		@@ -111,7 +116,7 @@ public interface ActivityMetricsLaunchObserver {
		* Multiple calls to this method cannot occur without first terminating the current
		* launch sequence.
		*/
		public void onIntentStarted(@NonNull Intent intent);
		public void onIntentStarted(@NonNull Intent intent, long timestampNanos);

		/**
		* Notifies the observer that the current launch sequence has failed to launch an activity.
		@@ -177,6 +182,9 @@ public interface ActivityMetricsLaunchObserver {
		* drawn for the first time: the top-most activity at the time is what's reported here.
		*
		* @param finalActivity the top-most activity whose windows were first to fully draw
		* @param timestampNanos the timestamp of ActivityLaunchFinished event in nanoseconds.
		* To compute the TotalTime duration, deduct the timestamp {@link #onIntentStarted}
		* from {@code timestampNanos}.
		*
		* Multiple calls to this method cannot occur without first terminating the current
		* launch sequence.
		@@ -186,5 +194,22 @@ public interface ActivityMetricsLaunchObserver {
		* and only the latest activity that was top-most during first-frame drawn
		* is reported here.
		*/
		public void onActivityLaunchFinished(@NonNull @ActivityRecordProto byte[] finalActivity);
		public void onActivityLaunchFinished(@NonNull @ActivityRecordProto byte[] finalActivity,
		long timestampNanos);

		/**
		* Notifies the observer that the application self-reported itself as being fully drawn.
		*
		* @param activity the activity that triggers the ReportFullyDrawn event.
		* @param timestampNanos the timestamp of ReportFullyDrawn event in nanoseconds.
		* To compute the duration, deduct the deduct the timestamp {@link #onIntentStarted}
		* from {@code timestampNanos}.
		*
		* @apiNote The behavior of ReportFullyDrawn mostly depends on the app.
		* It is used as an accurate estimate of meanfully app startup time.
		* This event may be missing for many apps.
		*/
		public void onReportFullyDrawn(@NonNull @ActivityRecordProto byte[] activity,
		long timestampNanos);

		}

services/core/java/com/android/server/wm/ActivityMetricsLogger.java

+61 −31

Original line number	Diff line number	Diff line
		@@ -92,6 +92,7 @@ import com.android.internal.logging.MetricsLogger;
		import com.android.internal.os.BackgroundThread;
		import com.android.internal.os.SomeArgs;
		import com.android.server.LocalServices;
		import java.util.concurrent.TimeUnit;

		/**
		* Listens to activity launches, transitions, visibility changes and window drawn callbacks to
		@@ -132,8 +133,8 @@ class ActivityMetricsLogger {

		// set to INVALID_START_TIME in reset.
		// set to valid value in notifyActivityLaunching
		private long mCurrentTransitionStartTime = INVALID_START_TIME;
		private long mLastTransitionStartTime = INVALID_START_TIME;
		private long mCurrentTransitionStartTimeNs = INVALID_START_TIME;
		private long mLastTransitionStartTimeNs = INVALID_START_TIME;

		private int mCurrentTransitionDeviceUptime;
		private int mCurrentTransitionDelayMs;
		@@ -326,12 +327,12 @@ class ActivityMetricsLogger {
		intent));
		}

		if (mCurrentTransitionStartTime == INVALID_START_TIME) {
		if (mCurrentTransitionStartTimeNs == INVALID_START_TIME) {

		mCurrentTransitionStartTime = SystemClock.uptimeMillis();
		mLastTransitionStartTime = mCurrentTransitionStartTime;
		mCurrentTransitionStartTimeNs = SystemClock.elapsedRealtimeNanos();
		mLastTransitionStartTimeNs = mCurrentTransitionStartTimeNs;

		launchObserverNotifyIntentStarted(intent);
		launchObserverNotifyIntentStarted(intent, mCurrentTransitionStartTimeNs);
		}
		}

		@@ -382,14 +383,15 @@ class ActivityMetricsLogger {
		? launchedActivity.getWindowingMode()
		: WINDOWING_MODE_UNDEFINED;
		final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
		if (mCurrentTransitionStartTime == INVALID_START_TIME) {
		if (mCurrentTransitionStartTimeNs == INVALID_START_TIME) {
		// No transition is active ignore this launch.
		return;
		}

		if (launchedActivity != null && launchedActivity.mDrawn) {
		// Launched activity is already visible. We cannot measure windows drawn delay.
		reset(true /* abort */, info, "launched activity already visible");
		reset(true /* abort */, info, "launched activity already visible",
		0L /* timestampNs */);
		return;
		}

		@@ -407,7 +409,8 @@ class ActivityMetricsLogger {
		if ((!isLoggableResultCode(resultCode) \|\| launchedActivity == null \|\| !processSwitch
		\|\| windowingMode == WINDOWING_MODE_UNDEFINED) && !otherWindowModesLaunching) {
		// Failed to launch or it was not a process switch, so we don't care about the timing.
		reset(true /* abort */, info, "failed to launch or not a process switch");
		reset(true /* abort */, info, "failed to launch or not a process switch",
		0L /* timestampNs */);
		return;
		} else if (otherWindowModesLaunching) {
		// Don't log this windowing mode but continue with the other windowing modes.
		@@ -441,19 +444,20 @@ class ActivityMetricsLogger {
		* Notifies the tracker that all windows of the app have been drawn.
		*/
		WindowingModeTransitionInfoSnapshot notifyWindowsDrawn(@WindowingMode int windowingMode,
		long timestamp) {
		long timestampNs) {
		if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn windowingMode=" + windowingMode);

		final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
		if (info == null \|\| info.loggedWindowsDrawn) {
		return null;
		}
		info.windowsDrawnDelayMs = calculateDelay(timestamp);
		info.windowsDrawnDelayMs = calculateDelay(timestampNs);
		info.loggedWindowsDrawn = true;
		final WindowingModeTransitionInfoSnapshot infoSnapshot =
		new WindowingModeTransitionInfoSnapshot(info);
		if (allWindowsDrawn() && mLoggedTransitionStarting) {
		reset(false /* abort */, info, "notifyWindowsDrawn - all windows drawn");
		reset(false /* abort */, info, "notifyWindowsDrawn - all windows drawn",
		timestampNs /* timestampNs */);
		}
		return infoSnapshot;
		}
		@@ -476,7 +480,7 @@ class ActivityMetricsLogger {
		* @param windowingModeToReason A map from windowing mode to a reason integer, which must be on
		* of ActivityTaskManagerInternal.APP_TRANSITION_* reasons.
		*/
		void notifyTransitionStarting(SparseIntArray windowingModeToReason, long timestamp) {
		void notifyTransitionStarting(SparseIntArray windowingModeToReason, long timestampNs) {
		if (!isAnyTransitionActive() \|\| mLoggedTransitionStarting) {
		// Ignore calls to this made after a reset and prior to notifyActivityLaunching.

		@@ -484,7 +488,7 @@ class ActivityMetricsLogger {
		return;
		}
		if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");
		mCurrentTransitionDelayMs = calculateDelay(timestamp);
		mCurrentTransitionDelayMs = calculateDelay(timestampNs);
		mLoggedTransitionStarting = true;

		WindowingModeTransitionInfo foundInfo = null;
		@@ -501,7 +505,8 @@ class ActivityMetricsLogger {
		if (allWindowsDrawn()) {
		// abort metrics collection if we cannot find a matching transition.
		final boolean abortMetrics = foundInfo == null;
		reset(abortMetrics, foundInfo, "notifyTransitionStarting - all windows drawn");
		reset(abortMetrics, foundInfo, "notifyTransitionStarting - all windows drawn",
		timestampNs /* timestampNs */);
		}
		}

		@@ -567,7 +572,8 @@ class ActivityMetricsLogger {
		logAppTransitionCancel(info);
		mWindowingModeTransitionInfo.remove(r.getWindowingMode());
		if (mWindowingModeTransitionInfo.size() == 0) {
		reset(true /* abort */, info, "notifyVisibilityChanged to invisible");
		reset(true /* abort */, info, "notifyVisibilityChanged to invisible",
		0L /* timestampNs */);
		}
		}
		}
		@@ -598,12 +604,16 @@ class ActivityMetricsLogger {
		}

		private boolean isAnyTransitionActive() {
		return mCurrentTransitionStartTime != INVALID_START_TIME
		return mCurrentTransitionStartTimeNs != INVALID_START_TIME
		&& mWindowingModeTransitionInfo.size() > 0;
		}

		private void reset(boolean abort, WindowingModeTransitionInfo info, String cause) {
		if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort + ",cause=" + cause);
		private void reset(boolean abort, WindowingModeTransitionInfo info, String cause,
		long timestampNs) {
		if (DEBUG_METRICS) {
		Slog.i(TAG,
		"reset abort=" + abort + ",cause=" + cause + ",timestamp=" + timestampNs);
		}
		if (!abort && isAnyTransitionActive()) {
		logAppTransitionMultiEvents();
		}
		@@ -615,13 +625,13 @@ class ActivityMetricsLogger {
		if (abort) {
		launchObserverNotifyActivityLaunchCancelled(info);
		} else {
		launchObserverNotifyActivityLaunchFinished(info);
		launchObserverNotifyActivityLaunchFinished(info, timestampNs);
		}
		} else {
		launchObserverNotifyIntentFailed();
		}

		mCurrentTransitionStartTime = INVALID_START_TIME;
		mCurrentTransitionStartTimeNs = INVALID_START_TIME;
		mCurrentTransitionDelayMs = INVALID_DELAY;
		mLoggedTransitionStarting = false;
		mWindowingModeTransitionInfo.clear();
		@@ -629,12 +639,14 @@ class ActivityMetricsLogger {

		private int calculateCurrentDelay() {
		// Shouldn't take more than 25 days to launch an app, so int is fine here.
		return (int) (SystemClock.uptimeMillis() - mCurrentTransitionStartTime);
		return (int) TimeUnit.NANOSECONDS
		.toMillis(SystemClock.elapsedRealtimeNanos() - mCurrentTransitionStartTimeNs);
		}

		private int calculateDelay(long timestamp) {
		private int calculateDelay(long timestampNs) {
		// Shouldn't take more than 25 days to launch an app, so int is fine here.
		return (int) (timestamp - mCurrentTransitionStartTime);
		return (int) TimeUnit.NANOSECONDS.toMillis(timestampNs -
		mCurrentTransitionStartTimeNs);
		}

		private void logAppTransitionCancel(WindowingModeTransitionInfo info) {
		@@ -811,7 +823,9 @@ class ActivityMetricsLogger {
		final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
		builder.setPackageName(r.packageName);
		builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
		long startupTimeMs = SystemClock.uptimeMillis() - mLastTransitionStartTime;
		long currentTimestampNs = SystemClock.elapsedRealtimeNanos();
		long startupTimeMs =
		TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - mLastTransitionStartTimeNs);
		builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
		builder.setType(restoredFromBundle
		? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
		@@ -837,6 +851,10 @@ class ActivityMetricsLogger {
		final WindowingModeTransitionInfoSnapshot infoSnapshot =
		new WindowingModeTransitionInfoSnapshot(info, r, (int) startupTimeMs);
		BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));

		// Notify reportFullyDrawn event.
		launchObserverNotifyReportFullyDrawn(r, currentTimestampNs);

		return infoSnapshot;
		}

		@@ -1006,12 +1024,12 @@ class ActivityMetricsLogger {
		}

		/** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */
		private void launchObserverNotifyIntentStarted(Intent intent) {
		private void launchObserverNotifyIntentStarted(Intent intent, long timestampNs) {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
		"MetricsLogger:launchObserverNotifyIntentStarted");

		// Beginning a launch is timing sensitive and so should be observed as soon as possible.
		mLaunchObserver.onIntentStarted(intent);
		mLaunchObserver.onIntentStarted(intent, timestampNs);

		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		}
		@@ -1048,6 +1066,16 @@ class ActivityMetricsLogger {
		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		}

		/**
		* Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event.
		*/
		private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs) {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
		"MetricsLogger:launchObserverNotifyReportFullyDrawn");
		mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNs);
		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		}

		/**
		* Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is
		* cancelled.
		@@ -1068,12 +1096,14 @@ class ActivityMetricsLogger {
		* Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
		* has fully finished (successfully).
		*/
		private void launchObserverNotifyActivityLaunchFinished(WindowingModeTransitionInfo info) {
		private void launchObserverNotifyActivityLaunchFinished(WindowingModeTransitionInfo info,
		long timestampNs) {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
		"MetricsLogger:launchObserverNotifyActivityLaunchFinished");

		mLaunchObserver.onActivityLaunchFinished(
		convertActivityRecordToProto(info.launchedActivity));
		mLaunchObserver
		.onActivityLaunchFinished(convertActivityRecordToProto(info.launchedActivity),
		timestampNs);

		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		}

services/core/java/com/android/server/wm/ActivityRecord.java

+3 −3

Original line number	Diff line number	Diff line
		@@ -3114,13 +3114,13 @@ final class ActivityRecord extends AppWindowToken {
		}

		/** Called when the windows associated app window container are drawn. */
		void onWindowsDrawn(boolean drawn, long timestamp) {
		void onWindowsDrawn(boolean drawn, long timestampNs) {
		mDrawn = drawn;
		if (!drawn) {
		return;
		}
		final WindowingModeTransitionInfoSnapshot info = mStackSupervisor
		.getActivityMetricsLogger().notifyWindowsDrawn(getWindowingMode(), timestamp);
		.getActivityMetricsLogger().notifyWindowsDrawn(getWindowingMode(), timestampNs);
		final int windowsDrawnDelayMs = info != null ? info.windowsDrawnDelayMs : INVALID_DELAY;
		final @LaunchState int launchState = info != null ? info.getLaunchState() : -1;
		mStackSupervisor.reportActivityLaunchedLocked(false /* timeout */, this,

services/core/java/com/android/server/wm/ActivityTaskManagerInternal.java

+3 −3

Original line number	Diff line number	Diff line
		@@ -159,10 +159,10 @@ public abstract class ActivityTaskManagerInternal {
		*
		* @param reasons A map from windowing mode to a reason integer why the transition was started,
		* which must be one of the APP_TRANSITION_* values.
		* @param timestamp The time at which the app transition started in
		* {@link SystemClock#uptimeMillis()} timebase.
		* @param timestampNs The time at which the app transition started in
		* {@link SystemClock#elapsedRealtimeNs()} ()} timebase.
		*/
		public abstract void notifyAppTransitionStarting(SparseIntArray reasons, long timestamp);
		public abstract void notifyAppTransitionStarting(SparseIntArray reasons, long timestampNs);

		/**
		* Callback for window manager to let activity manager know that the app transition was