Added some protologs to BLASTSyncEngine

To enable easier debugging of sync-related issues

Bug: None
Test: adb shell wm logging enable-text WM_DEBUG_SYNC_ENGINE
Change-Id: Id5b6e47de6958a5b81ac3bf5617038831282165e

4 files changed, 70 insertions, 2 deletions

diff --git a/core/java/com/android/internal/protolog/ProtoLogGroup.java b/core/java/com/android/internal/protolog/ProtoLogGroup.java
index 9f7436a13bdc..9874c6aabf04 100644
--- a/core/java/com/android/internal/protolog/ProtoLogGroup.java
+++ b/core/java/com/android/internal/protolog/ProtoLogGroup.java
@@ -72,7 +72,9 @@ public enum ProtoLogGroup implements IProtoLogGroup {
             Consts.TAG_WM),
     WM_DEBUG_WINDOW_ORGANIZER(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
             Consts.TAG_WM),
-    TEST_GROUP(true, true, false, "WindowManagetProtoLogTest");
+    WM_DEBUG_SYNC_ENGINE(Consts.ENABLE_DEBUG, Consts.ENABLE_LOG_TO_PROTO_DEBUG, false,
+            Consts.TAG_WM),
+    TEST_GROUP(true, true, false, "WindowManagerProtoLogTest");
 
     private final boolean mEnabled;
     private volatile boolean mLogToProto;
diff --git a/data/etc/services.core.protolog.json b/data/etc/services.core.protolog.json
index 217de84cfc3e..668229e110df 100644
--- a/data/etc/services.core.protolog.json
+++ b/data/etc/services.core.protolog.json
@@ -151,6 +151,12 @@
       "group": "WM_ERROR",
       "at": "com\/android\/server\/wm\/WindowManagerService.java"
     },
+    "-1910833551": {
+      "message": "SyncSet{%x:%d} Start for %s",
+      "level": "VERBOSE",
+      "group": "WM_DEBUG_SYNC_ENGINE",
+      "at": "com\/android\/server\/wm\/BLASTSyncEngine.java"
+    },
     "-1895337367": {
       "message": "Delete root task display=%d winMode=%d",
       "level": "VERBOSE",
@@ -457,6 +463,12 @@
       "group": "WM_ERROR",
       "at": "com\/android\/server\/wm\/WindowManagerService.java"
     },
+    "-1387080937": {
+      "message": "SyncSet{%x:%d} Child ready, now ready=%b and waiting on %d transactions",
+      "level": "VERBOSE",
+      "group": "WM_DEBUG_SYNC_ENGINE",
+      "at": "com\/android\/server\/wm\/BLASTSyncEngine.java"
+    },
     "-1364754753": {
       "message": "Task vanished taskId=%d",
       "level": "VERBOSE",
@@ -475,6 +487,12 @@
       "group": "WM_DEBUG_BOOT",
       "at": "com\/android\/server\/wm\/WindowManagerService.java"
     },
+    "-1340783230": {
+      "message": "SyncSet{%x:%d} Added %s. now waiting on %d transactions",
+      "level": "VERBOSE",
+      "group": "WM_DEBUG_SYNC_ENGINE",
+      "at": "com\/android\/server\/wm\/BLASTSyncEngine.java"
+    },
     "-1340540100": {
       "message": "Creating SnapshotStartingData",
       "level": "VERBOSE",
@@ -853,6 +871,12 @@
       "group": "WM_DEBUG_ORIENTATION",
       "at": "com\/android\/server\/wm\/DragState.java"
     },
+    "-678300709": {
+      "message": "SyncSet{%x:%d} Trying to add %s",
+      "level": "VERBOSE",
+      "group": "WM_DEBUG_SYNC_ENGINE",
+      "at": "com\/android\/server\/wm\/BLASTSyncEngine.java"
+    },
     "-668956537": {
       "message": "  THUMBNAIL %s: CREATE",
       "level": "INFO",
@@ -1729,6 +1753,12 @@
       "group": "WM_DEBUG_IME",
       "at": "com\/android\/server\/wm\/ImeInsetsSourceProvider.java"
     },
+    "590184240": {
+      "message": "- NOT adding to sync: visible=%b hasListener=%b",
+      "level": "VERBOSE",
+      "group": "WM_DEBUG_SYNC_ENGINE",
+      "at": "com\/android\/server\/wm\/WindowContainer.java"
+    },
     "594260577": {
       "message": "createWallpaperAnimations()",
       "level": "DEBUG",
@@ -1993,6 +2023,12 @@
       "group": "WM_DEBUG_REMOTE_ANIMATIONS",
       "at": "com\/android\/server\/wm\/RemoteAnimationController.java"
     },
+    "1000601037": {
+      "message": "SyncSet{%x:%d} Set ready",
+      "level": "VERBOSE",
+      "group": "WM_DEBUG_SYNC_ENGINE",
+      "at": "com\/android\/server\/wm\/BLASTSyncEngine.java"
+    },
     "1001904964": {
       "message": "***** BOOT TIMEOUT: forcing display enabled",
       "level": "WARN",
@@ -2599,6 +2635,12 @@
       "group": "WM_DEBUG_CONFIGURATION",
       "at": "com\/android\/server\/wm\/ActivityRecord.java"
     },
+    "2001924866": {
+      "message": "SyncSet{%x:%d} Finished. Reporting %d containers to %s",
+      "level": "VERBOSE",
+      "group": "WM_DEBUG_SYNC_ENGINE",
+      "at": "com\/android\/server\/wm\/BLASTSyncEngine.java"
+    },
     "2016061474": {
       "message": "Prepare app transition: transit=%s %s alwaysKeepCurrent=%b displayId=%d Callers=%s",
       "level": "VERBOSE",
@@ -2775,6 +2817,9 @@
     "WM_DEBUG_SWITCH": {
       "tag": "WindowManager"
     },
+    "WM_DEBUG_SYNC_ENGINE": {
+      "tag": "WindowManager"
+    },
     "WM_DEBUG_WINDOW_MOVEMENT": {
       "tag": "WindowManager"
     },
diff --git a/services/core/java/com/android/server/wm/BLASTSyncEngine.java b/services/core/java/com/android/server/wm/BLASTSyncEngine.java
index 6305fda4924c..958a7a8f07f8 100644
--- a/services/core/java/com/android/server/wm/BLASTSyncEngine.java
+++ b/services/core/java/com/android/server/wm/BLASTSyncEngine.java
@@ -16,9 +16,13 @@
 
 package com.android.server.wm;
 
+import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_SYNC_ENGINE;
+
 import android.util.ArrayMap;
 import android.util.ArraySet;
 
+import com.android.internal.protolog.common.ProtoLog;
+
 import java.util.Set;
 
 /**
@@ -63,25 +67,38 @@ class BLASTSyncEngine {
 
         private void tryFinish() {
             if (mRemainingTransactions == 0 && mReady) {
+                ProtoLog.v(WM_DEBUG_SYNC_ENGINE, "SyncSet{%x:%d} Finished. Reporting %d "
+                        + "containers to %s", BLASTSyncEngine.this.hashCode(), mSyncId,
+                        mWindowContainersReady.size(), mListener);
                 mListener.onTransactionReady(mSyncId, mWindowContainersReady);
                 mPendingSyncs.remove(mSyncId);
             }
         }
 
-        public void onTransactionReady(int mSyncId, Set<WindowContainer> windowContainersReady) {
+        public void onTransactionReady(int syncId, Set<WindowContainer> windowContainersReady) {
             mRemainingTransactions--;
+            ProtoLog.v(WM_DEBUG_SYNC_ENGINE, "SyncSet{%x:%d} Child ready, now ready=%b"
+                    + " and waiting on %d transactions", BLASTSyncEngine.this.hashCode(), mSyncId,
+                    mReady, mRemainingTransactions);
             mWindowContainersReady.addAll(windowContainersReady);
             tryFinish();
         }
 
         void setReady() {
+            ProtoLog.v(WM_DEBUG_SYNC_ENGINE, "SyncSet{%x:%d} Set ready",
+                    BLASTSyncEngine.this.hashCode(), mSyncId);
             mReady = true;
             tryFinish();
         }
 
         boolean addToSync(WindowContainer wc) {
+            ProtoLog.v(WM_DEBUG_SYNC_ENGINE, "SyncSet{%x:%d} Trying to add %s",
+                    BLASTSyncEngine.this.hashCode(), mSyncId, wc);
             if (wc.prepareForSync(this, mSyncId)) {
                 mRemainingTransactions++;
+                ProtoLog.v(WM_DEBUG_SYNC_ENGINE, "SyncSet{%x:%d} Added %s. now waiting "
+                        + "on %d transactions", BLASTSyncEngine.this.hashCode(), mSyncId, wc,
+                        mRemainingTransactions);
                 return true;
             }
             return false;
@@ -105,6 +122,7 @@ class BLASTSyncEngine {
         final int id = mNextSyncId++;
         final SyncState s = new SyncState(listener, id);
         mPendingSyncs.put(id, s);
+        ProtoLog.v(WM_DEBUG_SYNC_ENGINE, "SyncSet{%x:%d} Start for %s", hashCode(), id, listener);
         return id;
     }
 
diff --git a/services/core/java/com/android/server/wm/WindowContainer.java b/services/core/java/com/android/server/wm/WindowContainer.java
index ae8f7a556ffd..2b93080a8dad 100644
--- a/services/core/java/com/android/server/wm/WindowContainer.java
+++ b/services/core/java/com/android/server/wm/WindowContainer.java
@@ -32,6 +32,7 @@ import static android.view.SurfaceControl.Transaction;
 import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_APP_TRANSITIONS;
 import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_APP_TRANSITIONS_ANIM;
 import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_ORIENTATION;
+import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_SYNC_ENGINE;
 import static com.android.server.policy.WindowManagerPolicy.FINISH_LAYOUT_REDO_WALLPAPER;
 import static com.android.server.wm.AppTransition.MAX_APP_TRANSITION_DURATION;
 import static com.android.server.wm.IdentifierProto.HASH_CODE;
@@ -2886,6 +2887,8 @@ class WindowContainer<E extends WindowContainer> extends ConfigurationContainer<
         // If we are invisible, no need to sync, likewise if we are already engaged in a sync,
         // we can't support overlapping syncs on a single container yet.
         if (!isVisible() || mWaitingListener != null) {
+            ProtoLog.v(WM_DEBUG_SYNC_ENGINE, "- NOT adding to sync: visible=%b "
+                            + "hasListener=%b", isVisible(), mWaitingListener != null);
             return false;
         }
         mUsingBLASTSyncTransaction = true;