SF Buffer Stuffing
When SF presents a frame because it started late (because the previous
frame ran too long), this case is similar to App Buffer Stuffing. The
frame rate will be smooth but all frames have an increased latency.
Currently, we mark this as SFScheduling jank. This change classifies
these frames as a separate jank called SFStuffing. This is useful in
weeding out issues related to frame rate vs latency.
Bug: 181593046
Test: libsurfaceflinger_unittest
Change-Id: I59a2931c5e636e9a38fd07e0a328d37873969c44
diff --git a/libs/gui/include/gui/JankInfo.h b/libs/gui/include/gui/JankInfo.h
index 85ae9cb..ce9716f 100644
--- a/libs/gui/include/gui/JankInfo.h
+++ b/libs/gui/include/gui/JankInfo.h
@@ -42,6 +42,10 @@
BufferStuffing = 0x40,
// Jank due to unknown reasons.
Unknown = 0x80,
+ // SF is said to be stuffed if the previous frame ran longer than expected resulting in the case
+ // where the previous frame was presented in the current frame's expected vsync. This pushes the
+ // current frame to the next vsync. The behavior is similar to BufferStuffing.
+ SurfaceFlingerStuffing = 0x100,
};
} // namespace android
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index be552c6..0033dbe 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -256,6 +256,10 @@
protoJank |= FrameTimelineEvent::JANK_UNKNOWN;
jankType &= ~JankType::Unknown;
}
+ if (jankType & JankType::SurfaceFlingerStuffing) {
+ protoJank |= FrameTimelineEvent::JANK_SF_STUFFING;
+ jankType &= ~JankType::SurfaceFlingerStuffing;
+ }
// jankType should be 0 if all types of jank were checked for.
LOG_ALWAYS_FATAL_IF(jankType != 0, "Unrecognized jank type value 0x%x", jankType);
@@ -875,7 +879,8 @@
mGpuFence = gpuFence;
}
-void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync) {
+void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,
+ nsecs_t previousPresentTime) {
if (mPredictionState == PredictionState::Expired ||
mSurfaceFlingerActuals.presentTime == Fence::SIGNAL_TIME_INVALID) {
// Cannot do jank classification with expired predictions or invalid signal times. Set the
@@ -949,7 +954,15 @@
mJankType = JankType::Unknown;
}
} else if (mFramePresentMetadata == FramePresentMetadata::LatePresent) {
- if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) {
+ if (std::abs(mSurfaceFlingerPredictions.presentTime - previousPresentTime) <=
+ mJankClassificationThresholds.presentThreshold ||
+ previousPresentTime > mSurfaceFlingerPredictions.presentTime) {
+ // The previous frame was either presented in the current frame's expected vsync or
+ // it was presented even later than the current frame's expected vsync.
+ mJankType = JankType::SurfaceFlingerStuffing;
+ }
+ if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish &&
+ !(mJankType & JankType::SurfaceFlingerStuffing)) {
// Finish on time, Present late
if (deltaToVsync < mJankClassificationThresholds.presentThreshold ||
deltaToVsync >= (mRefreshRate.getPeriodNsecs() -
@@ -963,11 +976,12 @@
mJankType = JankType::PredictionError;
}
} else if (mFrameReadyMetadata == FrameReadyMetadata::LateFinish) {
- if (mFrameStartMetadata == FrameStartMetadata::LateStart) {
- // Late start, Late finish, Late Present
- mJankType = JankType::SurfaceFlingerScheduling;
- } else {
- // OnTime start, Finish late, Present late
+ if (!(mJankType & JankType::SurfaceFlingerStuffing) ||
+ mSurfaceFlingerActuals.presentTime - previousPresentTime >
+ mRefreshRate.getPeriodNsecs() +
+ mJankClassificationThresholds.presentThreshold) {
+ // Classify CPU vs GPU if SF wasn't stuffed or if SF was stuffed but this frame
+ // was presented more than a vsync late.
if (mGpuFence != FenceTime::NO_FENCE &&
mSurfaceFlingerActuals.endTime - mSurfaceFlingerActuals.startTime <
mRefreshRate.getPeriodNsecs()) {
@@ -989,11 +1003,11 @@
}
}
-void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {
+void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime, nsecs_t previousPresentTime) {
mSurfaceFlingerActuals.presentTime = signalTime;
nsecs_t deadlineDelta = 0;
nsecs_t deltaToVsync = 0;
- classifyJank(deadlineDelta, deltaToVsync);
+ classifyJank(deadlineDelta, deltaToVsync, previousPresentTime);
for (auto& surfaceFrame : mSurfaceFrames) {
surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync);
@@ -1158,8 +1172,9 @@
}
}
auto& displayFrame = pendingPresentFence.second;
- displayFrame->onPresent(signalTime);
+ displayFrame->onPresent(signalTime, mPreviousPresentTime);
displayFrame->trace(mSurfaceFlingerPid);
+ mPreviousPresentTime = signalTime;
mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));
--i;
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
index 41f4978..0563a53 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
@@ -370,7 +370,7 @@
void onSfWakeUp(int64_t token, Fps refreshRate, std::optional<TimelineItem> predictions,
nsecs_t wakeUpTime);
// Sets the appropriate metadata and classifies the jank.
- void onPresent(nsecs_t signalTime);
+ void onPresent(nsecs_t signalTime, nsecs_t previousPresentTime);
// Adds the provided SurfaceFrame to the current display frame.
void addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame);
@@ -398,7 +398,8 @@
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);
+ void classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,
+ nsecs_t previousPresentTime);
int64_t mToken = FrameTimelineInfo::INVALID_VSYNC_ID;
@@ -480,6 +481,7 @@
uint32_t mMaxDisplayFrames;
std::shared_ptr<TimeStats> mTimeStats;
const pid_t mSurfaceFlingerPid;
+ nsecs_t mPreviousPresentTime = 0;
const JankClassificationThresholds mJankClassificationThresholds;
static constexpr uint32_t kDefaultMaxDisplayFrames = 64;
// The initial container size for the vector<SurfaceFrames> inside display frame. Although
diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
index 8a3f561..6ed6148 100644
--- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
+++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
@@ -1561,13 +1561,22 @@
/*
* Case 1 - cpu time > vsync period but combined time > deadline > deadline -> cpudeadlinemissed
* Case 2 - cpu time < vsync period but combined time > deadline -> gpudeadlinemissed
+ * Case 3 - previous frame ran longer -> sf_stuffing
+ * Case 4 - Long cpu under SF stuffing -> cpudeadlinemissed
*/
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence3 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence4 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
auto gpuFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
auto gpuFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto gpuFence3 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto gpuFence4 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 40});
int64_t sfToken2 = mTokenManager->generateTokenForPredictions({52, 60, 60});
+ int64_t sfToken3 = mTokenManager->generateTokenForPredictions({82, 90, 90});
+ int64_t sfToken4 = mTokenManager->generateTokenForPredictions({112, 120, 120});
+
// case 1 - cpu time = 33 - 12 = 21, vsync period = 11
mFrameTimeline->setSfWakeUp(sfToken1, 12, Fps::fromPeriodNsecs(11));
mFrameTimeline->setSfPresent(33, presentFence1, gpuFence1);
@@ -1578,12 +1587,12 @@
// Fences haven't been flushed yet, so it should be 0
EXPECT_EQ(displayFrame0->getActuals().presentTime, 0);
- // case 2 - cpu time = 56 - 52 = 4, vsync period = 11
- mFrameTimeline->setSfWakeUp(sfToken2, 52, Fps::fromPeriodNsecs(11));
+ // case 2 - cpu time = 56 - 52 = 4, vsync period = 30
+ mFrameTimeline->setSfWakeUp(sfToken2, 52, Fps::fromPeriodNsecs(30));
mFrameTimeline->setSfPresent(56, presentFence2, gpuFence2);
auto displayFrame1 = getDisplayFrame(1);
- gpuFence2->signalForTest(66);
- presentFence2->signalForTest(71);
+ gpuFence2->signalForTest(76);
+ presentFence2->signalForTest(90);
EXPECT_EQ(displayFrame1->getActuals().presentTime, 0);
// Fences have flushed for first displayFrame, so the present timestamps should be updated
@@ -1592,35 +1601,41 @@
EXPECT_EQ(displayFrame0->getFrameReadyMetadata(), FrameReadyMetadata::LateFinish);
EXPECT_EQ(displayFrame0->getJankType(), JankType::SurfaceFlingerCpuDeadlineMissed);
- addEmptyDisplayFrame();
+ // case 3 - cpu time = 86 - 82 = 4, vsync period = 30
+ mFrameTimeline->setSfWakeUp(sfToken3, 106, Fps::fromPeriodNsecs(30));
+ mFrameTimeline->setSfPresent(112, presentFence3, gpuFence3);
+ auto displayFrame2 = getDisplayFrame(2);
+ gpuFence3->signalForTest(116);
+ presentFence3->signalForTest(120);
+ EXPECT_EQ(displayFrame2->getActuals().presentTime, 0);
// Fences have flushed for second displayFrame, so the present timestamps should be updated
- EXPECT_EQ(displayFrame1->getActuals().presentTime, 71);
+ EXPECT_EQ(displayFrame1->getActuals().presentTime, 90);
EXPECT_EQ(displayFrame1->getFramePresentMetadata(), FramePresentMetadata::LatePresent);
EXPECT_EQ(displayFrame1->getFrameReadyMetadata(), FrameReadyMetadata::LateFinish);
EXPECT_EQ(displayFrame1->getJankType(), JankType::SurfaceFlingerGpuDeadlineMissed);
-}
-TEST_F(FrameTimelineTest, jankClassification_displayFrameLateStartLateFinishLatePresent) {
- auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 40});
- mFrameTimeline->setSfWakeUp(sfToken1, 26, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(36, presentFence1);
- auto displayFrame = getDisplayFrame(0);
- presentFence1->signalForTest(52);
+ // case 4 - cpu time = 86 - 82 = 4, vsync period = 30
+ mFrameTimeline->setSfWakeUp(sfToken4, 120, Fps::fromPeriodNsecs(30));
+ mFrameTimeline->setSfPresent(140, presentFence4, gpuFence4);
+ auto displayFrame3 = getDisplayFrame(3);
+ gpuFence4->signalForTest(156);
+ presentFence4->signalForTest(180);
- // Fences haven't been flushed yet, so it should be 0
- EXPECT_EQ(displayFrame->getActuals().presentTime, 0);
+ EXPECT_EQ(displayFrame3->getActuals().presentTime, 0);
+ // Fences have flushed for third displayFrame, so the present timestamps should be updated
+ EXPECT_EQ(displayFrame2->getActuals().presentTime, 120);
+ EXPECT_EQ(displayFrame2->getFramePresentMetadata(), FramePresentMetadata::LatePresent);
+ EXPECT_EQ(displayFrame2->getFrameReadyMetadata(), FrameReadyMetadata::LateFinish);
+ EXPECT_EQ(displayFrame2->getJankType(), JankType::SurfaceFlingerStuffing);
addEmptyDisplayFrame();
- displayFrame = getDisplayFrame(0);
- // Fences have flushed, so the present timestamps should be updated
- EXPECT_EQ(displayFrame->getActuals().presentTime, 52);
- EXPECT_EQ(displayFrame->getFrameStartMetadata(), FrameStartMetadata::LateStart);
- EXPECT_EQ(displayFrame->getFramePresentMetadata(), FramePresentMetadata::LatePresent);
- EXPECT_EQ(displayFrame->getFrameReadyMetadata(), FrameReadyMetadata::LateFinish);
- EXPECT_EQ(displayFrame->getJankType(), JankType::SurfaceFlingerScheduling);
+ // Fences have flushed for third displayFrame, so the present timestamps should be updated
+ EXPECT_EQ(displayFrame3->getActuals().presentTime, 180);
+ EXPECT_EQ(displayFrame3->getFramePresentMetadata(), FramePresentMetadata::LatePresent);
+ EXPECT_EQ(displayFrame3->getFrameReadyMetadata(), FrameReadyMetadata::LateFinish);
+ EXPECT_EQ(displayFrame3->getJankType(), JankType::SurfaceFlingerGpuDeadlineMissed);
}
TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishEarlyPresent) {