From 115ac691f66f87782de4089254c928f55d70bbc1 Mon Sep 17 00:00:00 2001 From: Adithya Srinivasan Date: Sat, 6 Mar 2021 01:21:30 +0000 Subject: Call SurfaceFrame::onPresent if DisplayFrame predictions expired If the DisplayFrame's Predictions have expired, that shouldn't stop the SurfaceFrames from being classified. The predictions for SurfaceFrames and DisplayFrames are retreived at different points of time. So, if a present fence is signaled, make sure the SurfaceFrame's onPresent is called. Bug: 182006762 Test: libsurfaceflinger_unittest Change-Id: I23f3b85f979938a6e4a7e2dcf7341d6ab2222d53 --- .../surfaceflinger/FrameTimeline/FrameTimeline.cpp | 18 ++++++++--- .../surfaceflinger/FrameTimeline/FrameTimeline.h | 3 +- .../tests/unittests/FrameTimelineTest.cpp | 37 ++++++++++++++++++++++ 3 files changed, 53 insertions(+), 5 deletions(-) diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp index 03e38f30de..ca37ee4429 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp @@ -826,25 +826,27 @@ void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) { mSurfaceFlingerActuals.endTime = actualEndTime; } -void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { - mSurfaceFlingerActuals.presentTime = signalTime; +void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync) { if (mPredictionState == PredictionState::Expired) { // Cannot do jank classification with expired predictions mJankType = JankType::Unknown; + deadlineDelta = -1; + deltaToVsync = -1; return; } // Delta between the expected present and the actual present const nsecs_t presentDelta = mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime; - const nsecs_t deadlineDelta = + deadlineDelta = mSurfaceFlingerActuals.endTime - (mSurfaceFlingerPredictions.endTime - mHwcDuration); // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there // was a prediction error or not. - nsecs_t deltaToVsync = mRefreshRate.getPeriodNsecs() > 0 + deltaToVsync = mRefreshRate.getPeriodNsecs() > 0 ? std::abs(presentDelta) % mRefreshRate.getPeriodNsecs() : 0; + if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) { mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent : FramePresentMetadata::EarlyPresent; @@ -922,6 +924,14 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { mJankType = JankType::Unknown; } } +} + +void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { + mSurfaceFlingerActuals.presentTime = signalTime; + nsecs_t deadlineDelta = 0; + nsecs_t deltaToVsync = 0; + classifyJank(deadlineDelta, deltaToVsync); + for (auto& surfaceFrame : mSurfaceFrames) { surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync); } diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h index 7c6a0cc866..0303a371ec 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h @@ -355,7 +355,7 @@ public: // Sets the token, vsyncPeriod, predictions and SF start time. void onSfWakeUp(int64_t token, Fps refreshRate, std::optional predictions, nsecs_t wakeUpTime); - // Sets the appropriate metadata, classifies the jank and returns the classified jankType. + // Sets the appropriate metadata and classifies the jank. void onPresent(nsecs_t signalTime); // Adds the provided SurfaceFrame to the current display frame. void addSurfaceFrame(std::shared_ptr surfaceFrame); @@ -383,6 +383,7 @@ public: void dump(std::string& result, nsecs_t baseTime) const; void tracePredictions(pid_t surfaceFlingerPid) const; void traceActuals(pid_t surfaceFlingerPid) const; + void classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync); int64_t mToken = FrameTimelineInfo::INVALID_VSYNC_ID; diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp index f2cb9513f0..0ef2373387 100644 --- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp +++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp @@ -603,6 +603,43 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMissWithRenderRate) { EXPECT_EQ(surfaceFrame1->getJankType(), JankType::AppDeadlineMissed); } +TEST_F(FrameTimelineTest, presentFenceSignaled_displayFramePredictionExpiredPresentsSurfaceFrame) { + Fps refreshRate = Fps::fromPeriodNsecs(11); + Fps renderRate = Fps::fromPeriodNsecs(30); + + EXPECT_CALL(*mTimeStats, + incrementJankyFrames(TimeStats::JankyFramesInfo{refreshRate, renderRate, sUidOne, + sLayerNameOne, JankType::Unknown, + -1, -1, 25})); + auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); + int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions({10, 20, 60}); + int64_t sfToken1 = mTokenManager->generateTokenForPredictions({82, 90, 90}); + + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, + sUidOne, sLayerIdOne, sLayerNameOne, + sLayerNameOne); + surfaceFrame1->setAcquireFenceTime(45); + // Trigger a prediction expiry + flushTokens(systemTime() + maxTokenRetentionTime); + mFrameTimeline->setSfWakeUp(sfToken1, 52, refreshRate); + + surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); + surfaceFrame1->setRenderRate(renderRate); + mFrameTimeline->addSurfaceFrame(surfaceFrame1); + presentFence1->signalForTest(90); + mFrameTimeline->setSfPresent(86, presentFence1); + + auto displayFrame = getDisplayFrame(0); + EXPECT_EQ(displayFrame->getJankType(), JankType::Unknown); + EXPECT_EQ(displayFrame->getFrameStartMetadata(), FrameStartMetadata::UnknownStart); + EXPECT_EQ(displayFrame->getFrameReadyMetadata(), FrameReadyMetadata::UnknownFinish); + EXPECT_EQ(displayFrame->getFramePresentMetadata(), FramePresentMetadata::UnknownPresent); + + EXPECT_EQ(surfaceFrame1->getActuals().presentTime, 90); + EXPECT_EQ(surfaceFrame1->getJankType(), JankType::Unknown); +} + /* * Tracing Tests * -- cgit v1.2.3-59-g8ed1b From 7c4ac7a31d3dc4a0cfec9d2f893c56307ee95185 Mon Sep 17 00:00:00 2001 From: Adithya Srinivasan Date: Mon, 8 Mar 2021 23:48:03 +0000 Subject: 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 --- .../surfaceflinger/FrameTimeline/FrameTimeline.cpp | 70 ++++++++++++---------- .../surfaceflinger/FrameTimeline/FrameTimeline.h | 2 + .../tests/unittests/FrameTimelineTest.cpp | 47 +++++++++++++++ 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(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. -- cgit v1.2.3-59-g8ed1b