Enable starting window logging

Also extend it to make sure we catch the bug!

Test: Open a couple of cold/hot apps, make sure logs look accurate
Bug: 37888853
Change-Id: Ied394969748d4d2d40359af15e0b491a2dc2b078

6 files changed, 44 insertions, 11 deletions

diff --git a/services/core/java/com/android/server/wm/AppWindowContainerController.java b/services/core/java/com/android/server/wm/AppWindowContainerController.java
index 5545e2b770ee..c982f081d624 100644
--- a/services/core/java/com/android/server/wm/AppWindowContainerController.java
+++ b/services/core/java/com/android/server/wm/AppWindowContainerController.java
@@ -19,6 +19,7 @@ package com.android.server.wm;
 import static android.content.pm.ActivityInfo.SCREEN_ORIENTATION_UNSPECIFIED;
 import static android.view.WindowManager.LayoutParams.FLAG_SHOW_WALLPAPER;
 import static com.android.server.wm.AppTransition.TRANSIT_UNSET;
+import static com.android.server.wm.WindowManagerDebugConfig.DEBUG;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_ADD_REMOVE;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_APP_TRANSITIONS;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_ORIENTATION;
@@ -98,18 +99,27 @@ public class AppWindowContainerController
     private final Runnable mRemoveStartingWindow = () -> {
         StartingSurface surface = null;
         synchronized (mWindowMap) {
-            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Remove starting " + mContainer
-                    + ": startingWindow=" + mContainer.startingWindow
-                    + " startingView=" + mContainer.startingSurface);
             if (mContainer == null) {
+                if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "mContainer was null while trying to"
+                        + " remove starting window");
                 return;
             }
+            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Remove starting " + mContainer
+                    + ": startingWindow=" + mContainer.startingWindow
+                    + " startingView=" + mContainer.startingSurface);
             if (mContainer.startingWindow != null) {
                 surface = mContainer.startingSurface;
                 mContainer.startingData = null;
                 mContainer.startingSurface = null;
                 mContainer.startingWindow = null;
                 mContainer.startingDisplayed = false;
+                if (surface == null && DEBUG_STARTING_WINDOW) {
+                    Slog.v(TAG_WM, "startingWindow was set but startingSurface==null, couldn't "
+                            + "remove");
+                }
+            } else if (DEBUG_STARTING_WINDOW) {
+                Slog.v(TAG_WM, "Tried to remove starting window but startingWindow was null:"
+                        + mContainer);
             }
         }
         if (surface != null) {
@@ -127,6 +137,8 @@ public class AppWindowContainerController
 
         synchronized (mWindowMap) {
             if (mContainer == null) {
+                if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "mContainer was null while trying to"
+                        + " add starting window");
                 return;
             }
             startingData = mContainer.startingData;
@@ -135,6 +147,8 @@ public class AppWindowContainerController
 
         if (startingData == null) {
             // Animation has been canceled... do nothing.
+            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "startingData was nulled out before handling"
+                    + " mAddStartingWindow: " + mContainer);
             return;
         }
 
@@ -174,6 +188,8 @@ public class AppWindowContainerController
             if (abort) {
                 surface.remove();
             }
+        } else if (DEBUG_STARTING_WINDOW) {
+            Slog.v(TAG_WM, "Surface returned was null: " + mContainer);
         }
     };
 
@@ -450,7 +466,9 @@ public class AppWindowContainerController
             boolean allowTaskSnapshot, boolean activityCreated) {
         synchronized(mWindowMap) {
             if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "setAppStartingWindow: token=" + mToken
-                    + " pkg=" + pkg + " transferFrom=" + transferFrom);
+                    + " pkg=" + pkg + " transferFrom=" + transferFrom + " newTask=" + newTask
+                    + " taskSwitch=" + taskSwitch + " processRunning=" + processRunning
+                    + " allowTaskSnapshot=" + allowTaskSnapshot);
 
             if (mContainer == null) {
                 Slog.w(TAG_WM, "Attempted to set icon of non-existing app token: " + mToken);
@@ -536,7 +554,7 @@ public class AppWindowContainerController
                 return false;
             }
 
-            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Creating StartingData");
+            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Creating SplashScreenStartingData");
             mContainer.startingData = new SplashScreenStartingData(mService, pkg, theme,
                     compatInfo, nonLocalizedLabel, labelRes, icon, logo, windowFlags,
                     mContainer.getMergedOverrideConfiguration());
@@ -574,6 +592,7 @@ public class AppWindowContainerController
             return false;
         }
 
+        if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Creating SnapshotStartingData");
         mContainer.startingData = new SnapshotStartingData(mService, snapshot);
         scheduleAddStartingWindow();
         return true;
@@ -583,6 +602,8 @@ public class AppWindowContainerController
         synchronized (mWindowMap) {
             if (mHandler.hasCallbacks(mRemoveStartingWindow)) {
                 // Already scheduled.
+                if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Trying to remove starting window but "
+                        + "already scheduled");
                 return;
             }
 
@@ -597,8 +618,7 @@ public class AppWindowContainerController
                 return;
             }
 
-            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, Debug.getCallers(1)
-                    + ": Schedule remove starting " + mContainer
+            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Schedule remove starting " + mContainer
                     + " startingWindow=" + mContainer.startingWindow);
             mHandler.post(mRemoveStartingWindow);
         }
diff --git a/services/core/java/com/android/server/wm/AppWindowToken.java b/services/core/java/com/android/server/wm/AppWindowToken.java
index 52eb2fb01d79..17db253adb16 100644
--- a/services/core/java/com/android/server/wm/AppWindowToken.java
+++ b/services/core/java/com/android/server/wm/AppWindowToken.java
@@ -38,6 +38,7 @@ import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_FOCUS_LIGHT;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_LAYOUT_REPEATS;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_ORIENTATION;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_STARTING_WINDOW;
+import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_STARTING_WINDOW_VERBOSE;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_TOKEN_MOVEMENT;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_VISIBILITY;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_WINDOW_MOVEMENT;
@@ -806,6 +807,8 @@ class AppWindowToken extends WindowToken implements WindowManagerService.AppFree
         } else if (mChildren.size() == 1 && startingSurface != null && !isRelaunching()) {
             // If this is the last window except for a starting transition window,
             // we need to get rid of the starting transition.
+            if (DEBUG_STARTING_WINDOW) Slog.v(TAG_WM, "Last window, removing starting window "
+                    + win);
             if (getController() != null) {
                 getController().removeStartingWindow();
             }
@@ -1372,7 +1375,7 @@ class AppWindowToken extends WindowToken implements WindowManagerService.AppFree
      *         windows in this app token where not considered drawn as of the last pass.
      */
     boolean updateDrawnWindowStates(WindowState w) {
-        if (DEBUG_STARTING_WINDOW && w == startingWindow) {
+        if (DEBUG_STARTING_WINDOW_VERBOSE && w == startingWindow) {
             Slog.d(TAG, "updateWindows: starting " + w + " isOnScreen=" + w.isOnScreen()
                     + " allDrawn=" + allDrawn + " freezingScreen=" + mAppAnimator.freezingScreen);
         }
diff --git a/services/core/java/com/android/server/wm/TaskSnapshotSurface.java b/services/core/java/com/android/server/wm/TaskSnapshotSurface.java
index 5e71bcbe557e..3a116bb10d98 100644
--- a/services/core/java/com/android/server/wm/TaskSnapshotSurface.java
+++ b/services/core/java/com/android/server/wm/TaskSnapshotSurface.java
@@ -39,6 +39,7 @@ import static com.android.internal.policy.DecorView.STATUS_BAR_COLOR_VIEW_ATTRIB
 import static com.android.internal.policy.DecorView.getColorViewLeftInset;
 import static com.android.internal.policy.DecorView.getColorViewTopInset;
 import static com.android.internal.policy.DecorView.getNavigationBarRect;
+import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_STARTING_WINDOW;
 import static com.android.server.wm.WindowManagerDebugConfig.TAG_WITH_CLASS_NAME;
 import static com.android.server.wm.WindowManagerDebugConfig.TAG_WM;
 
@@ -232,10 +233,14 @@ class TaskSnapshotSurface implements StartingSurface {
             final long now = SystemClock.uptimeMillis();
             if (mSizeMismatch && now - mShownTime < SIZE_MISMATCH_MINIMUM_TIME_MS) {
                 mHandler.postAtTime(this::remove, mShownTime + SIZE_MISMATCH_MINIMUM_TIME_MS);
+                if (DEBUG_STARTING_WINDOW) {
+                    Slog.v(TAG, "Defer removing snapshot surface in "  + (now - mShownTime) + "ms");
+                }
                 return;
             }
         }
         try {
+            if (DEBUG_STARTING_WINDOW) Slog.v(TAG, "Removing snapshot surface");
             mSession.remove(mWindow);
         } catch (RemoteException e) {
             // Local call.
@@ -254,6 +259,8 @@ class TaskSnapshotSurface implements StartingSurface {
 
     private void drawSnapshot() {
         final GraphicBuffer buffer = mSnapshot.getSnapshot();
+        if (DEBUG_STARTING_WINDOW) Slog.v(TAG, "Drawing snapshot surface sizeMismatch="
+                + mSizeMismatch);
         if (mSizeMismatch) {
             // The dimensions of the buffer and the window don't match, so attaching the buffer
             // will fail. Better create a child window with the exact dimensions and fill the parent
diff --git a/services/core/java/com/android/server/wm/WindowManagerDebugConfig.java b/services/core/java/com/android/server/wm/WindowManagerDebugConfig.java
index 1b61fca5e25c..8279b5167766 100644
--- a/services/core/java/com/android/server/wm/WindowManagerDebugConfig.java
+++ b/services/core/java/com/android/server/wm/WindowManagerDebugConfig.java
@@ -51,7 +51,8 @@ public class WindowManagerDebugConfig {
     static final boolean DEBUG_APP_ORIENTATION = false;
     static final boolean DEBUG_CONFIGURATION = false;
     static final boolean DEBUG_APP_TRANSITIONS = false;
-    static final boolean DEBUG_STARTING_WINDOW = false;
+    static final boolean DEBUG_STARTING_WINDOW_VERBOSE = false;
+    static final boolean DEBUG_STARTING_WINDOW = DEBUG_STARTING_WINDOW_VERBOSE || true;
     static final boolean DEBUG_WALLPAPER = false;
     static final boolean DEBUG_WALLPAPER_LIGHT = false || DEBUG_WALLPAPER;
     static final boolean DEBUG_DRAG = false;
diff --git a/services/core/java/com/android/server/wm/WindowState.java b/services/core/java/com/android/server/wm/WindowState.java
index a69bc58e8d20..83e0551487d1 100644
--- a/services/core/java/com/android/server/wm/WindowState.java
+++ b/services/core/java/com/android/server/wm/WindowState.java
@@ -80,6 +80,7 @@ import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_ORIENTATION;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_POWER;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_RESIZE;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_STARTING_WINDOW;
+import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_STARTING_WINDOW_VERBOSE;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_SURFACE_TRACE;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_VISIBILITY;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_WALLPAPER_LIGHT;
@@ -3785,7 +3786,7 @@ class WindowState extends WindowContainer<WindowState> implements WindowManagerP
 
     private void logPerformShow(String prefix) {
         if (DEBUG_VISIBILITY
-                || (DEBUG_STARTING_WINDOW && mAttrs.type == TYPE_APPLICATION_STARTING)) {
+                || (DEBUG_STARTING_WINDOW_VERBOSE && mAttrs.type == TYPE_APPLICATION_STARTING)) {
             Slog.v(TAG, prefix + this
                     + ": mDrawState=" + mWinAnimator.drawStateToString()
                     + " readyForDisplay=" + isReadyForDisplay()
diff --git a/services/core/java/com/android/server/wm/WindowStateAnimator.java b/services/core/java/com/android/server/wm/WindowStateAnimator.java
index e1c6bc39ca41..d75afcf357a8 100644
--- a/services/core/java/com/android/server/wm/WindowStateAnimator.java
+++ b/services/core/java/com/android/server/wm/WindowStateAnimator.java
@@ -30,6 +30,7 @@ import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_LAYERS;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_LAYOUT_REPEATS;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_ORIENTATION;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_STARTING_WINDOW;
+import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_STARTING_WINDOW_VERBOSE;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_SURFACE_TRACE;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_VISIBILITY;
 import static com.android.server.wm.WindowManagerDebugConfig.DEBUG_WALLPAPER;
@@ -519,7 +520,7 @@ class WindowStateAnimator {
 
     // This must be called while inside a transaction.
     boolean commitFinishDrawingLocked() {
-        if (DEBUG_STARTING_WINDOW &&
+        if (DEBUG_STARTING_WINDOW_VERBOSE &&
                 mWin.mAttrs.type == WindowManager.LayoutParams.TYPE_APPLICATION_STARTING) {
             Slog.i(TAG, "commitFinishDrawingLocked: " + mWin + " cur mDrawState="
                     + drawStateToString());