Merge "Log transaction commit time of transition" into main

3 files changed, 30 insertions, 14 deletions

diff --git a/services/core/java/com/android/server/wm/BLASTSyncEngine.java b/services/core/java/com/android/server/wm/BLASTSyncEngine.java
index 94830fa11134..6eda3cf48eb4 100644
--- a/services/core/java/com/android/server/wm/BLASTSyncEngine.java
+++ b/services/core/java/com/android/server/wm/BLASTSyncEngine.java
@@ -95,6 +95,7 @@ class BLASTSyncEngine {
 
     interface TransactionReadyListener {
         void onTransactionReady(int mSyncId, SurfaceControl.Transaction transaction);
+        default void onTransactionCommitted() {}
         default void onTransactionCommitTimeout() {}
         default void onReadyTimeout() {}
 
@@ -224,20 +225,19 @@ class BLASTSyncEngine {
             if (mOrphanTransaction != null) {
                 merged.merge(mOrphanTransaction);
             }
-            for (WindowContainer wc : mRootMembers) {
-                wc.finishSync(merged, this, false /* cancel */);
-            }
-
-            final ArraySet<WindowContainer> wcAwaitingCommit = new ArraySet<>();
-            for (WindowContainer wc : mRootMembers) {
-                wc.waitForSyncTransactionCommit(wcAwaitingCommit);
-            }
 
             final long mergedTxId = merged.getId();
             class CommitCallback implements Runnable {
+                final ArraySet<WindowContainer> mWcAwaitingCommit = new ArraySet<>();
+
                 // Can run a second time if the action completes after the timeout.
                 boolean ran = false;
                 public void onCommitted(SurfaceControl.Transaction t) {
+                    mListener.onTransactionCommitted();
+                    if (mTraceName != null) {
+                        Trace.instant(TRACE_TAG_WINDOW_MANAGER,
+                                mSyncName + "#" + mSyncId + "-committed");
+                    }
                     // Don't wait to hold the global lock to remove the timeout runnable
                     mHandler.removeCallbacks(this);
                     synchronized (mWm.mGlobalLock) {
@@ -245,11 +245,11 @@ class BLASTSyncEngine {
                             return;
                         }
                         ran = true;
-                        for (WindowContainer wc : wcAwaitingCommit) {
-                            wc.onSyncTransactionCommitted(t);
+                        for (int i = mWcAwaitingCommit.size() - 1; i >= 0; --i) {
+                            mWcAwaitingCommit.valueAt(i).onSyncTransactionCommitted(t);
                         }
                         t.apply();
-                        wcAwaitingCommit.clear();
+                        mWcAwaitingCommit.clear();
                     }
                 }
 
@@ -272,6 +272,12 @@ class BLASTSyncEngine {
                 }
             };
             CommitCallback callback = new CommitCallback();
+            for (int i = mRootMembers.size() - 1; i >= 0; --i) {
+                final WindowContainer<?> wc = mRootMembers.valueAt(i);
+                wc.finishSync(merged, this, false /* cancel */);
+                wc.waitForSyncTransactionCommit(callback.mWcAwaitingCommit);
+            }
+
             merged.addTransactionCommittedListener(Runnable::run,
                     () -> callback.onCommitted(new SurfaceControl.Transaction()));
             mHandler.postDelayed(callback, BLAST_TIMEOUT_DURATION);
diff --git a/services/core/java/com/android/server/wm/Transition.java b/services/core/java/com/android/server/wm/Transition.java
index e7ed61ae57fb..f0faa8e4691f 100644
--- a/services/core/java/com/android/server/wm/Transition.java
+++ b/services/core/java/com/android/server/wm/Transition.java
@@ -1977,7 +1977,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
         } else {
             // No player registered or it's not enabled, so just finish/apply immediately
             if (!mIsPlayerEnabled) {
-                mLogger.mSendTimeNs = SystemClock.uptimeNanos();
+                mLogger.mSendTimeNs = SystemClock.elapsedRealtimeNanos();
                 ProtoLog.v(WmProtoLogGroups.WM_DEBUG_WINDOW_TRANSITIONS,
                         "Apply and finish immediately because player is disabled "
                                 + "for transition #%d .", mSyncId);
@@ -2080,6 +2080,12 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
         }
     }
 
+    // Note that this method is not called in WM lock.
+    @Override
+    public void onTransactionCommitted() {
+        mLogger.mTransactionCommitTimeNs = SystemClock.elapsedRealtimeNanos();
+    }
+
     @Override
     public void onTransactionCommitTimeout() {
         if (mCleanupTransaction == null) return;
@@ -3991,7 +3997,7 @@ class Transition implements BLASTSyncEngine.TransactionReadyListener {
         /** @return true if all tracked subtrees are ready. */
         boolean allReady() {
             ProtoLog.v(WmProtoLogGroups.WM_DEBUG_WINDOW_TRANSITIONS,
-                    " allReady query: used=%b " + "override=%b defer=%d states=[%s]", mUsed,
+                    " allReady query: used=%b override=%b defer=%d states=[%s]", mUsed,
                     mReadyOverride, mDeferReadyDepth, groupsToString());
             // If the readiness has never been touched, mUsed will be false. We never want to
             // consider a transition ready if nothing has been reported on it.
diff --git a/services/core/java/com/android/server/wm/TransitionController.java b/services/core/java/com/android/server/wm/TransitionController.java
index f3c03cbfb3b4..ff9e5a2aad99 100644
--- a/services/core/java/com/android/server/wm/TransitionController.java
+++ b/services/core/java/com/android/server/wm/TransitionController.java
@@ -774,7 +774,7 @@ class TransitionController {
                     "Disabling player for transition #%d because display isn't enabled yet",
                     transition.getSyncId());
             transition.mIsPlayerEnabled = false;
-            transition.mLogger.mRequestTimeNs = SystemClock.uptimeNanos();
+            transition.mLogger.mRequestTimeNs = SystemClock.elapsedRealtimeNanos();
             mAtm.mH.post(() -> mAtm.mWindowOrganizerController.startTransition(
                     transition.getToken(), null));
             return transition;
@@ -1694,6 +1694,7 @@ class TransitionController {
         long mStartTimeNs;
         long mReadyTimeNs;
         long mSendTimeNs;
+        long mTransactionCommitTimeNs;
         long mFinishTimeNs;
         long mAbortTimeNs;
         TransitionRequestInfo mRequest;
@@ -1746,6 +1747,9 @@ class TransitionController {
             sb.append(" started=").append(toMsString(mStartTimeNs - mCreateTimeNs));
             sb.append(" ready=").append(toMsString(mReadyTimeNs - mCreateTimeNs));
             sb.append(" sent=").append(toMsString(mSendTimeNs - mCreateTimeNs));
+            if (mTransactionCommitTimeNs != 0) {
+                sb.append(" commit=").append(toMsString(mTransactionCommitTimeNs - mSendTimeNs));
+            }
             sb.append(" finished=").append(toMsString(mFinishTimeNs - mCreateTimeNs));
             return sb.toString();
         }