From e8d3d197d4fdda35d4389f1949e84af4f4f203dd Mon Sep 17 00:00:00 2001 From: Riddle Hsu Date: Tue, 26 Nov 2019 18:56:39 +0800 Subject: [PATCH] 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 --- .../server/wm/ActivityMetricsLogger.java | 70 +++++++++++++------ 1 file changed, 47 insertions(+), 23 deletions(-) diff --git a/services/core/java/com/android/server/wm/ActivityMetricsLogger.java b/services/core/java/com/android/server/wm/ActivityMetricsLogger.java index de51d4b267dfa..72665c84b970d 100644 --- a/services/core/java/com/android/server/wm/ActivityMetricsLogger.java +++ b/services/core/java/com/android/server/wm/ActivityMetricsLogger.java @@ -190,6 +190,8 @@ class ActivityMetricsLogger { final int mTransitionType; /** Whether the process was already running when the transition started. */ 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. */ final LinkedList mPendingDrawActivities = new LinkedList<>(); /** 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. */ @Nullable 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; if (processRunning) { if (startResult == START_SUCCESS) { @@ -235,16 +238,18 @@ class ActivityMetricsLogger { // That means the startResult is neither START_SUCCESS nor START_TASK_TO_FRONT. 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. */ private TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType, - boolean processRunning) { + boolean processRunning, boolean processSwitch) { mLaunchingState = launchingState; mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs; mTransitionType = transitionType; mProcessRunning = processRunning; + mProcessSwitch = processSwitch; mCurrentTransitionDeviceUptime = (int) TimeUnit.MILLISECONDS.toSeconds(SystemClock.uptimeMillis()); setLatestLaunchedActivity(r); @@ -282,6 +287,14 @@ class ActivityMetricsLogger { return mPendingDrawActivities.isEmpty(); } + /** + * @return {@code true} if the transition info should be sent to MetricsLogger, StatsLog, or + * LaunchObserver. + */ + boolean isInterestingToLoggerAndObserver() { + return mProcessSwitch; + } + int calculateCurrentDelay() { return calculateDelay(SystemClock.elapsedRealtimeNanos()); } @@ -540,13 +553,8 @@ class ActivityMetricsLogger { return; } - if (!processSwitch) { - abort(info, "not a process switch"); - return; - } - final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState, - processRunning, resultCode); + processRunning, processSwitch, resultCode); if (newInfo == null) { abort(info, "unrecognized launch"); return; @@ -557,7 +565,12 @@ class ActivityMetricsLogger { mTransitionInfoList.add(newInfo); mLastTransitionInfo.put(launchedActivity, newInfo); startLaunchTrace(newInfo); - launchObserverNotifyActivityLaunched(newInfo); + if (newInfo.isInterestingToLoggerAndObserver()) { + launchObserverNotifyActivityLaunched(newInfo); + } else { + // As abort for no process switch. + launchObserverNotifyIntentFailed(); + } } /** @@ -733,7 +746,9 @@ class ActivityMetricsLogger { launchObserverNotifyActivityLaunchCancelled(info); } else { logAppTransitionFinished(info); - launchObserverNotifyActivityLaunchFinished(info, timestampNs); + if (info.isInterestingToLoggerAndObserver()) { + launchObserverNotifyActivityLaunchFinished(info, timestampNs); + } } info.mPendingDrawActivities.clear(); mTransitionInfoList.remove(info); @@ -768,8 +783,11 @@ class ActivityMetricsLogger { // 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. final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info); - BackgroundThread.getHandler().post(() -> logAppTransition( - info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs, infoSnapshot)); + if (info.isInterestingToLoggerAndObserver()) { + BackgroundThread.getHandler().post(() -> logAppTransition( + info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs, + infoSnapshot)); + } BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot)); if (info.mPendingFullyDrawn != null) { info.mPendingFullyDrawn.run(); @@ -905,6 +923,18 @@ class ActivityMetricsLogger { 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 // actually used to trace this function, but instead the logical task that this function // fullfils (handling reportFullyDrawn() callbacks). @@ -914,10 +944,6 @@ class ActivityMetricsLogger { final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN); builder.setPackageName(r.packageName); 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.setType(restoredFromBundle ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE @@ -940,10 +966,6 @@ class ActivityMetricsLogger { // the trace slice to have a noticable duration. Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); - final TransitionInfoSnapshot infoSnapshot = - new TransitionInfoSnapshot(info, r, (int) startupTimeMs); - BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot)); - // Notify reportFullyDrawn event. launchObserverNotifyReportFullyDrawn(r, currentTimestampNs); @@ -1069,7 +1091,8 @@ class ActivityMetricsLogger { return; } 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. */ @@ -1078,7 +1101,8 @@ class ActivityMetricsLogger { if (info.mLaunchTraceName == null) { 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; }