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

Commit 8820f0cf authored by Riddle Hsu's avatar Riddle Hsu
Browse files

Move fully drawn metric log out of wm lock 

The method getPackageOptimizationInfo will access IO which
may spend 3~10+ms, so post the log action to the logger thread
to avoid blocking other important UI operations.

ActivityRecord#reportFullyDrawnLocked is removed because fully
drawn won't be accepted if the window is not drawn, so the
invocation reportActivityLaunched in it is a dead code.
Currently reportActivityLaunched will be called from
ActivityRecord#onWindowsDrawn.

Bug: 236677935
Test: atest ActivityMetricsLaunchObserverTests
Change-Id: Ic64b9722de4edb0a41cc7370ed0ed2f7019bbdec
parent 4e72b984

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

+2 −1
Original line number Diff line number Diff line
@@ -1211,7 +1211,8 @@ class ActivityClientController extends IActivityClientController.Stub { 
            synchronized (mGlobalLock) {

                final ActivityRecord r = ActivityRecord.isInRootTaskLocked(token);

                if (r != null) {

                    r.reportFullyDrawnLocked(restoredFromBundle);

                    mTaskSupervisor.getActivityMetricsLogger().notifyFullyDrawn(r,

                            restoredFromBundle);

                }

            }

        } finally {

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

+47 −44
Original line number Diff line number Diff line
@@ -454,6 +454,7 @@ class ActivityMetricsLogger { 
        final int windowsFullyDrawnDelayMs;

        final int activityRecordIdHashCode;

        final boolean relaunched;

        final long timestampNs;



        private TransitionInfoSnapshot(TransitionInfo info) {

            this(info, info.mLastLaunchedActivity, INVALID_DELAY);
@@ -483,6 +484,7 @@ class ActivityMetricsLogger { 
            activityRecordIdHashCode = System.identityHashCode(launchedActivity);

            this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;

            relaunched = info.mRelaunched;

            timestampNs = info.mLaunchingState.mStartRealtimeNs;

        }



        @WaitResult.LaunchState int getLaunchState() {
@@ -498,6 +500,10 @@ class ActivityMetricsLogger { 
            }

        }



        boolean isIntresetedToEventLog() {

            return type == TYPE_TRANSITION_WARM_LAUNCH || type == TYPE_TRANSITION_COLD_LAUNCH;

        }



        PackageOptimizationInfo getPackageOptimizationInfo(ArtManagerInternal artManagerInternal) {

            return artManagerInternal == null || launchedActivityAppRecordRequiredAbi == null

                    ? PackageOptimizationInfo.createWithNoInfo()
@@ -1022,16 +1028,17 @@ 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 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(

                    timestampNs, uptimeNs, transitionDelay, infoSnapshot, isHibernating,

                    uptimeNs, transitionDelay, infoSnapshot, isHibernating,

                    processState, processOomAdj));

        }

        if (infoSnapshot.isIntresetedToEventLog()) {

            mLoggerHandler.post(() -> logAppDisplayed(infoSnapshot));

        }

        if (info.mPendingFullyDrawn != null) {

            info.mPendingFullyDrawn.run();

        }
@@ -1040,7 +1047,7 @@ class ActivityMetricsLogger { 
    }



    // This gets called on another thread without holding the activity manager lock.

    private void logAppTransition(long transitionStartTimeNs, long transitionDeviceUptimeNs,

    private void logAppTransition(long transitionDeviceUptimeNs,

            int currentTransitionDelayMs, TransitionInfoSnapshot info, boolean isHibernating,

            int processState, int processOomAdj) {

        final LogMaker builder = new LogMaker(APP_TRANSITION);
@@ -1108,7 +1115,7 @@ class ActivityMetricsLogger { 
                isIncremental,

                isLoading,

                info.launchedActivityName.hashCode(),

                TimeUnit.NANOSECONDS.toMillis(transitionStartTimeNs),

                TimeUnit.NANOSECONDS.toMillis(info.timestampNs),

                processState,

                processOomAdj);
@@ -1132,10 +1139,6 @@ class ActivityMetricsLogger { 
    }



    private void logAppDisplayed(TransitionInfoSnapshot info) {

        if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {

            return;

        }



        EventLog.writeEvent(WM_ACTIVITY_LAUNCH_TIME,

                info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName,

                info.windowsDrawnDelayMs);
@@ -1181,8 +1184,7 @@ class ActivityMetricsLogger { 
    }



    /** @see android.app.Activity#reportFullyDrawn */

    TransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,

            boolean restoredFromBundle) {

    TransitionInfoSnapshot notifyFullyDrawn(ActivityRecord r, boolean restoredFromBundle) {

        final TransitionInfo info = mLastTransitionInfo.get(r);

        if (info == null) {

            return null;
@@ -1191,7 +1193,7 @@ class ActivityMetricsLogger { 
            // There are still undrawn activities, postpone reporting fully drawn until all of its

            // windows are drawn. So that is closer to an usable state.

            info.mPendingFullyDrawn = () -> {

                logAppTransitionReportedDrawn(r, restoredFromBundle);

                notifyFullyDrawn(r, restoredFromBundle);

                info.mPendingFullyDrawn = null;

            };

            return null;
@@ -1204,7 +1206,9 @@ class ActivityMetricsLogger { 
                        currentTimestampNs - info.mLaunchingState.mStartUptimeNs);

        final TransitionInfoSnapshot infoSnapshot =

                new TransitionInfoSnapshot(info, r, (int) startupTimeMs);

        if (infoSnapshot.isIntresetedToEventLog()) {

            mLoggerHandler.post(() -> logAppFullyDrawn(infoSnapshot));

        }

        mLastTransitionInfo.remove(r);



        if (!info.isInterestingToLoggerAndObserver()) {
@@ -1216,61 +1220,60 @@ class ActivityMetricsLogger { 
        // fullfils (handling reportFullyDrawn() callbacks).

        Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,

                "ActivityManager:ReportingFullyDrawn " + info.mLastLaunchedActivity.packageName);

        mLoggerHandler.post(() -> logAppFullyDrawnMetrics(infoSnapshot, restoredFromBundle,

                info.mProcessRunning));

        // Ends the trace started at the beginning of this function. This is located here to allow

        // the trace slice to have a noticable duration.

        Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);



        // Notify reportFullyDrawn event.

        launchObserverNotifyReportFullyDrawn(info, currentTimestampNs);



        return infoSnapshot;

    }



    private void logAppFullyDrawnMetrics(TransitionInfoSnapshot info, boolean restoredFromBundle,

            boolean processRunning) {

        final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);

        builder.setPackageName(r.packageName);

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

        builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);

        builder.setPackageName(info.packageName);

        builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName);

        builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS,

                (long) info.windowsFullyDrawnDelayMs);

        builder.setType(restoredFromBundle

                ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE

                : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);

        builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING,

                info.mProcessRunning ? 1 : 0);

        builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING, processRunning ? 1 : 0);

        mMetricsLogger.write(builder);

        final PackageOptimizationInfo packageOptimizationInfo =

                infoSnapshot.getPackageOptimizationInfo(getArtManagerInternal());

                info.getPackageOptimizationInfo(getArtManagerInternal());

        // Incremental info

        boolean isIncremental = false, isLoading = false;

        final String codePath = info.mLastLaunchedActivity.info.applicationInfo.getCodePath();

        final String codePath = info.applicationInfo.getCodePath();

        if (codePath != null && IncrementalManager.isIncrementalPath(codePath)) {

            isIncremental = true;

            isLoading = isIncrementalLoading(info.mLastLaunchedActivity.packageName,

                            info.mLastLaunchedActivity.mUserId);

            isLoading = isIncrementalLoading(info.packageName, info.userId);

        }

        FrameworkStatsLog.write(

                FrameworkStatsLog.APP_START_FULLY_DRAWN,

                info.mLastLaunchedActivity.info.applicationInfo.uid,

                info.mLastLaunchedActivity.packageName,

                info.applicationInfo.uid,

                info.packageName,

                restoredFromBundle

                        ? FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE

                        : FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,

                info.mLastLaunchedActivity.info.name,

                info.mProcessRunning,

                startupTimeMs,

                info.launchedActivityName,

                processRunning,

                info.windowsFullyDrawnDelayMs,

                packageOptimizationInfo.getCompilationReason(),

                packageOptimizationInfo.getCompilationFilter(),

                info.mSourceType,

                info.mSourceEventDelayMs,

                info.sourceType,

                info.sourceEventDelayMs,

                isIncremental,

                isLoading,

                info.mLastLaunchedActivity.info.name.hashCode(),

                TimeUnit.NANOSECONDS.toMillis(info.mLaunchingState.mStartRealtimeNs));



        // Ends the trace started at the beginning of this function. This is located here to allow

        // the trace slice to have a noticable duration.

        Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);



        // Notify reportFullyDrawn event.

        launchObserverNotifyReportFullyDrawn(info, currentTimestampNs);



        return infoSnapshot;

                info.launchedActivityName.hashCode(),

                TimeUnit.NANOSECONDS.toMillis(info.timestampNs));

    }



    private void logAppFullyDrawn(TransitionInfoSnapshot info) {

        if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {

            return;

        }



        StringBuilder sb = mStringBuilder;

        sb.setLength(0);

        sb.append("Fully drawn ");

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

+0 −9
Original line number Diff line number Diff line
@@ -6485,15 +6485,6 @@ final class ActivityRecord extends WindowToken implements WindowManagerService.A 
        }

    }



    void reportFullyDrawnLocked(boolean restoredFromBundle) {

        final TransitionInfoSnapshot info = mTaskSupervisor

            .getActivityMetricsLogger().logAppTransitionReportedDrawn(this, restoredFromBundle);

        if (info != null) {

            mTaskSupervisor.reportActivityLaunched(false /* timeout */, this,

                    info.windowsFullyDrawnDelayMs, info.getLaunchState());

        }

    }



    void onFirstWindowDrawn(WindowState win) {

        firstWindowDrawn = true;

        // stop tracking

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

+2 −2
Original line number Diff line number Diff line
@@ -324,7 +324,7 @@ public class ActivityMetricsLaunchObserverTests extends WindowTestsBase { 


        // The activity reports fully drawn before windows drawn, then the fully drawn event will

        // be pending (see {@link WindowingModeTransitionInfo#pendingFullyDrawn}).

        mActivityMetricsLogger.logAppTransitionReportedDrawn(mTopActivity, false);

        mActivityMetricsLogger.notifyFullyDrawn(mTopActivity, false /* restoredFromBundle */);

        notifyTransitionStarting(mTopActivity);

        // The pending fully drawn event should send when the actual windows drawn event occurs.

        final ActivityMetricsLogger.TransitionInfoSnapshot info = notifyWindowsDrawn(mTopActivity);
@@ -337,7 +337,7 @@ public class ActivityMetricsLaunchObserverTests extends WindowTestsBase { 
        verifyNoMoreInteractions(mLaunchObserver);



        final ActivityMetricsLogger.TransitionInfoSnapshot fullyDrawnInfo = mActivityMetricsLogger

                .logAppTransitionReportedDrawn(mTopActivity, false /* restoredFromBundle */);

                .notifyFullyDrawn(mTopActivity, false /* restoredFromBundle */);

        assertWithMessage("Invisible event must be dropped").that(fullyDrawnInfo).isNull();

    }