SF: handle long waiting Layer sync point

When Layer transaction deferred
it wait for barrier layer's specific frame.

When the target frame is delayed for a long time, e.g. 5 min
the deferred transaction layer may queue up in mPendingStates,
may up to 20000 in real case.

When the target frame come, it will loop through mPendingStates
and call popPendingState with mPendingStates.removeAt(0);
which is an inefficient operator for Vector, which cause SWT.

Change to use std::deque for mPendingStates & mPendingStatesSnapshot
Add sync point timeout debug log.

Bug: 170690571
Test: boot up
Test: LayerUpdateTest
Test: setting pages in/out

Change-Id: I17f3751836574c3691c7e5a1e6d2ea6c3fcd3903
Merged-In: I17f3751836574c3691c7e5a1e6d2ea6c3fcd3903

2 files changed, 43 insertions, 7 deletions

diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp
index e9965d4717..55af849b7f 100644
--- a/services/surfaceflinger/Layer.cpp
+++ b/services/surfaceflinger/Layer.cpp
@@ -793,7 +793,9 @@ void Layer::pushPendingState() {
             // to be applied as per normal (no synchronization).
             mCurrentState.barrierLayer_legacy = nullptr;
         } else {
-            auto syncPoint = std::make_shared<SyncPoint>(mCurrentState.frameNumber_legacy, this);
+            auto syncPoint = std::make_shared<SyncPoint>(mCurrentState.frameNumber_legacy,
+                                                         this,
+                                                         barrierLayer);
             if (barrierLayer->addSyncPoint(syncPoint)) {
                 std::stringstream ss;
                 ss << "Adding sync point " << mCurrentState.frameNumber_legacy;
@@ -818,7 +820,7 @@ void Layer::popPendingState(State* stateToCommit) {
     ATRACE_CALL();
     *stateToCommit = mPendingStates[0];
 
-    mPendingStates.removeAt(0);
+    mPendingStates.pop_front();
     ATRACE_INT(mTransactionName.c_str(), mPendingStates.size());
 }
 
@@ -857,6 +859,7 @@ bool Layer::applyPendingStates(State* stateToCommit) {
                 mRemoteSyncPoints.pop_front();
             } else {
                 ATRACE_NAME("!frameIsAvailable");
+                mRemoteSyncPoints.front()->checkTimeoutAndLog();
                 break;
             }
         } else {
diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h
index 2c90c92f6c..d071710542 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -35,6 +35,7 @@
 #include <utils/RefBase.h>
 #include <utils/Timers.h>
 
+#include <chrono>
 #include <cstdint>
 #include <list>
 #include <optional>
@@ -881,12 +882,14 @@ protected:
 
     class SyncPoint {
     public:
-        explicit SyncPoint(uint64_t frameNumber, wp<Layer> requestedSyncLayer)
+        explicit SyncPoint(uint64_t frameNumber,
+                           wp<Layer> requestedSyncLayer,
+                           wp<Layer> barrierLayer_legacy)
               : mFrameNumber(frameNumber),
                 mFrameIsAvailable(false),
                 mTransactionIsApplied(false),
-                mRequestedSyncLayer(requestedSyncLayer) {}
-
+                mRequestedSyncLayer(requestedSyncLayer),
+                mBarrierLayer_legacy(barrierLayer_legacy) {}
         uint64_t getFrameNumber() const { return mFrameNumber; }
 
         bool frameIsAvailable() const { return mFrameIsAvailable; }
@@ -899,11 +902,41 @@ protected:
 
         sp<Layer> getRequestedSyncLayer() { return mRequestedSyncLayer.promote(); }
 
+        sp<Layer> getBarrierLayer() const { return mBarrierLayer_legacy.promote(); }
+
+        bool isTimeout() const {
+            using namespace std::chrono_literals;
+            static constexpr std::chrono::nanoseconds TIMEOUT_THRESHOLD = 1s;
+
+            return std::chrono::steady_clock::now() - mCreateTimeStamp > TIMEOUT_THRESHOLD;
+        }
+
+        void checkTimeoutAndLog() {
+            using namespace std::chrono_literals;
+            static constexpr std::chrono::nanoseconds LOG_PERIOD = 1s;
+
+            if (!frameIsAvailable() && isTimeout()) {
+                const auto now = std::chrono::steady_clock::now();
+                if (now - mLastLogTime > LOG_PERIOD) {
+                    mLastLogTime = now;
+                    sp<Layer> requestedSyncLayer = getRequestedSyncLayer();
+                    sp<Layer> barrierLayer = getBarrierLayer();
+                    ALOGW("[%s] sync point %" PRIu64 " wait timeout %lld for %s",
+                          requestedSyncLayer ? requestedSyncLayer->getDebugName() : "Removed",
+                          mFrameNumber, (now - mCreateTimeStamp).count(),
+                          barrierLayer ? barrierLayer->getDebugName() : "Removed");
+                }
+            }
+        }
     private:
         const uint64_t mFrameNumber;
         std::atomic<bool> mFrameIsAvailable;
         std::atomic<bool> mTransactionIsApplied;
         wp<Layer> mRequestedSyncLayer;
+        wp<Layer> mBarrierLayer_legacy;
+        const std::chrono::time_point<std::chrono::steady_clock> mCreateTimeStamp =
+            std::chrono::steady_clock::now();
+        std::chrono::time_point<std::chrono::steady_clock> mLastLogTime;
     };
 
     // SyncPoints which will be signaled when the correct frame is at the head
@@ -984,12 +1017,12 @@ protected:
     State mDrawingState;
     // Store a copy of the pending state so that the drawing thread can access the
     // states without a lock.
-    Vector<State> mPendingStatesSnapshot;
+    std::deque<State> mPendingStatesSnapshot;
 
     // these are protected by an external lock (mStateLock)
     State mCurrentState;
     std::atomic<uint32_t> mTransactionFlags{0};
-    Vector<State> mPendingStates;
+    std::deque<State> mPendingStates;
 
     // Timestamp history for UIAutomation. Thread safe.
     FrameTracker mFrameTracker;