Fix multi-dimen app transition delay tron event
Make sure to log everything.
Test: Open app, inspect log.
Test: com.android.systemmetrics.functional.AppStartTests
Bug: 33086172
Change-Id: I6fdfef625c09267dcf20724e853cf7471abc86c9
diff --git a/services/core/java/com/android/server/am/ActivityMetricsLogger.java b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
index ff796a54..ebbce02 100644
--- a/services/core/java/com/android/server/am/ActivityMetricsLogger.java
+++ b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
@@ -1,24 +1,36 @@
package com.android.server.am;
+import static android.app.ActivityManager.START_SUCCESS;
+import static android.app.ActivityManager.START_TASK_TO_FRONT;
import static android.app.ActivityManager.StackId.ASSISTANT_STACK_ID;
import static android.app.ActivityManager.StackId.DOCKED_STACK_ID;
import static android.app.ActivityManager.StackId.FREEFORM_WORKSPACE_STACK_ID;
import static android.app.ActivityManager.StackId.FULLSCREEN_WORKSPACE_STACK_ID;
+import static android.app.ActivityManager.StackId.INVALID_STACK_ID;
import static android.app.ActivityManager.StackId.PINNED_STACK_ID;
-
+import static android.app.ActivityManagerInternal.APP_TRANSITION_TIMEOUT;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_ACTIVITY_NAME;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH;
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.ActivityStack.STACK_INVISIBLE;
-import android.annotation.Nullable;
import android.app.ActivityManager.StackId;
import android.content.Context;
+import android.metrics.LogMaker;
import android.os.SystemClock;
import android.util.Slog;
+import android.util.SparseArray;
+import android.util.SparseIntArray;
-import android.metrics.LogMaker;
import com.android.internal.logging.MetricsLogger;
-import com.android.internal.logging.nano.MetricsProto.MetricsEvent;
import java.util.ArrayList;
@@ -48,12 +60,27 @@
private long mLastLogTimeSecs;
private final ActivityStackSupervisor mSupervisor;
private final Context mContext;
+ private final MetricsLogger mMetricsLogger = new MetricsLogger();
private long mCurrentTransitionStartTime = INVALID_START_TIME;
- private boolean mLoggedWindowsDrawn;
- private boolean mLoggedStartingWindowDrawn;
+
+ private int mCurrentTransitionDeviceUptime;
+ private int mCurrentTransitionDelayMs;
private boolean mLoggedTransitionStarting;
+ private final SparseArray<StackTransitionInfo> mStackTransitionInfo = new SparseArray<>();
+
+ private final class StackTransitionInfo {
+ private ActivityRecord launchedActivity;
+ private int startResult;
+ private boolean currentTransitionProcessRunning;
+ private int windowsDrawnDelayMs;
+ private int startingWindowDelayMs;
+ private int reason = APP_TRANSITION_TIMEOUT;
+ private boolean loggedWindowsDrawn;
+ private boolean loggedStartingWindowDrawn;
+ }
+
ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context) {
mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
mSupervisor = supervisor;
@@ -102,7 +129,9 @@
* activity.
*/
void notifyActivityLaunching() {
- mCurrentTransitionStartTime = System.currentTimeMillis();
+ if (!isAnyTransitionActive()) {
+ mCurrentTransitionStartTime = System.currentTimeMillis();
+ }
}
/**
@@ -118,9 +147,6 @@
launchedActivity.appInfo.uid)
: null;
final boolean processRunning = processRecord != null;
- final String componentName = launchedActivity != null
- ? launchedActivity.shortComponentName
- : null;
// We consider this a "process switch" if the process of the activity that gets launched
// didn't have an activity that was in started state. In this case, we assume that lot
@@ -129,7 +155,7 @@
final boolean processSwitch = processRecord == null
|| !hasStartedActivity(processRecord, launchedActivity);
- notifyActivityLaunched(resultCode, componentName, processRunning, processSwitch);
+ notifyActivityLaunched(resultCode, launchedActivity, processRunning, processSwitch);
}
private boolean hasStartedActivity(ProcessRecord record, ActivityRecord launchedActivity) {
@@ -151,92 +177,120 @@
*
* @param resultCode one of the ActivityManager.START_* flags, indicating the result of the
* launch
- * @param componentName the component name of the activity being launched
+ * @param launchedActivity the activity being launched
* @param processRunning whether the process that will contains the activity is already running
* @param processSwitch whether the process that will contain the activity didn't have any
* activity that was stopped, i.e. the started activity is "switching"
* processes
*/
- private void notifyActivityLaunched(int resultCode, @Nullable String componentName,
+ private void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity,
boolean processRunning, boolean processSwitch) {
- if (resultCode < 0 || componentName == null || !processSwitch) {
-
- // Failed to launch or it was not a process switch, so we don't care about the timing.
- reset();
+ // If we are already in an existing transition, only update the activity name, but not the
+ // other attributes.
+ final int stackId = launchedActivity != null && launchedActivity.getStack() != null
+ ? launchedActivity.getStack().mStackId
+ : INVALID_STACK_ID;
+ final StackTransitionInfo info = mStackTransitionInfo.get(stackId);
+ if (launchedActivity != null && info != null) {
+ info.launchedActivity = launchedActivity;
return;
}
- MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_COMPONENT_NAME,
- componentName);
- MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_PROCESS_RUNNING,
- processRunning);
- MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS,
- (int) (SystemClock.uptimeMillis() / 1000));
+ final boolean otherStacksLaunching = mStackTransitionInfo.size() > 0 && info == null;
+ if ((resultCode < 0 || launchedActivity == null || !processSwitch
+ || stackId == INVALID_STACK_ID) && !otherStacksLaunching) {
- LogMaker builder = new LogMaker(MetricsEvent.APP_TRANSITION);
- builder.addTaggedData(MetricsEvent.APP_TRANSITION_COMPONENT_NAME, componentName);
- builder.addTaggedData(MetricsEvent.APP_TRANSITION_PROCESS_RUNNING, processRunning ? 1 : 0);
- builder.addTaggedData(MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS,
- SystemClock.uptimeMillis() / 1000);
- MetricsLogger.action(builder);
+ // Failed to launch or it was not a process switch, so we don't care about the timing.
+ reset(true /* abort */);
+ return;
+ } else if (otherStacksLaunching) {
+ // Don't log this stack but continue with the other stacks.
+ return;
+ }
+
+ final StackTransitionInfo newInfo = new StackTransitionInfo();
+ newInfo.launchedActivity = launchedActivity;
+ newInfo.currentTransitionProcessRunning = processRunning;
+ newInfo.startResult = resultCode;
+ mStackTransitionInfo.append(stackId, newInfo);
+ mCurrentTransitionDeviceUptime = (int) (SystemClock.uptimeMillis() / 1000);
}
/**
* Notifies the tracker that all windows of the app have been drawn.
*/
- void notifyWindowsDrawn() {
- if (!isTransitionActive() || mLoggedWindowsDrawn) {
+ void notifyWindowsDrawn(int stackId) {
+ final StackTransitionInfo info = mStackTransitionInfo.get(stackId);
+ if (info == null || info.loggedWindowsDrawn) {
return;
}
- MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS,
- calculateCurrentDelay());
- mLoggedWindowsDrawn = true;
- if (mLoggedTransitionStarting) {
- reset();
+ info.windowsDrawnDelayMs = calculateCurrentDelay();
+ info.loggedWindowsDrawn = true;
+ if (allStacksWindowsDrawn() && mLoggedTransitionStarting) {
+ reset(false /* abort */);
}
}
/**
* Notifies the tracker that the starting window was drawn.
*/
- void notifyStartingWindowDrawn() {
- if (!isTransitionActive() || mLoggedStartingWindowDrawn) {
+ void notifyStartingWindowDrawn(int stackId) {
+ final StackTransitionInfo info = mStackTransitionInfo.get(stackId);
+ if (info == null || info.loggedStartingWindowDrawn) {
return;
}
- mLoggedStartingWindowDrawn = true;
- MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
- calculateCurrentDelay());
+ info.loggedStartingWindowDrawn = true;
+ info.startingWindowDelayMs = calculateCurrentDelay();
}
/**
* Notifies the tracker that the app transition is starting.
*
- * @param reason The reason why we started it. Must be on of
- * ActivityManagerInternal.APP_TRANSITION_* reasons.
+ * @param stackIdReasons A map from stack id to a reason integer, which must be on of
+ * ActivityManagerInternal.APP_TRANSITION_* reasons.
*/
- void notifyTransitionStarting(int reason) {
- if (!isTransitionActive() || mLoggedTransitionStarting) {
+ void notifyTransitionStarting(SparseIntArray stackIdReasons) {
+ if (!isAnyTransitionActive() || mLoggedTransitionStarting) {
return;
}
- MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_REASON, reason);
- MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_DELAY_MS,
- calculateCurrentDelay());
+ mCurrentTransitionDelayMs = calculateCurrentDelay();
mLoggedTransitionStarting = true;
- if (mLoggedWindowsDrawn) {
- reset();
+ for (int index = stackIdReasons.size() - 1; index >= 0; index--) {
+ final int stackId = stackIdReasons.keyAt(index);
+ final StackTransitionInfo info = mStackTransitionInfo.get(stackId);
+ if (info == null) {
+ continue;
+ }
+ info.reason = stackIdReasons.valueAt(index);
+ }
+ if (allStacksWindowsDrawn()) {
+ reset(false /* abort */);
}
}
- private boolean isTransitionActive() {
- return mCurrentTransitionStartTime != INVALID_START_TIME;
+ private boolean allStacksWindowsDrawn() {
+ for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) {
+ if (!mStackTransitionInfo.valueAt(index).loggedWindowsDrawn) {
+ return false;
+ }
+ }
+ return true;
}
- private void reset() {
+ private boolean isAnyTransitionActive() {
+ return mCurrentTransitionStartTime != INVALID_START_TIME
+ && mStackTransitionInfo.size() > 0;
+ }
+
+ private void reset(boolean abort) {
+ if (!abort && isAnyTransitionActive()) {
+ logAppTransitionMultiEvents();
+ }
mCurrentTransitionStartTime = INVALID_START_TIME;
- mLoggedWindowsDrawn = false;
+ mCurrentTransitionDelayMs = -1;
mLoggedTransitionStarting = false;
- mLoggedStartingWindowDrawn = false;
+ mStackTransitionInfo.clear();
}
private int calculateCurrentDelay() {
@@ -244,4 +298,41 @@
// Shouldn't take more than 25 days to launch an app, so int is fine here.
return (int) (System.currentTimeMillis() - mCurrentTransitionStartTime);
}
+
+ private void logAppTransitionMultiEvents() {
+ for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) {
+ final StackTransitionInfo info = mStackTransitionInfo.valueAt(index);
+ final int type = getTransitionType(info);
+ if (type == -1) {
+ return;
+ }
+ final LogMaker builder = new LogMaker(APP_TRANSITION);
+ builder.setPackageName(info.launchedActivity.packageName);
+ builder.addTaggedData(APP_TRANSITION_ACTIVITY_NAME, info.launchedActivity.info.name);
+ builder.setType(type);
+ builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS,
+ mCurrentTransitionDeviceUptime);
+ builder.addTaggedData(APP_TRANSITION_DELAY_MS, mCurrentTransitionDelayMs);
+ builder.setSubtype(info.reason);
+ if (info.startingWindowDelayMs != -1) {
+ builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
+ info.startingWindowDelayMs);
+ }
+ builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs);
+ mMetricsLogger.write(builder);
+ }
+ }
+
+ private int getTransitionType(StackTransitionInfo info) {
+ if (info.currentTransitionProcessRunning) {
+ if (info.startResult == START_SUCCESS) {
+ return TYPE_TRANSITION_WARM_LAUNCH;
+ } else if (info.startResult == START_TASK_TO_FRONT) {
+ return TYPE_TRANSITION_HOT_LAUNCH;
+ }
+ } else if (info.startResult == START_SUCCESS) {
+ return TYPE_TRANSITION_COLD_LAUNCH;
+ }
+ return -1;
+ }
}