App transition delay tracking
Add TRON logging for all kinds aspects when we execute an app transition.
Bug: 27295491
Change-Id: Icb0cbdb92d4d5fbfedadd40a017a50eb217058aa
diff --git a/core/java/android/app/ActivityManagerInternal.java b/core/java/android/app/ActivityManagerInternal.java
index 4fa654f..7310d67 100644
--- a/core/java/android/app/ActivityManagerInternal.java
+++ b/core/java/android/app/ActivityManagerInternal.java
@@ -29,6 +29,31 @@
* @hide Only for use within the system server.
*/
public abstract class ActivityManagerInternal {
+
+ /**
+ * Type for {@link #notifyAppTransitionStarting}: The transition was started because we had
+ * the surface saved.
+ */
+ public static final int APP_TRANSITION_SAVED_SURFACE = 0;
+
+ /**
+ * Type for {@link #notifyAppTransitionStarting}: The transition was started because we drew
+ * the starting window.
+ */
+ public static final int APP_TRANSITION_STARTING_WINDOW = 1;
+
+ /**
+ * Type for {@link #notifyAppTransitionStarting}: The transition was started because we all
+ * app windows were drawn
+ */
+ public static final int APP_TRANSITION_WINDOWS_DRAWN = 2;
+
+ /**
+ * Type for {@link #notifyAppTransitionStarting}: The transition was started because of a
+ * timeout.
+ */
+ public static final int APP_TRANSITION_TIMEOUT = 3;
+
// Called by the power manager.
public abstract void onWakefulnessChanged(int wakefulness);
@@ -48,6 +73,7 @@
* with underlying activities.
*/
public static abstract class SleepToken {
+
/**
* Releases the sleep token.
*/
@@ -56,6 +82,7 @@
/**
* Returns home activity for the specified user.
+ *
* @param userId ID of the user or {@link android.os.UserHandle#USER_ALL}
*/
public abstract ComponentName getHomeActivityForUser(int userId);
@@ -72,4 +99,19 @@
public abstract void onLocalVoiceInteractionStarted(IBinder callingActivity,
IVoiceInteractionSession mSession,
IVoiceInteractor mInteractor);
+
+ /**
+ * Callback for window manager to let activity manager know that the starting window has been
+ * drawn
+ */
+ public abstract void notifyStartingWindowDrawn();
+
+ /**
+ * Callback for window manager to let activity manager know that we are finally starting the
+ * app transition;
+ *
+ * @param reason The reason why the app transition started. Must be one of the APP_TRANSITION_*
+ * values.
+ */
+ public abstract void notifyAppTransitionStarting(int reason);
}
diff --git a/proto/src/metrics_constants.proto b/proto/src/metrics_constants.proto
index 568edab..471feef 100644
--- a/proto/src/metrics_constants.proto
+++ b/proto/src/metrics_constants.proto
@@ -450,5 +450,33 @@
// Logged when a user double taps the overview button to launch the previous task
OVERVIEW_LAUNCH_PREVIOUS_TASK = 318;
+
+ // Logged when we execute an app transition. This indicates the total delay from startActivity
+ // until the app transition is starting to animate, in milliseconds.
+ APP_TRANSITION_DELAY_MS = 319;
+
+ // Logged when we execute an app transition. This indicates the reason why the transition
+ // started. Must be one of ActivityManagerInternal.APP_TRANSITION_* reasons.
+ APP_TRANSITION_REASON = 320;
+
+ // Logged when we execute an app transition and we drew a starting window. This indicates the
+ // delay from startActivity until the starting window was drawn.
+ APP_TRANSITION_STARTING_WINDOW_DELAY_MS = 321;
+
+ // Logged when we execute an app transition and all windows of the app got drawn. This indicates
+ // the delay from startActivity until all windows have been drawn.
+ APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS = 322;
+
+ // Logged when we execute an app transition. This indicates the component name of the current
+ // transition.
+ APP_TRANSITION_COMPONENT_NAME = 323;
+
+ // Logged when we execute an app transition. This indicates whether the process was already
+ // running.
+ APP_TRANSITION_PROCESS_RUNNING = 324;
+
+ // Logged when we execute an app transition. This indicates the device uptime in seconds when
+ // the transition was executed.
+ APP_TRANSITION_DEVICE_UPTIME_SECONDS = 325;
}
}
diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index e3a0b5c..e14b837 100644
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -1371,7 +1371,6 @@
int mProcessLimitOverride = -1;
WindowManagerService mWindowManager;
-
final ActivityThread mSystemThread;
private final class AppDeathRecipient implements IBinder.DeathRecipient {
@@ -2487,7 +2486,6 @@
mActivityStarter = new ActivityStarter(this, mStackSupervisor);
mRecentTasks = new RecentTasks(this, mStackSupervisor);
-
mProcessCpuThread = new Thread("CpuTracker") {
@Override
public void run() {
@@ -20757,6 +20755,20 @@
voiceSession, voiceInteractor);
}
}
+
+ @Override
+ public void notifyStartingWindowDrawn() {
+ synchronized (ActivityManagerService.this) {
+ mStackSupervisor.mActivityMetricsLogger.notifyStartingWindowDrawn();
+ }
+ }
+
+ @Override
+ public void notifyAppTransitionStarting(int reason) {
+ synchronized (ActivityManagerService.this) {
+ mStackSupervisor.mActivityMetricsLogger.notifyTransitionStarting(reason);
+ }
+ }
}
private final class SleepTokenImpl extends SleepToken {
diff --git a/services/core/java/com/android/server/am/ActivityMetricsLogger.java b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
index ffb2fc4..0e6dd28 100644
--- a/services/core/java/com/android/server/am/ActivityMetricsLogger.java
+++ b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
@@ -7,11 +7,13 @@
import static android.app.ActivityManager.StackId.PINNED_STACK_ID;
import static com.android.server.am.ActivityStack.STACK_INVISIBLE;
+import android.annotation.Nullable;
import android.app.ActivityManager.StackId;
import android.content.Context;
import android.os.SystemClock;
import com.android.internal.logging.MetricsLogger;
+import com.android.internal.logging.MetricsProto.MetricsEvent;
/**
* Handles logging into Tron.
@@ -24,6 +26,8 @@
private static final int WINDOW_STATE_FREEFORM = 2;
private static final int WINDOW_STATE_INVALID = -1;
+ private static final long INVALID_START_TIME = -1;
+
// Preallocated strings we are sending to tron, so we don't have to allocate a new one every
// time we log.
private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = {
@@ -34,6 +38,11 @@
private final ActivityStackSupervisor mSupervisor;
private final Context mContext;
+ private long mCurrentTransitionStartTime = INVALID_START_TIME;
+ private boolean mLoggedWindowsDrawn;
+ private boolean mLoggedStartingWindowDrawn;
+ private boolean mLoggedTransitionStarting;
+
ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context) {
mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
mSupervisor = supervisor;
@@ -73,4 +82,101 @@
throw new IllegalStateException("Unknown stack=" + stack);
}
}
+
+ /**
+ * Notifies the tracker at the earliest possible point when we are starting to launch an
+ * activity.
+ */
+ void notifyActivityLaunching() {
+ mCurrentTransitionStartTime = System.currentTimeMillis();
+ }
+
+ /**
+ * Notifies the tracker the the activity is actually launching.
+ *
+ * @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 processRunning whether the process that will contains the activity is already running
+ */
+ void notifyActivityLaunched(int resultCode, @Nullable String componentName,
+ boolean processRunning) {
+
+ if (resultCode < 0 || componentName == null) {
+
+ // Failed to launch, don't track anything.
+ reset();
+ 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));
+ }
+
+ /**
+ * Notifies the tracker that all windows of the app have been drawn.
+ */
+ void notifyWindowsDrawn() {
+ if (!isTransitionActive() || mLoggedWindowsDrawn) {
+ return;
+ }
+ MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS,
+ calculateCurrentDelay());
+ mLoggedWindowsDrawn = true;
+ if (mLoggedTransitionStarting) {
+ reset();
+ }
+ }
+
+ /**
+ * Notifies the tracker that the starting window was drawn.
+ */
+ void notifyStartingWindowDrawn() {
+ if (!isTransitionActive() || mLoggedStartingWindowDrawn) {
+ return;
+ }
+ mLoggedStartingWindowDrawn = true;
+ MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
+ 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.
+ */
+ void notifyTransitionStarting(int reason) {
+ if (!isTransitionActive() || mLoggedTransitionStarting) {
+ return;
+ }
+ MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_REASON, reason);
+ MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_DELAY_MS,
+ calculateCurrentDelay());
+ mLoggedTransitionStarting = true;
+ if (mLoggedWindowsDrawn) {
+ reset();
+ }
+ }
+
+ private boolean isTransitionActive() {
+ return mCurrentTransitionStartTime != INVALID_START_TIME;
+ }
+
+ private void reset() {
+ mCurrentTransitionStartTime = INVALID_START_TIME;
+ mLoggedWindowsDrawn = false;
+ mLoggedTransitionStarting = false;
+ mLoggedStartingWindowDrawn = false;
+ }
+
+ private int calculateCurrentDelay() {
+
+ // Shouldn't take more than 25 days to launch an app, so int is fine here.
+ return (int) (System.currentTimeMillis() - mCurrentTransitionStartTime);
+ }
}
diff --git a/services/core/java/com/android/server/am/ActivityRecord.java b/services/core/java/com/android/server/am/ActivityRecord.java
index 32ca5bf..e2ea1f1 100755
--- a/services/core/java/com/android/server/am/ActivityRecord.java
+++ b/services/core/java/com/android/server/am/ActivityRecord.java
@@ -1167,6 +1167,7 @@
}
void windowsDrawnLocked() {
+ mStackSupervisor.mActivityMetricsLogger.notifyWindowsDrawn();
if (displayStartTime != 0) {
reportLaunchTimeLocked(SystemClock.uptimeMillis());
}
diff --git a/services/core/java/com/android/server/am/ActivityStackSupervisor.java b/services/core/java/com/android/server/am/ActivityStackSupervisor.java
index af5f6b3..20f8285 100644
--- a/services/core/java/com/android/server/am/ActivityStackSupervisor.java
+++ b/services/core/java/com/android/server/am/ActivityStackSupervisor.java
@@ -406,7 +406,7 @@
// Whether tasks have moved and we need to rank the tasks before next OOM scoring
private boolean mTaskLayersChanged = true;
- private final ActivityMetricsLogger mActivityMetricsLogger;
+ final ActivityMetricsLogger mActivityMetricsLogger;
private final ResizeDockedStackTimeout mResizeDockedStackTimeout;
diff --git a/services/core/java/com/android/server/am/ActivityStarter.java b/services/core/java/com/android/server/am/ActivityStarter.java
index 9c7eb95..0181640 100644
--- a/services/core/java/com/android/server/am/ActivityStarter.java
+++ b/services/core/java/com/android/server/am/ActivityStarter.java
@@ -593,6 +593,7 @@
if (intent != null && intent.hasFileDescriptors()) {
throw new IllegalArgumentException("File descriptors passed in Intent");
}
+ mSupervisor.mActivityMetricsLogger.notifyActivityLaunching();
boolean componentSpecified = intent.getComponent() != null;
// Save a copy in case ephemeral needs it
@@ -722,11 +723,13 @@
}
}
+ final ActivityRecord[] outRecord = new ActivityRecord[1];
int res = startActivityLocked(caller, intent, ephemeralIntent, resolvedType,
aInfo, rInfo, voiceSession, voiceInteractor,
resultTo, resultWho, requestCode, callingPid,
callingUid, callingPackage, realCallingPid, realCallingUid, startFlags,
- options, ignoreTargetSecurity, componentSpecified, null, container, inTask);
+ options, ignoreTargetSecurity, componentSpecified, outRecord, container,
+ inTask);
Binder.restoreCallingIdentity(origId);
@@ -773,6 +776,13 @@
}
}
+ final String componentName = outRecord[0] != null ? outRecord[0].shortComponentName
+ : null;
+ final boolean processRunning = outRecord[0] != null &&
+ mService.mProcessNames.get(outRecord[0].processName,
+ outRecord[0].appInfo.uid) != null;
+ mSupervisor.mActivityMetricsLogger.notifyActivityLaunched(res, componentName,
+ processRunning);
return res;
}
}
diff --git a/services/core/java/com/android/server/wm/WindowManagerService.java b/services/core/java/com/android/server/wm/WindowManagerService.java
index daeecfc..72621c2 100644
--- a/services/core/java/com/android/server/wm/WindowManagerService.java
+++ b/services/core/java/com/android/server/wm/WindowManagerService.java
@@ -20,6 +20,7 @@
import android.animation.ValueAnimator;
import android.annotation.NonNull;
import android.annotation.Nullable;
+import android.app.ActivityManagerInternal;
import android.app.ActivityManagerNative;
import android.app.AppOpsManager;
import android.app.IActivityManager;
@@ -362,6 +363,7 @@
final WindowManagerPolicy mPolicy = new PhoneWindowManager();
final IActivityManager mActivityManager;
+ final ActivityManagerInternal mAmInternal;
final AppOpsManager mAppOps;
@@ -902,6 +904,7 @@
mAppTransition.registerListenerLocked(mActivityManagerAppTransitionNotifier);
mActivityManager = ActivityManagerNative.getDefault();
+ mAmInternal = LocalServices.getService(ActivityManagerInternal.class);
mAppOps = (AppOpsManager)context.getSystemService(Context.APP_OPS_SERVICE);
AppOpsManager.OnOpChangedInternalListener opListener =
new AppOpsManager.OnOpChangedInternalListener() {
@@ -7606,6 +7609,9 @@
public static final int WINDOW_REPLACEMENT_TIMEOUT = 46;
+ public static final int NOTIFY_APP_TRANSITION_STARTING = 47;
+ public static final int NOTIFY_STARTING_WINDOW_DRAWN = 48;
+
/**
* Used to denote that an integer field in a message will not be used.
*/
@@ -8203,6 +8209,13 @@
token.clearTimedoutReplacesLocked();
}
}
+ case NOTIFY_APP_TRANSITION_STARTING: {
+ mAmInternal.notifyAppTransitionStarting(msg.arg1);
+ }
+ break;
+ case NOTIFY_STARTING_WINDOW_DRAWN: {
+ mAmInternal.notifyStartingWindowDrawn();
+ }
break;
}
if (DEBUG_WINDOW_TRACE) {
diff --git a/services/core/java/com/android/server/wm/WindowSurfacePlacer.java b/services/core/java/com/android/server/wm/WindowSurfacePlacer.java
index f705df8..856d30a 100644
--- a/services/core/java/com/android/server/wm/WindowSurfacePlacer.java
+++ b/services/core/java/com/android/server/wm/WindowSurfacePlacer.java
@@ -1,5 +1,9 @@
package com.android.server.wm;
+import static android.app.ActivityManagerInternal.APP_TRANSITION_SAVED_SURFACE;
+import static android.app.ActivityManagerInternal.APP_TRANSITION_STARTING_WINDOW;
+import static android.app.ActivityManagerInternal.APP_TRANSITION_TIMEOUT;
+import static android.app.ActivityManagerInternal.APP_TRANSITION_WINDOWS_DRAWN;
import static android.view.WindowManager.LayoutParams.FLAG_KEEP_SCREEN_ON;
import static android.view.WindowManager.LayoutParams.FLAG_SHOW_WALLPAPER;
import static android.view.WindowManager.LayoutParams.PRIVATE_FLAG_KEYGUARD;
@@ -42,6 +46,7 @@
import android.graphics.PixelFormat;
import android.graphics.Rect;
import android.os.Debug;
+import android.os.Message;
import android.os.PowerManager;
import android.os.RemoteException;
import android.os.SystemClock;
@@ -782,6 +787,7 @@
}
}
} else if (w.isDrawnLw()) {
+ mService.mH.sendEmptyMessage(NOTIFY_STARTING_WINDOW_DRAWN);
atoken.startingDisplayed = true;
}
}
@@ -1262,6 +1268,7 @@
"Checking " + appsCount + " opening apps (frozen="
+ mService.mDisplayFrozen + " timeout="
+ mService.mAppTransition.isTimeout() + ")...");
+ int reason = APP_TRANSITION_TIMEOUT;
if (!mService.mAppTransition.isTimeout()) {
for (int i = 0; i < appsCount; i++) {
AppWindowToken wtoken = mService.mOpeningApps.valueAt(i);
@@ -1271,11 +1278,18 @@
+ wtoken.startingDisplayed + " startingMoved="
+ wtoken.startingMoved);
+ final boolean drawnBeforeRestoring = wtoken.allDrawn;
wtoken.restoreSavedSurfaces();
if (!wtoken.allDrawn && !wtoken.startingDisplayed && !wtoken.startingMoved) {
return false;
}
+ if (wtoken.allDrawn) {
+ reason = drawnBeforeRestoring ? APP_TRANSITION_WINDOWS_DRAWN
+ : APP_TRANSITION_SAVED_SURFACE;
+ } else {
+ reason = APP_TRANSITION_STARTING_WINDOW;
+ }
}
// We also need to wait for the specs to be fetched, if needed.
@@ -1285,9 +1299,15 @@
}
// If the wallpaper is visible, we need to check it's ready too.
- return !mWallpaperControllerLocked.isWallpaperVisible() ||
+ boolean wallpaperReady = !mWallpaperControllerLocked.isWallpaperVisible() ||
mWallpaperControllerLocked.wallpaperTransitionReady();
+ if (wallpaperReady) {
+ mService.mH.obtainMessage(NOTIFY_APP_TRANSITION_STARTING, reason, 0).sendToTarget();
+ return true;
+ }
+ return false;
}
+ mService.mH.obtainMessage(NOTIFY_APP_TRANSITION_STARTING, reason, 0).sendToTarget();
return true;
}