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

Commit d47f90bc authored by Yan Wang's avatar Yan Wang
Browse files

startop: Add timestamps for IntentStarted and ActivityLaunchFinished. 

The timestamps are used to compute duration of TotalTime and ReportFullyDrawn.

TotalTime = t(ActivityLaunchFinished) - t(IntentStarted)
ReportFullyDrawn = t(ReportFullyDrawn) - t(IntentStarted)

where t(x) is the timestamp of x.

Bug: 137786390
Bug: 137784595
Test: Make
Test: atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests
Change-Id: I75c0be8508499dce186fd392e79b67b2fefc8842
parent 9eac5ecd

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

+3 −3
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,11 +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 timestampNanos) {













        public void onReportFullyDrawn(byte[] finalActivity, long timestampNs) {















        }















    };















































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



+6
−2




























Original line number
Diff line number
Diff line








@@ -116,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.










@@ -182,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.









@@ -191,7 +194,8 @@ 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.

































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



+46
−33




























Original line number
Diff line number
Diff line








@@ -133,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;










@@ -327,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);















        }















    }


























@@ -383,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;















        }

























@@ -408,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.










@@ -442,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;















    }









@@ -477,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.

























@@ -485,7 +488,7 @@ class ActivityMetricsLogger {













            return;















        }















        if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");













        mCurrentTransitionDelayMs = calculateDelay(timestamp);













        mCurrentTransitionDelayMs = calculateDelay(timestampNs);















        mLoggedTransitionStarting = true;































        WindowingModeTransitionInfo foundInfo = null;









@@ -502,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 */);















        }















    }


























@@ -568,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 */);















            }















        }















    }










@@ -599,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();















        }









@@ -616,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();









@@ -630,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) {










@@ -814,7 +825,7 @@ class ActivityMetricsLogger {













        builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);















        long currentTimestampNs = SystemClock.elapsedRealtimeNanos();















        long startupTimeMs =













            TimeUnit.NANOSECONDS.toMillis(currentTimestampNs) - mLastTransitionStartTime;













            TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - mLastTransitionStartTimeNs);















        builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);















        builder.setType(restoredFromBundle















                ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE










@@ -1013,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);















    }










@@ -1058,10 +1069,10 @@ class ActivityMetricsLogger {













    /**















     * Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event.















     */













    private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNanos) {













    private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs) {















        Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,















            "MetricsLogger:launchObserverNotifyReportFullyDrawn");













        mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNanos);













        mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNs);















        Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);















    }

























@@ -1085,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








@@ -3110,13 +3110,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