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

6 files changed, 106 insertions, 14 deletions

diff --git a/proto/src/metrics_constants.proto b/proto/src/metrics_constants.proto
index f82d435dd360..e79aecd821ba 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 ----
 
     // OPEN: Settings > Network & Internet > Mobile network
diff --git a/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java b/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java
index ceb2ad622b8d..0a7d3fdb5973 100644
--- a/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java
+++ b/services/core/java/com/android/server/am/ActivityManagerDebugConfig.java
@@ -92,6 +92,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 93c0f77235c4..eb022b78d958 100644
--- a/services/core/java/com/android/server/am/ActivityMetricsLogger.java
+++ b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
@@ -13,6 +13,7 @@ import static android.app.WindowConfiguration.WINDOWING_MODE_UNDEFINED;
 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;
@@ -28,16 +29,22 @@ 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 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;
 
@@ -58,6 +65,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 = {
@@ -78,6 +87,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;
@@ -91,10 +117,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() {
@@ -145,6 +172,7 @@ class ActivityMetricsLogger {
      */
     void notifyActivityLaunching() {
         if (!isAnyTransitionActive()) {
+            if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunching");
             mCurrentTransitionStartTime = SystemClock.uptimeMillis();
             mLastTransitionStartTime = mCurrentTransitionStartTime;
         }
@@ -202,6 +230,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
@@ -230,6 +264,8 @@ class ActivityMetricsLogger {
             return;
         }
 
+        if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
+
         final StackTransitionInfo newInfo = new StackTransitionInfo();
         newInfo.launchedActivity = launchedActivity;
         newInfo.currentTransitionProcessRunning = processRunning;
@@ -243,6 +279,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;
@@ -276,6 +314,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--) {
@@ -295,17 +334,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 */);
+                }
             }
         }
     }
@@ -341,6 +400,7 @@ class ActivityMetricsLogger {
     }
 
     private void reset(boolean abort) {
+        if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort);
         if (!abort && isAnyTransitionActive()) {
             logAppTransitionMultiEvents();
         }
@@ -361,7 +421,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 2f0b64918bf9..b45c7b7bc8ba 100644
--- a/services/core/java/com/android/server/am/ActivityRecord.java
+++ b/services/core/java/com/android/server/am/ActivityRecord.java
@@ -1526,7 +1526,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 3506d6b1602b..a4e825117e04 100644
--- a/services/core/java/com/android/server/am/ActivityStackSupervisor.java
+++ b/services/core/java/com/android/server/am/ActivityStackSupervisor.java
@@ -573,7 +573,7 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D
         mService = service;
         mHandler = new ActivityStackSupervisorHandler(looper);
         mRunningTasks = createRunningTasks();
-        mActivityMetricsLogger = new ActivityMetricsLogger(this, mService.mContext);
+        mActivityMetricsLogger = new ActivityMetricsLogger(this, mService.mContext, looper);
         mKeyguardController = new KeyguardController(service, this);
 
         mLaunchingBoundsController = new LaunchingBoundsController();
@@ -4496,9 +4496,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 1b5a1ce33cff..bef325ca038c 100644
--- a/services/core/java/com/android/server/am/TaskRecord.java
+++ b/services/core/java/com/android/server/am/TaskRecord.java
@@ -1036,6 +1036,16 @@ class TaskRecord extends ConfigurationContainer implements TaskWindowContainerLi
         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) {