Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 23e36d3e authored by Riddle Hsu's avatar Riddle Hsu
Browse files

Use uptime for activity startup time 

It was changed from uptime to elapsed realtime in [1] because when
changing the time unit from millisecond to nanosecond, the method
uptimeNanos is not yet available.

It may cause unexpected long duration if someone starts activity
without holding wakelock while device is not awake and the device
enters deep sleep state in the middle of the startup.

Since uptimeNanos is added, switch to it to avoid the noise.

[1]: I75c0be8508499dce186fd392e79b67b2fefc8842

Bug: 204488635
Test: atest ActivityMetricsLoggerTests

Change-Id: I86db562b6dbffa4565d21c2942b258af8e3bc44e
parent 520f0183

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
@@ -6536,9 +6536,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 =
@@ -6665,7 +6665,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