Fix issues with TRON app transition logging
There was a case where a app launch started activity A. A step in
the UI finished A and started B in the same task. Next time A was
started it immediately finished itself, putting B at the top of
the task. Now, this launch was considered aborted because A was
finished during launching, making it invisible.
We fix this by modifying the logic to only abort the launch if the
full task is not visible anymore after an activity has been set to
invisible.
There is another case where an app launches A, finishes A, and then
launches B. In this case the home gets visible in between so we
don't consider this an app launch anymore, and correctly cancel
the logging. However it's still useful to know that this is
happening to expose it to the developer, so we log any cancel
events, no matter where they are coming from.
Test: Launch Snapchat, click Sign Up, click home, relaunch
Snapchat from home
Test: Open slow app and press home quickly to test cancel.
Change-Id: I211636c97fd6785adb3fe443a8ffa1ae766946a4
Merged-In: I211636c97fd6785adb3fe443a8ffa1ae766946a4
Fixes: 67094673
diff --git a/proto/src/metrics_constants.proto b/proto/src/metrics_constants.proto
index 81a23f0..cbd2f75 100644
--- a/proto/src/metrics_constants.proto
+++ b/proto/src/metrics_constants.proto
@@ -4567,6 +4567,10 @@
// OS: O MR
COLOR_MODE_SETTINGS = 1143;
+ // Enclosing category for group of APP_TRANSITION_FOO events,
+ // logged when we cancel an app transition.
+ APP_TRANSITION_CANCELLED = 1144;
+
// ---- End O-MR1 Constants, all O-MR1 constants go above this line ----
// Add new aosp constants above this line.
diff --git a/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java b/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java
index 3a9bf12..276f0ef 100644
--- a/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java
+++ b/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java
@@ -94,6 +94,7 @@
static final boolean DEBUG_USAGE_STATS = DEBUG_ALL || false;
static final boolean DEBUG_PERMISSIONS_REVIEW = DEBUG_ALL || false;
static final boolean DEBUG_WHITELISTS = DEBUG_ALL || false;
+ static final boolean DEBUG_METRICS = DEBUG_ALL || false;
static final String POSTFIX_ADD_REMOVE = (APPEND_CATEGORY_NAME) ? "_AddRemove" : "";
static final String POSTFIX_APP = (APPEND_CATEGORY_NAME) ? "_App" : "";
diff --git a/services/core/java/com/android/server/am/ActivityMetricsLogger.java b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
index f396e9e..a803874 100644
--- a/services/core/java/com/android/server/am/ActivityMetricsLogger.java
+++ b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
@@ -12,6 +12,7 @@
import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION;
import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_BIND_APPLICATION_DELAY_MS;
import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CALLING_PACKAGE_NAME;
+import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CANCELLED;
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_IS_EPHEMERAL;
@@ -27,6 +28,7 @@
import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE;
import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE;
import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH;
+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.ActivityStack.STACK_INVISIBLE;
@@ -34,12 +36,16 @@
import android.app.ActivityManager.StackId;
import android.content.Context;
import android.metrics.LogMaker;
+import android.os.Handler;
+import android.os.Looper;
+import android.os.Message;
import android.os.SystemClock;
import android.util.Slog;
import android.util.SparseArray;
import android.util.SparseIntArray;
import com.android.internal.logging.MetricsLogger;
+import com.android.internal.os.SomeArgs;
import java.util.ArrayList;
@@ -60,6 +66,8 @@
private static final long INVALID_START_TIME = -1;
+ private static final int MSG_CHECK_VISIBILITY = 0;
+
// 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 = {
@@ -80,6 +88,23 @@
private final SparseArray<StackTransitionInfo> mStackTransitionInfo = new SparseArray<>();
private final SparseArray<StackTransitionInfo> mLastStackTransitionInfo = new SparseArray<>();
+ private final H mHandler;
+ private final class H extends Handler {
+
+ public H(Looper looper) {
+ super(looper);
+ }
+
+ @Override
+ public void handleMessage(Message msg) {
+ switch (msg.what) {
+ case MSG_CHECK_VISIBILITY:
+ final SomeArgs args = (SomeArgs) msg.obj;
+ checkVisibility((TaskRecord) args.arg1, (ActivityRecord) args.arg2);
+ break;
+ }
+ }
+ };
private final class StackTransitionInfo {
private ActivityRecord launchedActivity;
@@ -93,10 +118,11 @@
private boolean loggedStartingWindowDrawn;
}
- ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context) {
+ ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context, Looper looper) {
mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
mSupervisor = supervisor;
mContext = context;
+ mHandler = new H(looper);
}
void logWindowState() {
@@ -142,6 +168,7 @@
*/
void notifyActivityLaunching() {
if (!isAnyTransitionActive()) {
+ if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunching");
mCurrentTransitionStartTime = SystemClock.uptimeMillis();
mLastTransitionStartTime = mCurrentTransitionStartTime;
}
@@ -199,6 +226,12 @@
private void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity,
boolean processRunning, boolean processSwitch) {
+ if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched"
+ + " resultCode=" + resultCode
+ + " launchedActivity=" + launchedActivity
+ + " processRunning=" + processRunning
+ + " processSwitch=" + processSwitch);
+
// 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
@@ -227,6 +260,8 @@
return;
}
+ if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
+
final StackTransitionInfo newInfo = new StackTransitionInfo();
newInfo.launchedActivity = launchedActivity;
newInfo.currentTransitionProcessRunning = processRunning;
@@ -240,6 +275,8 @@
* Notifies the tracker that all windows of the app have been drawn.
*/
void notifyWindowsDrawn(int stackId, long timestamp) {
+ if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn stackId=" + stackId);
+
final StackTransitionInfo info = mStackTransitionInfo.get(stackId);
if (info == null || info.loggedWindowsDrawn) {
return;
@@ -273,6 +310,7 @@
if (!isAnyTransitionActive() || mLoggedTransitionStarting) {
return;
}
+ if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");
mCurrentTransitionDelayMs = calculateDelay(timestamp);
mLoggedTransitionStarting = true;
for (int index = stackIdReasons.size() - 1; index >= 0; index--) {
@@ -292,17 +330,37 @@
* Notifies the tracker that the visibility of an app is changing.
*
* @param activityRecord the app that is changing its visibility
- * @param visible whether it's going to be visible or not
*/
- void notifyVisibilityChanged(ActivityRecord activityRecord, boolean visible) {
+ void notifyVisibilityChanged(ActivityRecord activityRecord) {
final StackTransitionInfo info = mStackTransitionInfo.get(activityRecord.getStackId());
+ if (info == null) {
+ return;
+ }
+ if (info.launchedActivity != activityRecord) {
+ return;
+ }
+ final TaskRecord t = activityRecord.getTask();
+ final SomeArgs args = SomeArgs.obtain();
+ args.arg1 = t;
+ args.arg2 = activityRecord;
+ mHandler.obtainMessage(MSG_CHECK_VISIBILITY, args).sendToTarget();
+ }
- // If we have an active transition that's waiting on a certain activity that will be
- // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary.
- if (info != null && !visible && info.launchedActivity == activityRecord) {
- mStackTransitionInfo.remove(activityRecord.getStackId());
- if (mStackTransitionInfo.size() == 0) {
- reset(true /* abort */);
+ private void checkVisibility(TaskRecord t, ActivityRecord r) {
+ synchronized (mSupervisor.mService) {
+
+ final StackTransitionInfo info = mStackTransitionInfo.get(r.getStackId());
+
+ // If we have an active transition that's waiting on a certain activity that will be
+ // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary.
+ if (info != null && !t.isVisible()) {
+ if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible"
+ + " activity=" + r);
+ logAppTransitionCancel(info);
+ mStackTransitionInfo.remove(r.getStackId());
+ if (mStackTransitionInfo.size() == 0) {
+ reset(true /* abort */);
+ }
}
}
}
@@ -338,6 +396,7 @@
}
private void reset(boolean abort) {
+ if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort);
if (!abort && isAnyTransitionActive()) {
logAppTransitionMultiEvents();
}
@@ -358,7 +417,20 @@
return (int) (timestamp - mCurrentTransitionStartTime);
}
+ private void logAppTransitionCancel(StackTransitionInfo info) {
+ final int type = getTransitionType(info);
+ if (type == -1) {
+ return;
+ }
+ final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED);
+ builder.setPackageName(info.launchedActivity.packageName);
+ builder.setType(type);
+ builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivity.info.name);
+ mMetricsLogger.write(builder);
+ }
+
private void logAppTransitionMultiEvents() {
+ if (DEBUG_METRICS) Slog.i(TAG, "logging transition events");
for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) {
final StackTransitionInfo info = mStackTransitionInfo.valueAt(index);
final int type = getTransitionType(info);
diff --git a/services/core/java/com/android/server/am/ActivityRecord.java b/services/core/java/com/android/server/am/ActivityRecord.java
index 4d98f19..fd44768 100644
--- a/services/core/java/com/android/server/am/ActivityRecord.java
+++ b/services/core/java/com/android/server/am/ActivityRecord.java
@@ -1578,7 +1578,7 @@
void setVisibility(boolean visible) {
mWindowContainerController.setVisibility(visible, mDeferHidingClient);
- mStackSupervisor.mActivityMetricsLogger.notifyVisibilityChanged(this, visible);
+ mStackSupervisor.mActivityMetricsLogger.notifyVisibilityChanged(this);
}
// TODO: Look into merging with #setVisibility()
diff --git a/services/core/java/com/android/server/am/ActivityStackSupervisor.java b/services/core/java/com/android/server/am/ActivityStackSupervisor.java
index b2dc3e6..795d7dd 100644
--- a/services/core/java/com/android/server/am/ActivityStackSupervisor.java
+++ b/services/core/java/com/android/server/am/ActivityStackSupervisor.java
@@ -606,7 +606,7 @@
public ActivityStackSupervisor(ActivityManagerService service, Looper looper) {
mService = service;
mHandler = new ActivityStackSupervisorHandler(looper);
- mActivityMetricsLogger = new ActivityMetricsLogger(this, mService.mContext);
+ mActivityMetricsLogger = new ActivityMetricsLogger(this, mService.mContext, looper);
mKeyguardController = new KeyguardController(service, this);
}
@@ -4836,9 +4836,13 @@
mService.mActivityStarter.sendPowerHintForLaunchStartIfNeeded(true /* forceSend */,
targetActivity);
mActivityMetricsLogger.notifyActivityLaunching();
- mService.moveTaskToFrontLocked(task.taskId, 0, bOptions, true /* fromRecents */);
- mActivityMetricsLogger.notifyActivityLaunched(ActivityManager.START_TASK_TO_FRONT,
- targetActivity);
+ try {
+ mService.moveTaskToFrontLocked(task.taskId, 0, bOptions,
+ true /* fromRecents */);
+ } finally {
+ mActivityMetricsLogger.notifyActivityLaunched(START_TASK_TO_FRONT,
+ targetActivity);
+ }
// If we are launching the task in the docked stack, put it into resizing mode so
// the window renders full-screen with the background filling the void. Also only
diff --git a/services/core/java/com/android/server/am/TaskRecord.java b/services/core/java/com/android/server/am/TaskRecord.java
index eadc8a6..f833109 100644
--- a/services/core/java/com/android/server/am/TaskRecord.java
+++ b/services/core/java/com/android/server/am/TaskRecord.java
@@ -1151,6 +1151,16 @@
return null;
}
+ boolean isVisible() {
+ for (int i = mActivities.size() - 1; i >= 0; --i) {
+ final ActivityRecord r = mActivities.get(i);
+ if (r.visible) {
+ return true;
+ }
+ }
+ return false;
+ }
+
void getAllRunningVisibleActivitiesLocked(ArrayList<ActivityRecord> outActivities) {
if (mStack != null) {
for (int activityNdx = mActivities.size() - 1; activityNdx >= 0; --activityNdx) {