[TimeStats] Expose pathological latch counters

* Missed latch because the acquire fence didn't fire
* Latched early because the desired present time was bad

Bug: 135478131
Test: libsurfaceflinger_unittest

Change-Id: Id02a62c222cb497c05889dd198be5fea6d64893a

8 files changed, 113 insertions, 3 deletions

diff --git a/services/surfaceflinger/BufferQueueLayer.cpp b/services/surfaceflinger/BufferQueueLayer.cpp
index b55e62b88c..bd8eafe683 100644
--- a/services/surfaceflinger/BufferQueueLayer.cpp
+++ b/services/surfaceflinger/BufferQueueLayer.cpp
@@ -117,6 +117,10 @@ bool BufferQueueLayer::shouldPresentNow(nsecs_t expectedPresentTime) const {
              "relative to expectedPresent %" PRId64,
              getDebugName(), addedTime, expectedPresentTime);
 
+    if (!isPlausible) {
+        mFlinger->mTimeStats->incrementBadDesiredPresent(getSequence());
+    }
+
     const bool isDue = addedTime < expectedPresentTime;
     return isDue || !isPlausible;
 }
@@ -154,7 +158,14 @@ bool BufferQueueLayer::fenceHasSignaled() const {
         // able to be latched. To avoid this, grab this buffer anyway.
         return true;
     }
-    return mQueueItems[0].mFenceTime->getSignalTime() != Fence::SIGNAL_TIME_PENDING;
+    const bool fenceSignaled =
+            mQueueItems[0].mFenceTime->getSignalTime() != Fence::SIGNAL_TIME_PENDING;
+    if (!fenceSignaled) {
+        mFlinger->mTimeStats->incrementLatchSkipped(getSequence(),
+                                                    TimeStats::LatchSkipReason::LateAcquire);
+    }
+
+    return fenceSignaled;
 }
 
 bool BufferQueueLayer::framePresentTimeIsCurrent(nsecs_t expectedPresentTime) const {
diff --git a/services/surfaceflinger/BufferStateLayer.cpp b/services/surfaceflinger/BufferStateLayer.cpp
index 287fe89990..b465a91de3 100644
--- a/services/surfaceflinger/BufferStateLayer.cpp
+++ b/services/surfaceflinger/BufferStateLayer.cpp
@@ -401,7 +401,14 @@ bool BufferStateLayer::fenceHasSignaled() const {
         return true;
     }
 
-    return getDrawingState().acquireFence->getStatus() == Fence::Status::Signaled;
+    const bool fenceSignaled =
+            getDrawingState().acquireFence->getStatus() == Fence::Status::Signaled;
+    if (!fenceSignaled) {
+        mFlinger->mTimeStats->incrementLatchSkipped(getSequence(),
+                                                    TimeStats::LatchSkipReason::LateAcquire);
+    }
+
+    return fenceSignaled;
 }
 
 bool BufferStateLayer::framePresentTimeIsCurrent(nsecs_t expectedPresentTime) const {
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
index 12c98da663..bed2471cd0 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.cpp
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -352,7 +352,12 @@ void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) {
             TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName];
             timeStatsLayer.totalFrames++;
             timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
+            timeStatsLayer.lateAcquireFrames += layerRecord.lateAcquireFrames;
+            timeStatsLayer.badDesiredPresentFrames += layerRecord.badDesiredPresentFrames;
+
             layerRecord.droppedFrames = 0;
+            layerRecord.lateAcquireFrames = 0;
+            layerRecord.badDesiredPresentFrames = 0;
 
             const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
                                                       timeRecords[0].frameTime.acquireTime);
@@ -466,6 +471,36 @@ void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latc
     }
 }
 
+void TimeStats::incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) {
+    if (!mEnabled.load()) return;
+
+    ATRACE_CALL();
+    ALOGV("[%d]-LatchSkipped-Reason[%d]", layerId,
+          static_cast<std::underlying_type<LatchSkipReason>::type>(reason));
+
+    std::lock_guard<std::mutex> lock(mMutex);
+    if (!mTimeStatsTracker.count(layerId)) return;
+    LayerRecord& layerRecord = mTimeStatsTracker[layerId];
+
+    switch (reason) {
+        case LatchSkipReason::LateAcquire:
+            layerRecord.lateAcquireFrames++;
+            break;
+    }
+}
+
+void TimeStats::incrementBadDesiredPresent(int32_t layerId) {
+    if (!mEnabled.load()) return;
+
+    ATRACE_CALL();
+    ALOGV("[%d]-BadDesiredPresent", layerId);
+
+    std::lock_guard<std::mutex> lock(mMutex);
+    if (!mTimeStatsTracker.count(layerId)) return;
+    LayerRecord& layerRecord = mTimeStatsTracker[layerId];
+    layerRecord.badDesiredPresentFrames++;
+}
+
 void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) {
     if (!mEnabled.load()) return;
 
diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h
index 71f06af794..a2843c8e59 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.h
+++ b/services/surfaceflinger/TimeStats/TimeStats.h
@@ -70,6 +70,18 @@ public:
     virtual void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
                              nsecs_t postTime) = 0;
     virtual void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) = 0;
+    // Reasons why latching a particular buffer may be skipped
+    enum class LatchSkipReason {
+        // If the acquire fence did not fire on some devices we skip latching
+        // the buffer until the fence fires.
+        LateAcquire,
+    };
+    // Increments the counter of skipped latch buffers.
+    virtual void incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) = 0;
+    // Increments the counter of bad desired present times for this layer.
+    // Bad desired present times are "implausible" and cause SurfaceFlinger to
+    // latch a buffer immediately to avoid stalling.
+    virtual void incrementBadDesiredPresent(int32_t layerId) = 0;
     virtual void setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) = 0;
     virtual void setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) = 0;
     virtual void setAcquireFence(int32_t layerId, uint64_t frameNumber,
@@ -116,6 +128,8 @@ class TimeStats : public android::TimeStats {
         // fences to signal, but rather waiting to receive those fences/timestamps.
         int32_t waitData = -1;
         uint32_t droppedFrames = 0;
+        uint32_t lateAcquireFrames = 0;
+        uint32_t badDesiredPresentFrames = 0;
         TimeRecord prevTimeRecord;
         std::deque<TimeRecord> timeRecords;
     };
@@ -200,6 +214,8 @@ public:
     void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
                      nsecs_t postTime) override;
     void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) override;
+    void incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) override;
+    void incrementBadDesiredPresent(int32_t layerId) override;
     void setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) override;
     void setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) override;
     void setAcquireFence(int32_t layerId, uint64_t frameNumber,
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
index 0ba90e23c9..1c910aa6a1 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
+++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
@@ -83,6 +83,8 @@ std::string TimeStatsHelper::TimeStatsLayer::toString() const {
     StringAppendF(&result, "packageName = %s\n", packageName.c_str());
     StringAppendF(&result, "totalFrames = %d\n", totalFrames);
     StringAppendF(&result, "droppedFrames = %d\n", droppedFrames);
+    StringAppendF(&result, "lateAcquireFrames = %d\n", lateAcquireFrames);
+    StringAppendF(&result, "badDesiredPresentFrames = %d\n", badDesiredPresentFrames);
     const auto iter = deltas.find("present2present");
     if (iter != deltas.end()) {
         StringAppendF(&result, "averageFPS = %.3f\n", 1000.0 / iter->second.averageTime());
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
index 702c50e58e..e374b73c38 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
+++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
@@ -46,6 +46,8 @@ public:
         std::string packageName;
         int32_t totalFrames = 0;
         int32_t droppedFrames = 0;
+        int32_t lateAcquireFrames = 0;
+        int32_t badDesiredPresentFrames = 0;
         std::unordered_map<std::string, Histogram> deltas;
 
         std::string toString() const;
diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
index 68e6697ce0..a170e34703 100644
--- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
+++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
@@ -306,6 +306,41 @@ TEST_F(TimeStatsTest, canIncreaseGlobalStats) {
     EXPECT_EQ(CLIENT_COMPOSITION_FRAMES, globalProto.client_composition_frames());
 }
 
+TEST_F(TimeStatsTest, canIncreaseLateAcquireFrames) {
+    // this stat is not in the proto so verify by checking the string dump
+    constexpr size_t LATE_ACQUIRE_FRAMES = 2;
+
+    EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
+
+    insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
+    for (size_t i = 0; i < LATE_ACQUIRE_FRAMES; i++) {
+        mTimeStats->incrementLatchSkipped(LAYER_ID_0, TimeStats::LatchSkipReason::LateAcquire);
+    }
+    insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_0, 2, 2000000);
+
+    const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
+    const std::string expectedResult = "lateAcquireFrames = " + std::to_string(LATE_ACQUIRE_FRAMES);
+    EXPECT_THAT(result, HasSubstr(expectedResult));
+}
+
+TEST_F(TimeStatsTest, canIncreaseBadDesiredPresent) {
+    // this stat is not in the proto so verify by checking the string dump
+    constexpr size_t BAD_DESIRED_PRESENT_FRAMES = 2;
+
+    EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
+
+    insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
+    for (size_t i = 0; i < BAD_DESIRED_PRESENT_FRAMES; i++) {
+        mTimeStats->incrementBadDesiredPresent(LAYER_ID_0);
+    }
+    insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_0, 2, 2000000);
+
+    const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
+    const std::string expectedResult =
+            "badDesiredPresentFrames = " + std::to_string(BAD_DESIRED_PRESENT_FRAMES);
+    EXPECT_THAT(result, HasSubstr(expectedResult));
+}
+
 TEST_F(TimeStatsTest, canIncreaseClientCompositionReusedFrames) {
     // this stat is not in the proto so verify by checking the string dump
     constexpr size_t CLIENT_COMPOSITION_REUSED_FRAMES = 2;
@@ -665,7 +700,7 @@ TEST_F(TimeStatsTest, canClearTimeStats) {
     EXPECT_EQ(0, globalProto.stats_size());
 }
 
-TEST_F(TimeStatsTest, canClearClientCompositionSkippedFrames) {
+TEST_F(TimeStatsTest, canClearClientCompositionReusedFrames) {
     // this stat is not in the proto so verify by checking the string dump
     EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
     ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementClientCompositionReusedFrames());
diff --git a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
index d1df08c40a..2720537432 100644
--- a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
+++ b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
@@ -40,6 +40,8 @@ public:
     MOCK_METHOD2(recordRenderEngineDuration, void(nsecs_t, nsecs_t));
     MOCK_METHOD2(recordRenderEngineDuration, void(nsecs_t, const std::shared_ptr<FenceTime>&));
     MOCK_METHOD4(setPostTime, void(int32_t, uint64_t, const std::string&, nsecs_t));
+    MOCK_METHOD2(incrementLatchSkipped, void(int32_t layerId, LatchSkipReason reason));
+    MOCK_METHOD1(incrementBadDesiredPresent, void(int32_t layerId));
     MOCK_METHOD3(setLatchTime, void(int32_t, uint64_t, nsecs_t));
     MOCK_METHOD3(setDesiredTime, void(int32_t, uint64_t, nsecs_t));
     MOCK_METHOD3(setAcquireTime, void(int32_t, uint64_t, nsecs_t));