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

Commit e8d3d197 authored by Riddle Hsu's avatar Riddle Hsu
Browse files

AML: Enable log and trace for non-process-switch launch

It will be more convenient to measure the generic launch
time by system or event log.

MetricsLogger, StatsLog, LaunchObserver still only focus
on process-switch launch.

Bug: 132736359
Bug: 144570280
Test: atest ActivityMetricsLoggerTests# \
            testLaunchTimeEventLogNonProcessSwitch

Change-Id: I2ed45677cbf41dc15938e0fad909cb66fb6ac2c3
parent fd66d4d7
Loading
Loading
Loading
Loading
+47 −23
Original line number Original line Diff line number Diff line
@@ -190,6 +190,8 @@ class ActivityMetricsLogger {
        final int mTransitionType;
        final int mTransitionType;
        /** Whether the process was already running when the transition started. */
        /** Whether the process was already running when the transition started. */
        final boolean mProcessRunning;
        final boolean mProcessRunning;
        /** whether the process of the launching activity didn't have any active activity. */
        final boolean mProcessSwitch;
        /** The activities that should be drawn. */
        /** The activities that should be drawn. */
        final LinkedList<ActivityRecord> mPendingDrawActivities = new LinkedList<>();
        final LinkedList<ActivityRecord> mPendingDrawActivities = new LinkedList<>();
        /** The latest activity to have been launched. */
        /** The latest activity to have been launched. */
@@ -218,7 +220,8 @@ class ActivityMetricsLogger {
        /** @return Non-null if there will be a window drawn event for the launch. */
        /** @return Non-null if there will be a window drawn event for the launch. */
        @Nullable
        @Nullable
        static TransitionInfo create(@NonNull ActivityRecord r,
        static TransitionInfo create(@NonNull ActivityRecord r,
                @NonNull LaunchingState launchingState, boolean processRunning, int startResult) {
                @NonNull LaunchingState launchingState, boolean processRunning,
                boolean processSwitch, int startResult) {
            int transitionType = INVALID_TRANSITION_TYPE;
            int transitionType = INVALID_TRANSITION_TYPE;
            if (processRunning) {
            if (processRunning) {
                if (startResult == START_SUCCESS) {
                if (startResult == START_SUCCESS) {
@@ -235,16 +238,18 @@ class ActivityMetricsLogger {
                // That means the startResult is neither START_SUCCESS nor START_TASK_TO_FRONT.
                // That means the startResult is neither START_SUCCESS nor START_TASK_TO_FRONT.
                return null;
                return null;
            }
            }
            return new TransitionInfo(r, launchingState, transitionType, processRunning);
            return new TransitionInfo(r, launchingState, transitionType, processRunning,
                    processSwitch);
        }
        }


        /** Use {@link TransitionInfo#create} instead to ensure the transition type is valid. */
        /** Use {@link TransitionInfo#create} instead to ensure the transition type is valid. */
        private TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType,
        private TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType,
                boolean processRunning) {
                boolean processRunning, boolean processSwitch) {
            mLaunchingState = launchingState;
            mLaunchingState = launchingState;
            mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs;
            mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs;
            mTransitionType = transitionType;
            mTransitionType = transitionType;
            mProcessRunning = processRunning;
            mProcessRunning = processRunning;
            mProcessSwitch = processSwitch;
            mCurrentTransitionDeviceUptime =
            mCurrentTransitionDeviceUptime =
                    (int) TimeUnit.MILLISECONDS.toSeconds(SystemClock.uptimeMillis());
                    (int) TimeUnit.MILLISECONDS.toSeconds(SystemClock.uptimeMillis());
            setLatestLaunchedActivity(r);
            setLatestLaunchedActivity(r);
@@ -282,6 +287,14 @@ class ActivityMetricsLogger {
            return mPendingDrawActivities.isEmpty();
            return mPendingDrawActivities.isEmpty();
        }
        }


        /**
         * @return {@code true} if the transition info should be sent to MetricsLogger, StatsLog, or
         *         LaunchObserver.
         */
        boolean isInterestingToLoggerAndObserver() {
            return mProcessSwitch;
        }

        int calculateCurrentDelay() {
        int calculateCurrentDelay() {
            return calculateDelay(SystemClock.elapsedRealtimeNanos());
            return calculateDelay(SystemClock.elapsedRealtimeNanos());
        }
        }
@@ -540,13 +553,8 @@ class ActivityMetricsLogger {
            return;
            return;
        }
        }


        if (!processSwitch) {
            abort(info, "not a process switch");
            return;
        }

        final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState,
        final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState,
                processRunning, resultCode);
                processRunning, processSwitch, resultCode);
        if (newInfo == null) {
        if (newInfo == null) {
            abort(info, "unrecognized launch");
            abort(info, "unrecognized launch");
            return;
            return;
@@ -557,7 +565,12 @@ class ActivityMetricsLogger {
        mTransitionInfoList.add(newInfo);
        mTransitionInfoList.add(newInfo);
        mLastTransitionInfo.put(launchedActivity, newInfo);
        mLastTransitionInfo.put(launchedActivity, newInfo);
        startLaunchTrace(newInfo);
        startLaunchTrace(newInfo);
        if (newInfo.isInterestingToLoggerAndObserver()) {
            launchObserverNotifyActivityLaunched(newInfo);
            launchObserverNotifyActivityLaunched(newInfo);
        } else {
            // As abort for no process switch.
            launchObserverNotifyIntentFailed();
        }
    }
    }


    /**
    /**
@@ -733,8 +746,10 @@ class ActivityMetricsLogger {
            launchObserverNotifyActivityLaunchCancelled(info);
            launchObserverNotifyActivityLaunchCancelled(info);
        } else {
        } else {
            logAppTransitionFinished(info);
            logAppTransitionFinished(info);
            if (info.isInterestingToLoggerAndObserver()) {
                launchObserverNotifyActivityLaunchFinished(info, timestampNs);
                launchObserverNotifyActivityLaunchFinished(info, timestampNs);
            }
            }
        }
        info.mPendingDrawActivities.clear();
        info.mPendingDrawActivities.clear();
        mTransitionInfoList.remove(info);
        mTransitionInfoList.remove(info);
    }
    }
@@ -768,8 +783,11 @@ class ActivityMetricsLogger {
        // Take a snapshot of the transition info before sending it to the handler for logging.
        // Take a snapshot of the transition info before sending it to the handler for logging.
        // This will avoid any races with other operations that modify the ActivityRecord.
        // This will avoid any races with other operations that modify the ActivityRecord.
        final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
        final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
        if (info.isInterestingToLoggerAndObserver()) {
            BackgroundThread.getHandler().post(() -> logAppTransition(
            BackgroundThread.getHandler().post(() -> logAppTransition(
                info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs, infoSnapshot));
                    info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs,
                    infoSnapshot));
        }
        BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));
        BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));
        if (info.mPendingFullyDrawn != null) {
        if (info.mPendingFullyDrawn != null) {
            info.mPendingFullyDrawn.run();
            info.mPendingFullyDrawn.run();
@@ -905,6 +923,18 @@ class ActivityMetricsLogger {
            return null;
            return null;
        }
        }


        final long currentTimestampNs = SystemClock.elapsedRealtimeNanos();
        final long startupTimeMs = info.mPendingFullyDrawn != null
                ? info.mWindowsDrawnDelayMs
                : TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - info.mTransitionStartTimeNs);
        final TransitionInfoSnapshot infoSnapshot =
                new TransitionInfoSnapshot(info, r, (int) startupTimeMs);
        BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));

        if (!info.isInterestingToLoggerAndObserver()) {
            return infoSnapshot;
        }

        // Record the handling of the reportFullyDrawn callback in the trace system. This is not
        // Record the handling of the reportFullyDrawn callback in the trace system. This is not
        // actually used to trace this function, but instead the logical task that this function
        // actually used to trace this function, but instead the logical task that this function
        // fullfils (handling reportFullyDrawn() callbacks).
        // fullfils (handling reportFullyDrawn() callbacks).
@@ -914,10 +944,6 @@ class ActivityMetricsLogger {
        final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
        final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
        builder.setPackageName(r.packageName);
        builder.setPackageName(r.packageName);
        builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
        builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
        final long currentTimestampNs = SystemClock.elapsedRealtimeNanos();
        final long startupTimeMs = info.mPendingFullyDrawn != null
                ? info.mWindowsDrawnDelayMs
                : TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - info.mTransitionStartTimeNs);
        builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
        builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
        builder.setType(restoredFromBundle
        builder.setType(restoredFromBundle
                ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
                ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
@@ -940,10 +966,6 @@ class ActivityMetricsLogger {
        // the trace slice to have a noticable duration.
        // the trace slice to have a noticable duration.
        Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
        Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);


        final TransitionInfoSnapshot infoSnapshot =
                new TransitionInfoSnapshot(info, r, (int) startupTimeMs);
        BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));

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


@@ -1069,7 +1091,8 @@ class ActivityMetricsLogger {
            return;
            return;
        }
        }
        info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName;
        info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName;
        Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName, 0);
        Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
                (int) info.mTransitionStartTimeNs /* cookie */);
    }
    }


    /** Stops trace for the launch is completed or cancelled. */
    /** Stops trace for the launch is completed or cancelled. */
@@ -1078,7 +1101,8 @@ class ActivityMetricsLogger {
        if (info.mLaunchTraceName == null) {
        if (info.mLaunchTraceName == null) {
            return;
            return;
        }
        }
        Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName, 0);
        Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
                (int) info.mTransitionStartTimeNs /* cookie */);
        info.mLaunchTraceName = null;
        info.mLaunchTraceName = null;
    }
    }