Merge "Use uptime for activity startup time" (73d707bb) · Commits · e / os / android_frameworks_base

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

+40 −42

Original line number	Diff line number	Diff line
		@@ -197,10 +197,16 @@ class ActivityMetricsLogger {
		* launched successfully.
		*/
		static final class LaunchingState {
		/** The device uptime of {@link #notifyActivityLaunching}. */
		private final long mCurrentUpTimeMs = SystemClock.uptimeMillis();
		/** The timestamp of {@link #notifyActivityLaunching}. */
		private long mCurrentTransitionStartTimeNs;
		/**
		* The device uptime of {@link #notifyActivityLaunching}. It can be used as a key for
		* observer to identify which callbacks belong to a launch event.
		*/
		final long mStartUptimeNs = SystemClock.uptimeNanos();
		/**
		* The timestamp of {@link #notifyActivityLaunching}. It is used to provide the time
		* relative to the wall-time.
		*/
		final long mStartRealtimeNs = SystemClock.elapsedRealtimeNanos();
		/** Non-null when a {@link TransitionInfo} is created for this state. */
		private TransitionInfo mAssociatedTransitionInfo;
		/** The sequence id for trace. It is used to map the traces before resolving intent. */
		@@ -263,13 +269,7 @@ class ActivityMetricsLogger {
		* @see LaunchingState#mAssociatedTransitionInfo
		*/
		final LaunchingState mLaunchingState;
		/**
		* The timestamp of the first {@link #notifyActivityLaunching}. It can be used as a key for
		* observer to identify which callbacks belong to a launch event.
		*/
		final long mTransitionStartTimeNs;
		/** The device uptime in millis when this transition info is created. */
		final long mTransitionDeviceUptimeMs;

		/** The type can be cold (new process), warm (new activity), or hot (bring to front). */
		final int mTransitionType;
		/** Whether the process was already running when the transition started. */
		@@ -289,11 +289,11 @@ class ActivityMetricsLogger {
		@SourceInfo.SourceType int mSourceType;
		/** The time from the source event (e.g. touch) to {@link #notifyActivityLaunching}. */
		int mSourceEventDelayMs = INVALID_DELAY;
		/** The time from {@link #mTransitionStartTimeNs} to {@link #notifyTransitionStarting}. */
		/** The time from {@link #notifyActivityLaunching} to {@link #notifyTransitionStarting}. */
		int mCurrentTransitionDelayMs;
		/** The time from {@link #mTransitionStartTimeNs} to {@link #notifyStartingWindowDrawn}. */
		/** The time from {@link #notifyActivityLaunching} to {@link #notifyStartingWindowDrawn}. */
		int mStartingWindowDelayMs = INVALID_DELAY;
		/** The time from {@link #mTransitionStartTimeNs} to {@link #notifyBindApplication}. */
		/** The time from {@link #notifyActivityLaunching} to {@link #notifyBindApplication}. */
		int mBindApplicationDelayMs = INVALID_DELAY;
		/** Elapsed time from when we launch an activity to when its windows are drawn. */
		int mWindowsDrawnDelayMs;
		@@ -339,13 +339,11 @@ class ActivityMetricsLogger {
		ActivityOptions options, int transitionType, boolean processRunning,
		boolean processSwitch, int processState, int processOomAdj) {
		mLaunchingState = launchingState;
		mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs;
		mTransitionType = transitionType;
		mProcessRunning = processRunning;
		mProcessSwitch = processSwitch;
		mProcessState = processState;
		mProcessOomAdj = processOomAdj;
		mTransitionDeviceUptimeMs = launchingState.mCurrentUpTimeMs;
		setLatestLaunchedActivity(r);
		// The launching state can be reused by consecutive launch. Its original association
		// shouldn't be changed by a separated transition.
		@@ -356,8 +354,8 @@ class ActivityMetricsLogger {
		final SourceInfo sourceInfo = options.getSourceInfo();
		if (sourceInfo != null) {
		mSourceType = sourceInfo.type;
		mSourceEventDelayMs =
		(int) (launchingState.mCurrentUpTimeMs - sourceInfo.eventTimeMs);
		mSourceEventDelayMs = (int) (TimeUnit.NANOSECONDS.toMillis(
		launchingState.mStartUptimeNs) - sourceInfo.eventTimeMs);
		}
		}
		}
		@@ -403,12 +401,13 @@ class ActivityMetricsLogger {
		}

		int calculateCurrentDelay() {
		return calculateDelay(SystemClock.elapsedRealtimeNanos());
		return calculateDelay(SystemClock.uptimeNanos());
		}

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

		@Override
		@@ -583,7 +582,6 @@ class ActivityMetricsLogger {
		*/
		LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller,
		int callingUid) {
		final long transitionStartTimeNs = SystemClock.elapsedRealtimeNanos();
		TransitionInfo existingInfo = null;
		if (callingUid != IGNORE_CALLER) {
		// Associate the launching event to an active transition if the caller is found in its
		@@ -608,12 +606,10 @@ class ActivityMetricsLogger {

		if (existingInfo == null) {
		final LaunchingState launchingState = new LaunchingState();
		launchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs;
		// Only notify the observer for a new launching event.
		launchObserverNotifyIntentStarted(intent, transitionStartTimeNs);
		launchObserverNotifyIntentStarted(intent, launchingState.mStartUptimeNs);
		return launchingState;
		}
		existingInfo.mLaunchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs;
		return existingInfo.mLaunchingState;
		}

		@@ -716,7 +712,7 @@ class ActivityMetricsLogger {
		launchObserverNotifyActivityLaunched(newInfo);
		} else {
		// As abort for no process switch.
		launchObserverNotifyIntentFailed(newInfo.mTransitionStartTimeNs);
		launchObserverNotifyIntentFailed(newInfo.mLaunchingState.mStartUptimeNs);
		}
		scheduleCheckActivityToBeDrawnIfSleeping(launchedActivity);

		@@ -749,9 +745,10 @@ class ActivityMetricsLogger {
		* to invisible (removed from active transition) or it was already drawn.
		*/
		@Nullable
		TransitionInfoSnapshot notifyWindowsDrawn(@NonNull ActivityRecord r, long timestampNs) {
		TransitionInfoSnapshot notifyWindowsDrawn(@NonNull ActivityRecord r) {
		if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn " + r);

		final long timestampNs = SystemClock.uptimeNanos();
		final TransitionInfo info = getActiveTransitionInfo(r);
		if (info == null \|\| info.mIsDrawn) {
		if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn not pending drawn " + info);
		@@ -778,7 +775,7 @@ class ActivityMetricsLogger {
		}
		if (DEBUG_METRICS) Slog.i(TAG, "notifyStartingWindowDrawn " + r);
		info.mLoggedStartingWindowDrawn = true;
		info.mStartingWindowDelayMs = info.calculateDelay(SystemClock.elapsedRealtimeNanos());
		info.mStartingWindowDelayMs = info.calculateCurrentDelay();
		}

		/**
		@@ -790,7 +787,7 @@ class ActivityMetricsLogger {
		void notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason) {
		if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting " + activityToReason);

		final long timestampNs = SystemClock.elapsedRealtimeNanos();
		final long timestampNs = SystemClock.uptimeNanos();
		for (int index = activityToReason.size() - 1; index >= 0; index--) {
		final WindowContainer<?> wc = activityToReason.keyAt(index);
		final ActivityRecord activity = wc.asActivityRecord();
		@@ -948,7 +945,7 @@ class ActivityMetricsLogger {
		}
		if (DEBUG_METRICS) Slog.i(TAG, "abort launch cause=" + cause);
		state.stopTrace(true /* abort /, null / endInfo */);
		launchObserverNotifyIntentFailed(state.mCurrentTransitionStartTimeNs);
		launchObserverNotifyIntentFailed(state.mStartUptimeNs);
		}

		/** Aborts tracking of current launch metrics. */
		@@ -1013,13 +1010,13 @@ class ActivityMetricsLogger {
		// This will avoid any races with other operations that modify the ActivityRecord.
		final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
		if (info.isInterestingToLoggerAndObserver()) {
		final long timestamp = info.mTransitionStartTimeNs;
		final long uptime = info.mTransitionDeviceUptimeMs;
		final long timestampNs = info.mLaunchingState.mStartRealtimeNs;
		final long uptimeNs = info.mLaunchingState.mStartUptimeNs;
		final int transitionDelay = info.mCurrentTransitionDelayMs;
		final int processState = info.mProcessState;
		final int processOomAdj = info.mProcessOomAdj;
		mLoggerHandler.post(() -> logAppTransition(
		timestamp, uptime, transitionDelay, infoSnapshot, isHibernating,
		timestampNs, uptimeNs, transitionDelay, infoSnapshot, isHibernating,
		processState, processOomAdj));
		}
		mLoggerHandler.post(() -> logAppDisplayed(infoSnapshot));
		@@ -1031,7 +1028,7 @@ class ActivityMetricsLogger {
		}

		// This gets called on another thread without holding the activity manager lock.
		private void logAppTransition(long transitionStartTimeNs, long transitionDeviceUptimeMs,
		private void logAppTransition(long transitionStartTimeNs, long transitionDeviceUptimeNs,
		int currentTransitionDelayMs, TransitionInfoSnapshot info, boolean isHibernating,
		int processState, int processOomAdj) {
		final LogMaker builder = new LogMaker(APP_TRANSITION);
		@@ -1049,7 +1046,7 @@ class ActivityMetricsLogger {
		}
		builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0);
		builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS,
		TimeUnit.MILLISECONDS.toSeconds(transitionDeviceUptimeMs));
		TimeUnit.NANOSECONDS.toSeconds(transitionDeviceUptimeNs));
		builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs);
		builder.setSubtype(info.reason);
		if (info.startingWindowDelayMs != INVALID_DELAY) {
		@@ -1188,10 +1185,11 @@ class ActivityMetricsLogger {
		return null;
		}

		final long currentTimestampNs = SystemClock.elapsedRealtimeNanos();
		final long currentTimestampNs = SystemClock.uptimeNanos();
		final long startupTimeMs = info.mPendingFullyDrawn != null
		? info.mWindowsDrawnDelayMs
		: TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - info.mTransitionStartTimeNs);
		: TimeUnit.NANOSECONDS.toMillis(
		currentTimestampNs - info.mLaunchingState.mStartUptimeNs);
		final TransitionInfoSnapshot infoSnapshot =
		new TransitionInfoSnapshot(info, r, (int) startupTimeMs);
		mLoggerHandler.post(() -> logAppFullyDrawn(infoSnapshot));
		@@ -1603,7 +1601,7 @@ class ActivityMetricsLogger {
		}
		info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName;
		Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
		(int) info.mTransitionStartTimeNs /* cookie */);
		(int) info.mLaunchingState.mStartRealtimeNs /* cookie */);
		}

		/** Stops trace for the launch is completed or cancelled. */
		@@ -1613,7 +1611,7 @@ class ActivityMetricsLogger {
		return;
		}
		Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
		(int) info.mTransitionStartTimeNs /* cookie */);
		(int) info.mLaunchingState.mStartRealtimeNs /* cookie */);
		info.mLaunchTraceName = null;
		}

		@@ -1658,7 +1656,7 @@ class ActivityMetricsLogger {
		convertTransitionTypeToLaunchObserverTemperature(info.mTransitionType);

		// Beginning a launch is timing sensitive and so should be observed as soon as possible.
		mLaunchObserver.onActivityLaunched(info.mTransitionStartTimeNs,
		mLaunchObserver.onActivityLaunched(info.mLaunchingState.mStartUptimeNs,
		info.mLastLaunchedActivity.mActivityComponent, temperature);

		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		@@ -1670,7 +1668,7 @@ class ActivityMetricsLogger {
		private void launchObserverNotifyReportFullyDrawn(TransitionInfo info, long timestampNs) {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
		"MetricsLogger:launchObserverNotifyReportFullyDrawn");
		mLaunchObserver.onReportFullyDrawn(info.mTransitionStartTimeNs, timestampNs);
		mLaunchObserver.onReportFullyDrawn(info.mLaunchingState.mStartUptimeNs, timestampNs);
		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		}

		@@ -1682,7 +1680,7 @@ class ActivityMetricsLogger {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
		"MetricsLogger:launchObserverNotifyActivityLaunchCancelled");

		mLaunchObserver.onActivityLaunchCancelled(info.mTransitionStartTimeNs);
		mLaunchObserver.onActivityLaunchCancelled(info.mLaunchingState.mStartUptimeNs);

		Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
		}
		@@ -1695,7 +1693,7 @@ class ActivityMetricsLogger {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
		"MetricsLogger:launchObserverNotifyActivityLaunchFinished");

		mLaunchObserver.onActivityLaunchFinished(info.mTransitionStartTimeNs,
		mLaunchObserver.onActivityLaunchFinished(info.mLaunchingState.mStartUptimeNs,
		info.mLastLaunchedActivity.mActivityComponent, 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
		@@ -6549,9 +6549,9 @@ final class ActivityRecord extends WindowToken implements WindowManagerService.A
		}

		/** Called when the windows associated app window container are drawn. */
		private void onWindowsDrawn(long timestampNs) {
		private void onWindowsDrawn() {
		final TransitionInfoSnapshot info = mTaskSupervisor
		.getActivityMetricsLogger().notifyWindowsDrawn(this, timestampNs);
		.getActivityMetricsLogger().notifyWindowsDrawn(this);
		final boolean validInfo = info != null;
		final int windowsDrawnDelayMs = validInfo ? info.windowsDrawnDelayMs : INVALID_DELAY;
		final @WaitResult.LaunchState int launchState =
		@@ -6678,7 +6678,7 @@ final class ActivityRecord extends WindowToken implements WindowManagerService.A
		+ numInteresting + " visible=" + numVisible);
		if (nowDrawn != mReportedDrawn) {
		if (nowDrawn) {
		onWindowsDrawn(SystemClock.elapsedRealtimeNanos());
		onWindowsDrawn();
		}
		mReportedDrawn = nowDrawn;
		}

services/tests/wmtests/src/com/android/server/wm/ActivityMetricsLaunchObserverTests.java

+1 −1

Original line number	Diff line number	Diff line
		@@ -384,7 +384,7 @@ public class ActivityMetricsLaunchObserverTests extends WindowTestsBase {
		}

		private ActivityMetricsLogger.TransitionInfoSnapshot notifyWindowsDrawn(ActivityRecord r) {
		return mActivityMetricsLogger.notifyWindowsDrawn(r, SystemClock.elapsedRealtimeNanos());
		return mActivityMetricsLogger.notifyWindowsDrawn(r);
		}

		@Test