Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 57dc81d9 authored by Adithya Srinivasan's avatar Adithya Srinivasan
Browse files

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
parent 3dec083f

libs/gui/include/gui/JankInfo.h

+4 −0
Original line number Diff line number Diff line
@@ -42,6 +42,10 @@ enum JankType { 
    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

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+25 −10
Original line number Diff line number Diff line
@@ -256,6 +256,10 @@ int32_t jankTypeBitmaskToProto(int32_t jankType) { 
        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 @@ void FrameTimeline::DisplayFrame::setGpuFence(const std::shared_ptr<FenceTime>& 
    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 @@ void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& 
                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 @@ void FrameTimeline::DisplayFrame::classifyJank(nsecs_t& deadlineDelta, nsecs_t& 
                    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::classifyJank(nsecs_t& deadlineDelta, nsecs_t& 
    }

}



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 @@ void FrameTimeline::flushPendingPresentFences() { 
            }

        }

        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;

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+4 −2
Original line number Diff line number Diff line
@@ -370,7 +370,7 @@ public: 
        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 @@ 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);

        void classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,

                          nsecs_t previousPresentTime);



        int64_t mToken = FrameTimelineInfo::INVALID_VSYNC_ID;
@@ -480,6 +481,7 @@ private: 
    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

services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp

+38 −23
Original line number Diff line number Diff line
@@ -1561,13 +1561,22 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameLateFinishLatePresent) 
    /*

     * 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 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameLateFinishLatePresent) 
    // 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 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameLateFinishLatePresent) 
    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) {