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

Commit 3d82416e authored by TreeHugger Robot's avatar TreeHugger Robot Committed by Android (Google) Code Review
Browse files

Merge changes from topic "am_launch_times"

* changes:
  AM: Update WaitResult parsing logic in AppLaunch
  AM: Use ActivityMetricsLogger to get app launch times
parents 75d2c1f1 017cddcb
Loading
Loading
Loading
Loading
+1 −4
Original line number Diff line number Diff line
@@ -28,10 +28,10 @@ import java.io.PrintWriter;
 * @hide
 */
public class WaitResult implements Parcelable {
    public static final int INVALID_DELAY = -1;
    public int result;
    public boolean timeout;
    public ComponentName who;
    public long thisTime;
    public long totalTime;

    public WaitResult() {
@@ -47,7 +47,6 @@ public class WaitResult implements Parcelable {
        dest.writeInt(result);
        dest.writeInt(timeout ? 1 : 0);
        ComponentName.writeToParcel(who, dest);
        dest.writeLong(thisTime);
        dest.writeLong(totalTime);
    }

@@ -68,7 +67,6 @@ public class WaitResult implements Parcelable {
        result = source.readInt();
        timeout = source.readInt() != 0;
        who = ComponentName.readFromParcel(source);
        thisTime = source.readLong();
        totalTime = source.readLong();
    }

@@ -77,7 +75,6 @@ public class WaitResult implements Parcelable {
        pw.println(prefix + "  result=" + result);
        pw.println(prefix + "  timeout=" + timeout);
        pw.println(prefix + "  who=" + who);
        pw.println(prefix + "  thisTime=" + thisTime);
        pw.println(prefix + "  totalTime=" + totalTime);
    }
}
 No newline at end of file
+0 −13
Original line number Diff line number Diff line
@@ -4202,7 +4202,6 @@ public class ActivityManagerService extends IActivityManager.Stub
    private final void handleAppDiedLocked(ProcessRecord app,
            boolean restarting, boolean allowRestart) {
        int pid = app.pid;
        final boolean clearLaunchStartTime = !restarting && app.removed && app.foregroundActivities;
        boolean kept = cleanUpApplicationRecordLocked(app, restarting, allowRestart, -1,
                false /*replacingPid*/);
        if (!kept && !restarting) {
@@ -4243,18 +4242,6 @@ public class ActivityManagerService extends IActivityManager.Stub
            mWindowManager.continueSurfaceLayout();
        }
        // TODO (b/67683350)
        // When an app process is removed, activities from the process may be relaunched. In the
        // case of forceStopPackageLocked the activities are finished before any window is drawn,
        // and the launch time is not cleared. This will be incorrectly used to calculate launch
        // time for the next launched activity launched in the same windowing mode.
        if (clearLaunchStartTime) {
            final LaunchTimeTracker.Entry entry = mStackSupervisor
                    .getLaunchTimeTracker().getEntry(mStackSupervisor.getWindowingMode());
            if (entry != null) {
                entry.mLaunchStartTime = 0;
            }
        }
    }
    private final int getLRURecordIndexForAppLocked(IApplicationThread thread) {
+0 −3
Original line number Diff line number Diff line
@@ -568,9 +568,6 @@ final class ActivityManagerShellCommand extends ShellCommand {
                if (result.who != null) {
                    pw.println("Activity: " + result.who.flattenToShortString());
                }
                if (result.thisTime >= 0) {
                    pw.println("ThisTime: " + result.thisTime);
                }
                if (result.totalTime >= 0) {
                    pw.println("TotalTime: " + result.totalTime);
                }
+155 −31
Original line number Diff line number Diff line
@@ -75,6 +75,7 @@ import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_T
import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_METRICS;
import static com.android.server.am.ActivityManagerDebugConfig.TAG_AM;
import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NAME;
import static com.android.server.am.EventLogTags.AM_ACTIVITY_LAUNCH_TIME;
import static com.android.server.am.MemoryStatUtil.MemoryStat;
import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem;
import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT;
@@ -89,10 +90,14 @@ import android.os.Handler;
import android.os.Looper;
import android.os.Message;
import android.os.SystemClock;
import android.os.Trace;
import android.util.EventLog;
import android.util.Log;
import android.util.Slog;
import android.util.SparseArray;
import android.util.SparseIntArray;
import android.util.StatsLog;
import android.util.TimeUtils;

import com.android.internal.logging.MetricsLogger;
import com.android.internal.os.BackgroundThread;
@@ -100,7 +105,12 @@ import com.android.internal.os.SomeArgs;
import com.android.server.LocalServices;

/**
 * Handles logging into Tron.
 * Listens to activity launches, transitions, visibility changes and window drawn callbacks to
 * determine app launch times and draw delays. Source of truth for activity metrics and provides
 * data for Tron, logcat, event logs and {@link android.app.WaitResult}.
 *
 * Tests:
 * atest SystemMetricsFunctionalTests
 */
class ActivityMetricsLogger {

@@ -115,6 +125,8 @@ class ActivityMetricsLogger {
    private static final int WINDOW_STATE_INVALID = -1;

    private static final long INVALID_START_TIME = -1;
    private static final int INVALID_DELAY = -1;
    private static final int INVALID_TRANSITION_TYPE = -1;

    private static final int MSG_CHECK_VISIBILITY = 0;

@@ -143,6 +155,8 @@ class ActivityMetricsLogger {
    private final H mHandler;

    private ArtManagerInternal mArtManagerInternal;
    private boolean mDrawingTraceActive;
    private final StringBuilder mStringBuilder = new StringBuilder();

    private final class H extends Handler {

@@ -165,36 +179,56 @@ class ActivityMetricsLogger {
        private ActivityRecord launchedActivity;
        private int startResult;
        private boolean currentTransitionProcessRunning;
        /** Elapsed time from when we launch an activity to when its windows are drawn. */
        private int windowsDrawnDelayMs;
        private int startingWindowDelayMs = -1;
        private int bindApplicationDelayMs = -1;
        private int startingWindowDelayMs = INVALID_DELAY;
        private int bindApplicationDelayMs = INVALID_DELAY;
        private int reason = APP_TRANSITION_TIMEOUT;
        private boolean loggedWindowsDrawn;
        private boolean loggedStartingWindowDrawn;
        private boolean launchTraceActive;
    }

    private final class WindowingModeTransitionInfoSnapshot {
    final class WindowingModeTransitionInfoSnapshot {
        final private ApplicationInfo applicationInfo;
        final private WindowProcessController processRecord;
        final private String packageName;
        final private String launchedActivityName;
        final String packageName;
        final String launchedActivityName;
        final private String launchedActivityLaunchedFromPackage;
        final private String launchedActivityLaunchToken;
        final private String launchedActivityAppRecordRequiredAbi;
        final String launchedActivityShortComponentName;
        final private String processName;
        final private int reason;
        final private int startingWindowDelayMs;
        final private int bindApplicationDelayMs;
        final private int windowsDrawnDelayMs;
        final private int type;
        final int windowsDrawnDelayMs;
        final int type;
        final int userId;
        /**
         * Elapsed time from when we launch an activity to when the app reported it was
         * fully drawn. If this is not reported then the value is set to INVALID_DELAY.
         */
        final int windowsFullyDrawnDelayMs;
        final int activityRecordIdHashCode;

        private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info) {
            applicationInfo = info.launchedActivity.appInfo;
            packageName = info.launchedActivity.packageName;
            launchedActivityName = info.launchedActivity.info.name;
            launchedActivityLaunchedFromPackage = info.launchedActivity.launchedFromPackage;
            launchedActivityLaunchToken = info.launchedActivity.info.launchToken;
            launchedActivityAppRecordRequiredAbi = info.launchedActivity.app == null
            this(info, info.launchedActivity);
        }

        private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info,
                ActivityRecord launchedActivity) {
            this(info, launchedActivity, INVALID_DELAY);
        }

        private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info,
                ActivityRecord launchedActivity, int windowsFullyDrawnDelayMs) {
            applicationInfo = launchedActivity.appInfo;
            packageName = launchedActivity.packageName;
            launchedActivityName = launchedActivity.info.name;
            launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage;
            launchedActivityLaunchToken = launchedActivity.info.launchToken;
            launchedActivityAppRecordRequiredAbi = launchedActivity.app == null
                    ? null
                    : info.launchedActivity.app.getRequiredAbi();
            reason = info.reason;
@@ -204,6 +238,10 @@ class ActivityMetricsLogger {
            type = getTransitionType(info);
            processRecord = findProcessForActivity(info.launchedActivity);
            processName = info.launchedActivity.processName;
            userId = launchedActivity.userId;
            launchedActivityShortComponentName = launchedActivity.shortComponentName;
            activityRecordIdHashCode = System.identityHashCode(launchedActivity);
            this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;
        }
    }

@@ -335,7 +373,7 @@ class ActivityMetricsLogger {
                || 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 */);
            reset(true /* abort */, info);
            return;
        } else if (otherWindowModesLaunching) {
            // Don't log this windowing mode but continue with the other windowing modes.
@@ -351,6 +389,7 @@ class ActivityMetricsLogger {
        mWindowingModeTransitionInfo.put(windowingMode, newInfo);
        mLastWindowingModeTransitionInfo.put(windowingMode, newInfo);
        mCurrentTransitionDeviceUptime = (int) (SystemClock.uptimeMillis() / 1000);
        startTraces(newInfo);
    }

    /**
@@ -364,18 +403,21 @@ class ActivityMetricsLogger {
    /**
     * Notifies the tracker that all windows of the app have been drawn.
     */
    void notifyWindowsDrawn(int windowingMode, long timestamp) {
    WindowingModeTransitionInfoSnapshot notifyWindowsDrawn(int windowingMode, long timestamp) {
        if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn windowingMode=" + windowingMode);

        final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
        if (info == null || info.loggedWindowsDrawn) {
            return;
            return null;
        }
        info.windowsDrawnDelayMs = calculateDelay(timestamp);
        info.loggedWindowsDrawn = true;
        final WindowingModeTransitionInfoSnapshot infoSnapshot =
                new WindowingModeTransitionInfoSnapshot(info);
        if (allWindowsDrawn() && mLoggedTransitionStarting) {
            reset(false /* abort */);
            reset(false /* abort */, info);
        }
        return infoSnapshot;
    }

    /**
@@ -394,7 +436,7 @@ class ActivityMetricsLogger {
     * Notifies the tracker that the app transition is starting.
     *
     * @param windowingModeToReason A map from windowing mode to a reason integer, which must be on
     *                              of ActivityManagerInternal.APP_TRANSITION_* reasons.
     *                              of ActivityTaskManagerInternal.APP_TRANSITION_* reasons.
     */
    void notifyTransitionStarting(SparseIntArray windowingModeToReason, long timestamp) {
        if (!isAnyTransitionActive() || mLoggedTransitionStarting) {
@@ -413,7 +455,7 @@ class ActivityMetricsLogger {
            info.reason = windowingModeToReason.valueAt(index);
        }
        if (allWindowsDrawn()) {
            reset(false /* abort */);
            reset(false /* abort */, null /* WindowingModeTransitionInfo */);
        }
    }

@@ -452,8 +494,9 @@ class ActivityMetricsLogger {
                logAppTransitionCancel(info);
                mWindowingModeTransitionInfo.remove(r.getWindowingMode());
                if (mWindowingModeTransitionInfo.size() == 0) {
                    reset(true /* abort */);
                    reset(true /* abort */, info);
                }
                stopFullyDrawnTraceIfNeeded();
            }
        }
    }
@@ -488,19 +531,19 @@ class ActivityMetricsLogger {
                && mWindowingModeTransitionInfo.size() > 0;
    }

    private void reset(boolean abort) {
    private void reset(boolean abort, WindowingModeTransitionInfo info) {
        if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort);
        if (!abort && isAnyTransitionActive()) {
            logAppTransitionMultiEvents();
        }
        stopLaunchTrace(info);
        mCurrentTransitionStartTime = INVALID_START_TIME;
        mCurrentTransitionDelayMs = -1;
        mCurrentTransitionDelayMs = INVALID_DELAY;
        mLoggedTransitionStarting = false;
        mWindowingModeTransitionInfo.clear();
    }

    private int calculateCurrentDelay() {

        // Shouldn't take more than 25 days to launch an app, so int is fine here.
        return (int) (SystemClock.uptimeMillis() - mCurrentTransitionStartTime);
    }
@@ -512,7 +555,7 @@ class ActivityMetricsLogger {

    private void logAppTransitionCancel(WindowingModeTransitionInfo info) {
        final int type = getTransitionType(info);
        if (type == -1) {
        if (type == INVALID_TRANSITION_TYPE) {
            return;
        }
        final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED);
@@ -533,7 +576,7 @@ class ActivityMetricsLogger {
        for (int index = mWindowingModeTransitionInfo.size() - 1; index >= 0; index--) {
            final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.valueAt(index);
            final int type = getTransitionType(info);
            if (type == -1) {
            if (type == INVALID_TRANSITION_TYPE) {
                return;
            }

@@ -545,6 +588,7 @@ class ActivityMetricsLogger {
            final int currentTransitionDelayMs = mCurrentTransitionDelayMs;
            BackgroundThread.getHandler().post(() -> logAppTransition(
                    currentTransitionDeviceUptime, currentTransitionDelayMs, infoSnapshot));
            BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));

            info.launchedActivity.info.launchToken = null;
        }
@@ -571,11 +615,11 @@ class ActivityMetricsLogger {
                currentTransitionDeviceUptime);
        builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs);
        builder.setSubtype(info.reason);
        if (info.startingWindowDelayMs != -1) {
        if (info.startingWindowDelayMs != INVALID_DELAY) {
            builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
                    info.startingWindowDelayMs);
        }
        if (info.bindApplicationDelayMs != -1) {
        if (info.bindApplicationDelayMs != INVALID_DELAY) {
            builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS,
                    info.bindApplicationDelayMs);
        }
@@ -612,6 +656,24 @@ class ActivityMetricsLogger {
        logAppStartMemoryStateCapture(info);
    }

    private void logAppDisplayed(WindowingModeTransitionInfoSnapshot info) {
        if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
            return;
        }

        EventLog.writeEvent(AM_ACTIVITY_LAUNCH_TIME,
                info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName,
                info.windowsDrawnDelayMs);

        StringBuilder sb = mStringBuilder;
        sb.setLength(0);
        sb.append("Displayed ");
        sb.append(info.launchedActivityShortComponentName);
        sb.append(": ");
        TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);
        Log.i(TAG, sb.toString());
    }

    private int convertAppStartTransitionType(int tronType) {
        if (tronType == TYPE_TRANSITION_COLD_LAUNCH) {
            return StatsLog.APP_START_OCCURRED__TYPE__COLD;
@@ -625,11 +687,12 @@ class ActivityMetricsLogger {
        return StatsLog.APP_START_OCCURRED__TYPE__UNKNOWN;
     }

    void logAppTransitionReportedDrawn(ActivityRecord r, boolean restoredFromBundle) {
    WindowingModeTransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,
            boolean restoredFromBundle) {
        final WindowingModeTransitionInfo info = mLastWindowingModeTransitionInfo.get(
                r.getWindowingMode());
        if (info == null) {
            return;
            return null;
        }
        final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
        builder.setPackageName(r.packageName);
@@ -652,6 +715,25 @@ class ActivityMetricsLogger {
                info.launchedActivity.info.name,
                info.currentTransitionProcessRunning,
                startupTimeMs);
        stopFullyDrawnTraceIfNeeded();
        final WindowingModeTransitionInfoSnapshot infoSnapshot =
                new WindowingModeTransitionInfoSnapshot(info, r, (int) startupTimeMs);
        BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));
        return infoSnapshot;
    }

    private void logAppFullyDrawn(WindowingModeTransitionInfoSnapshot 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 ");
        sb.append(info.launchedActivityShortComponentName);
        sb.append(": ");
        TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb);
        Log.i(TAG, sb.toString());
    }

    void logActivityStart(Intent intent, ProcessRecord callerApp, ActivityRecord r,
@@ -753,7 +835,7 @@ class ActivityMetricsLogger {
        } else if (info.startResult == START_SUCCESS) {
            return TYPE_TRANSITION_COLD_LAUNCH;
        }
        return -1;
        return INVALID_TRANSITION_TYPE;
    }

    private void logAppStartMemoryStateCapture(WindowingModeTransitionInfoSnapshot info) {
@@ -798,4 +880,46 @@ class ActivityMetricsLogger {
        }
        return mArtManagerInternal;
    }

    /**
     * Starts traces for app launch and draw times. We stop the fully drawn trace if its already
     * active since the app may not have reported fully drawn in the previous launch.
     *
     * See {@link android.app.Activity#reportFullyDrawn()}
     *
     * @param info
     * */
    private void startTraces(WindowingModeTransitionInfo info) {
        if (info == null) {
            return;
        }
        stopFullyDrawnTraceIfNeeded();
        int transitionType = getTransitionType(info);
        if (!info.launchTraceActive && transitionType == TYPE_TRANSITION_WARM_LAUNCH
                || transitionType == TYPE_TRANSITION_COLD_LAUNCH) {
            Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: "
                    + info.launchedActivity.packageName, 0);
            Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0);
            mDrawingTraceActive = true;
            info.launchTraceActive = true;
        }
    }

    private void stopLaunchTrace(WindowingModeTransitionInfo info) {
        if (info == null) {
            return;
        }
        if (info.launchTraceActive) {
            Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: "
                    + info.launchedActivity.packageName, 0);
            info.launchTraceActive = false;
        }
    }

    void stopFullyDrawnTraceIfNeeded() {
        if (mDrawingTraceActive) {
            Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "drawing", 0);
            mDrawingTraceActive = false;
        }
    }
}
+12 −93

File changed.

Preview size limit exceeded, changes collapsed.

Loading