Consider invalid present fence time in FrameTimeline

Virtual devices could send the present fence signal time as
SIGNAL_TIME_INVALID (-1) due to the present fence is unreliable
property. The current behavior silently drops the DisplayFrame along
with its SurfaceFrames. These SurfaceFrames could have been added to
pending jank list which require the present time to be set.

Aside from virtual devices, there also seems to be a very rare
occurrence of invalid signal time in physical devices. The repro rate is
very very low but happens around phone locking and unlocking after a
large interval. This could be tied to lifecycle of fences but its better
we address invalid signal times to solve this too.

Bug: 182006762
Test: libsurfaceflinger_unittest
Change-Id: I3a501dd070e86a2cd719a9251c22ab9cba38c16b

3 files changed, 88 insertions, 31 deletions

diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index ca37ee4429..344270603e 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -444,37 +444,26 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t
     dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);
 }
 
-void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,
-                             nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {
-    std::scoped_lock lock(mMutex);
-
-    if (mPresentState != PresentState::Presented) {
-        // No need to update dropped buffers
+void SurfaceFrame::classifyJankLocked(int32_t displayFrameJankType, const Fps& refreshRate,
+                                      nsecs_t& deadlineDelta) {
+    if (mPredictionState == PredictionState::Expired ||
+        mActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
+        // Cannot do any classification for invalid present time.
+        // For prediction expired case, we do not know what happened here to classify this
+        // correctly. This could potentially be AppDeadlineMissed but that's assuming no app will
+        // request frames 120ms apart.
+        mJankType = JankType::Unknown;
+        deadlineDelta = -1;
         return;
     }
 
-    mActuals.presentTime = presentTime;
-    // Jank Analysis for SurfaceFrame
     if (mPredictionState == PredictionState::None) {
         // Cannot do jank classification on frames that don't have a token.
         return;
     }
-    if (mPredictionState == PredictionState::Expired) {
-        // We do not know what happened here to classify this correctly. This could
-        // potentially be AppDeadlineMissed but that's assuming no app will request frames
-        // 120ms apart.
-        mJankType = JankType::Unknown;
-        mFramePresentMetadata = FramePresentMetadata::UnknownPresent;
-        mFrameReadyMetadata = FrameReadyMetadata::UnknownFinish;
-        const constexpr nsecs_t kAppDeadlineDelta = -1;
-        mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,
-                                          mJankType, displayDeadlineDelta, displayPresentDelta,
-                                          kAppDeadlineDelta});
-        return;
-    }
 
+    deadlineDelta = mActuals.endTime - mPredictions.endTime;
     const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime;
-    const nsecs_t deadlineDelta = mActuals.endTime - mPredictions.endTime;
     const nsecs_t deltaToVsync = refreshRate.getPeriodNsecs() > 0
             ? std::abs(presentDelta) % refreshRate.getPeriodNsecs()
             : 0;
@@ -558,8 +547,28 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType,
             }
         }
     }
-    mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName, mJankType,
-                                      displayDeadlineDelta, displayPresentDelta, deadlineDelta});
+}
+
+void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,
+                             nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {
+    std::scoped_lock lock(mMutex);
+
+    if (mPresentState != PresentState::Presented) {
+        // No need to update dropped buffers
+        return;
+    }
+
+    mActuals.presentTime = presentTime;
+    nsecs_t deadlineDelta = 0;
+
+    classifyJankLocked(displayFrameJankType, refreshRate, deadlineDelta);
+
+    if (mPredictionState != PredictionState::None) {
+        // Only update janky frames if the app used vsync predictions
+        mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,
+                                          mJankType, displayDeadlineDelta, displayPresentDelta,
+                                          deadlineDelta});
+    }
 }
 
 void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {
@@ -827,8 +836,9 @@ void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {
 }
 
 void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync) {
-    if (mPredictionState == PredictionState::Expired) {
-        // Cannot do jank classification with expired predictions
+    if (mPredictionState == PredictionState::Expired ||
+        mSurfaceFlingerActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
+        // Cannot do jank classification with expired predictions or invalid signal times.
         mJankType = JankType::Unknown;
         deadlineDelta = -1;
         deltaToVsync = -1;
@@ -1094,11 +1104,9 @@ void FrameTimeline::flushPendingPresentFences() {
                 continue;
             }
         }
-        if (signalTime != Fence::SIGNAL_TIME_INVALID) {
-            auto& displayFrame = pendingPresentFence.second;
-            displayFrame->onPresent(signalTime);
-            displayFrame->trace(mSurfaceFlingerPid);
-        }
+        auto& displayFrame = pendingPresentFence.second;
+        displayFrame->onPresent(signalTime);
+        displayFrame->trace(mSurfaceFlingerPid);
 
         mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
         --i;
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
index 0303a371ec..b66e02afe1 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
@@ -216,6 +216,8 @@ public:
 private:
     void tracePredictions(int64_t displayFrameToken) const;
     void traceActuals(int64_t displayFrameToken) const;
+    void classifyJankLocked(int32_t displayFrameJankType, const Fps& refreshRate,
+                            nsecs_t& deadlineDelta) REQUIRES(mMutex);
 
     const int64_t mToken;
     const int32_t mInputEventId;
diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
index 0ef2373387..81efe0b270 100644
--- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
+++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
@@ -420,7 +420,54 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) {
     EXPECT_EQ(getNumberOfDisplayFrames(), *maxDisplayFrames);
 }
 
+TEST_F(FrameTimelineTest, presentFenceSignaled_invalidSignalTime) {
+    Fps refreshRate = Fps::fromPeriodNsecs(11);
+
+    auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+    int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions({10, 20, 60});
+    int64_t sfToken1 = mTokenManager->generateTokenForPredictions({52, 60, 60});
+
+    auto surfaceFrame1 =
+            mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne,
+                                                       sUidOne, sLayerIdOne, sLayerNameOne,
+                                                       sLayerNameOne);
+    mFrameTimeline->setSfWakeUp(sfToken1, 52, refreshRate);
+    surfaceFrame1->setAcquireFenceTime(20);
+    surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented);
+    mFrameTimeline->addSurfaceFrame(surfaceFrame1);
+
+    mFrameTimeline->setSfPresent(59, presentFence1);
+    presentFence1->signalForTest(-1);
+    addEmptyDisplayFrame();
+
+    auto displayFrame0 = getDisplayFrame(0);
+    EXPECT_EQ(displayFrame0->getActuals().presentTime, -1);
+    EXPECT_EQ(displayFrame0->getJankType(), JankType::Unknown);
+    EXPECT_EQ(surfaceFrame1->getActuals().presentTime, -1);
+    EXPECT_EQ(surfaceFrame1->getJankType(), JankType::Unknown);
+}
+
 // Tests related to TimeStats
+TEST_F(FrameTimelineTest, presentFenceSignaled_doesNotReportForInvalidTokens) {
+    Fps refreshRate = Fps::fromPeriodNsecs(11);
+    EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)).Times(0);
+    auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+    int64_t surfaceFrameToken1 = -1;
+    int64_t sfToken1 = -1;
+
+    auto surfaceFrame1 =
+            mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne,
+                                                       sUidOne, sLayerIdOne, sLayerNameOne,
+                                                       sLayerNameOne);
+    mFrameTimeline->setSfWakeUp(sfToken1, 52, refreshRate);
+    surfaceFrame1->setAcquireFenceTime(20);
+    surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented);
+    mFrameTimeline->addSurfaceFrame(surfaceFrame1);
+    presentFence1->signalForTest(70);
+
+    mFrameTimeline->setSfPresent(59, presentFence1);
+}
+
 TEST_F(FrameTimelineTest, presentFenceSignaled_reportsLongSfCpu) {
     Fps refreshRate = Fps::fromPeriodNsecs(11);
     // Deadline delta is 2ms because, sf's adjusted deadline is 60 - composerTime(3) = 57ms.