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
(cherry picked from commit a9d408214cd73709ff25f235cf6817eaaf7a23d6)

6 files changed, 105 insertions, 14 deletions

diff --git a/proto/src/metrics_constants.proto b/proto/src/metrics_constants.proto
index 81a23f0afa3f..cbd2f75e46d5 100644
--- a/proto/src/metrics_constants.proto
+++ b/proto/src/metrics_constants.proto
@@ -4567,6 +4567,10 @@ message MetricsEvent {
     // 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 3a9bf1258d12..276f0efb570e 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 @@ class ActivityManagerDebugConfig {
     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 f396e9ef44a5..a8038747aa2a 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 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_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_T
 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 static com.android.server.am.ActivityStack.STACK_INVISIBLE;
 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 @@ class ActivityMetricsLogger {
 
     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 @@ class ActivityMetricsLogger {
 
     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 @@ class ActivityMetricsLogger {
         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 @@ class ActivityMetricsLogger {
      */
     void notifyActivityLaunching() {
         if (!isAnyTransitionActive()) {
+            if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunching");
             mCurrentTransitionStartTime = SystemClock.uptimeMillis();
             mLastTransitionStartTime = mCurrentTransitionStartTime;
         }
@@ -199,6 +226,12 @@ class ActivityMetricsLogger {
     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 @@ class ActivityMetricsLogger {
             return;
         }
 
+        if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
+
         final StackTransitionInfo newInfo = new StackTransitionInfo();
         newInfo.launchedActivity = launchedActivity;
         newInfo.currentTransitionProcessRunning = processRunning;
@@ -240,6 +275,8 @@ class ActivityMetricsLogger {
      * 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 @@ class ActivityMetricsLogger {
         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 @@ class ActivityMetricsLogger {
      * 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 @@ class ActivityMetricsLogger {
     }
 
     private void reset(boolean abort) {
+        if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort);
         if (!abort && isAnyTransitionActive()) {
             logAppTransitionMultiEvents();
         }
@@ -358,7 +417,20 @@ class ActivityMetricsLogger {
         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 be281df3a445..ee23d6328f10 100644
--- a/services/core/java/com/android/server/am/ActivityRecord.java
+++ b/services/core/java/com/android/server/am/ActivityRecord.java
@@ -1585,7 +1585,7 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo
 
     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 b2dc3e6a8b69..795d7dde78a0 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 class ActivityStackSupervisor extends ConfigurationContainer implements D
     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 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D
                 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 eadc8a6eadba..f83310954c3d 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 @@ final class TaskRecord extends ConfigurationContainer implements TaskWindowConta
         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) {