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

Commit aa107744 authored by Sally Qi's avatar Sally Qi
Browse files

Trace SF skipped frame. 

Bug: 273701290
Test: FrameTimelineTest#traceDisplayFrameSkipped; https://screenshot.googleplex.com/4As43np7DoF6Dxm

Change-Id: I0604ab3d15ef94351f9a592920c56ab00ef51b23
parent d60f6bb2

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+66 −3
Original line number Diff line number Diff line
@@ -1074,6 +1074,66 @@ void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid, 
    });

}



void FrameTimeline::DisplayFrame::addSkippedFrame(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,

                                                  nsecs_t previousActualPresentTime) const {

    nsecs_t skippedFrameStartTime = 0, skippedFramePresentTime = 0;

    const constexpr float kThresh = 0.5f;

    const constexpr float kRange = 1.5f;

    for (auto& surfaceFrame : mSurfaceFrames) {

        if (previousActualPresentTime != 0 &&

            static_cast<float>(mSurfaceFlingerActuals.presentTime - previousActualPresentTime) >=

                    static_cast<float>(mRenderRate.getPeriodNsecs()) * kRange &&

            static_cast<float>(surfaceFrame->getPredictions().presentTime) <=

                    (static_cast<float>(mSurfaceFlingerActuals.presentTime) -

                     kThresh * static_cast<float>(mRenderRate.getPeriodNsecs())) &&

            static_cast<float>(surfaceFrame->getPredictions().presentTime) >=

                    (static_cast<float>(previousActualPresentTime) -

                     kThresh * static_cast<float>(mRenderRate.getPeriodNsecs()))) {

            skippedFrameStartTime = surfaceFrame->getPredictions().endTime;

            skippedFramePresentTime = surfaceFrame->getPredictions().presentTime;

            break;

        }

    }



    // add slice

    if (skippedFrameStartTime != 0 && skippedFramePresentTime != 0) {

        int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();



        // Actual timeline start

        FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {

            auto packet = ctx.NewTracePacket();

            packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);

            packet->set_timestamp(static_cast<uint64_t>(skippedFrameStartTime + monoBootOffset));



            auto* event = packet->set_frame_timeline_event();

            auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();



            actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);



            actualDisplayFrameStartEvent->set_token(0);

            actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);

            actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==

                                                             FrameReadyMetadata::OnTimeFinish);

            actualDisplayFrameStartEvent->set_gpu_composition(false);

            actualDisplayFrameStartEvent->set_prediction_type(toProto(PredictionState::Valid));

            actualDisplayFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);

            actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(JankType::Dropped));

        });



        // Actual timeline end

        FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {

            auto packet = ctx.NewTracePacket();

            packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);

            packet->set_timestamp(static_cast<uint64_t>(skippedFramePresentTime + monoBootOffset));



            auto* event = packet->set_frame_timeline_event();

            auto* actualDisplayFrameEndEvent = event->set_frame_end();



            actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);

        });

    }

}



void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid,

                                               nsecs_t monoBootOffset) const {

    int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
@@ -1115,7 +1175,8 @@ void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid, 
    });

}



void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const {

void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,

                                        nsecs_t previousActualPresentTime) const {

    if (mSurfaceFrames.empty()) {

        // We don't want to trace display frames without any surface frames updates as this cannot

        // be janky
@@ -1138,6 +1199,8 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBoo 
    for (auto& surfaceFrame : mSurfaceFrames) {

        surfaceFrame->trace(mToken, monoBootOffset);

    }



    addSkippedFrame(surfaceFlingerPid, monoBootOffset, previousActualPresentTime);

}



float FrameTimeline::computeFps(const std::unordered_set<int32_t>& layerIds) {
@@ -1229,7 +1292,7 @@ void FrameTimeline::flushPendingPresentFences() { 
        const nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;

        auto& displayFrame = pendingPresentFence.second;

        displayFrame->onPresent(signalTime, mPreviousPresentTime);

        displayFrame->trace(mSurfaceFlingerPid, monoBootOffset);

        displayFrame->trace(mSurfaceFlingerPid, monoBootOffset, mPreviousPresentTime);

        mPendingPresentFences.erase(mPendingPresentFences.begin());

    }
@@ -1245,7 +1308,7 @@ void FrameTimeline::flushPendingPresentFences() { 


        auto& displayFrame = pendingPresentFence.second;

        displayFrame->onPresent(signalTime, mPreviousPresentTime);

        displayFrame->trace(mSurfaceFlingerPid, monoBootOffset);

        displayFrame->trace(mSurfaceFlingerPid, monoBootOffset, mPreviousPresentTime);

        mPreviousPresentTime = signalTime;



        mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+4 −1
Original line number Diff line number Diff line
@@ -378,7 +378,8 @@ public: 
        // Emits a packet for perfetto tracing. The function body will be executed only if tracing

        // is enabled. monoBootOffset is the difference between SYSTEM_TIME_BOOTTIME

        // and SYSTEM_TIME_MONOTONIC.

        void trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;

        void trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,

                   nsecs_t previousActualPresentTime) const;

        // Sets the token, vsyncPeriod, predictions and SF start time.

        void onSfWakeUp(int64_t token, Fps refreshRate, Fps renderRate,

                        std::optional<TimelineItem> predictions, nsecs_t wakeUpTime);
@@ -411,6 +412,8 @@ public: 
        void dump(std::string& result, nsecs_t baseTime) const;

        void tracePredictions(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;

        void traceActuals(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;

        void addSkippedFrame(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,

                             nsecs_t previousActualPresentTime) const;

        void classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,

                          nsecs_t previousPresentTime);

services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp

+88 −1
Original line number Diff line number Diff line
@@ -14,7 +14,6 @@ 
 * limitations under the License.

 */





#include "gmock/gmock-spec-builders.h"

#include "mock/MockTimeStats.h"

#undef LOG_TAG
@@ -1059,6 +1058,94 @@ void validateTraceEvent(const ProtoFrameEnd& received, const ProtoFrameEnd& sour 
    EXPECT_EQ(received.cookie(), source.cookie());

}



TEST_F(FrameTimelineTest, traceDisplayFrameSkipped) {

    // setup 2 display frames

    // DF 1: [22,40] -> [5, 40]

    // DF  : [36, 70] (Skipped one, added by the trace)

    // DF 2: [82, 100] -> SF [25, 70]

    auto tracingSession = getTracingSessionForTest();

    tracingSession->StartBlocking();

    int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 30, 40});

    int64_t sfToken2 = mTokenManager->generateTokenForPredictions({82, 90, 100});

    int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions({5, 16, 40});

    int64_t surfaceFrameToken2 = mTokenManager->generateTokenForPredictions({25, 36, 70});

    auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);



    int64_t traceCookie = snoopCurrentTraceCookie();



    // set up 1st display frame

    FrameTimelineInfo ftInfo1;

    ftInfo1.vsyncId = surfaceFrameToken1;

    ftInfo1.inputEventId = sInputEventId;

    auto surfaceFrame1 =

            mFrameTimeline->createSurfaceFrameForToken(ftInfo1, sPidOne, sUidOne, sLayerIdOne,

                                                       sLayerNameOne, sLayerNameOne,

                                                       /*isBuffer*/ true, sGameMode);

    surfaceFrame1->setAcquireFenceTime(16);

    mFrameTimeline->setSfWakeUp(sfToken1, 22, RR_11, RR_30);

    surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented);

    mFrameTimeline->addSurfaceFrame(surfaceFrame1);

    mFrameTimeline->setSfPresent(30, presentFence1);

    presentFence1->signalForTest(40);



    // Trigger a flush by finalizing the next DisplayFrame

    auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);

    FrameTimelineInfo ftInfo2;

    ftInfo2.vsyncId = surfaceFrameToken2;

    ftInfo2.inputEventId = sInputEventId;

    auto surfaceFrame2 =

            mFrameTimeline->createSurfaceFrameForToken(ftInfo2, sPidOne, sUidOne, sLayerIdOne,

                                                       sLayerNameOne, sLayerNameOne,

                                                       /*isBuffer*/ true, sGameMode);



    // set up 2nd display frame

    surfaceFrame2->setAcquireFenceTime(36);

    mFrameTimeline->setSfWakeUp(sfToken2, 82, RR_11, RR_30);

    surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented);

    mFrameTimeline->addSurfaceFrame(surfaceFrame2);

    mFrameTimeline->setSfPresent(90, presentFence2);

    presentFence2->signalForTest(100);



    // the token of skipped Display Frame

    auto protoSkippedActualDisplayFrameStart =

            createProtoActualDisplayFrameStart(traceCookie + 9, 0, kSurfaceFlingerPid,

                                               FrameTimelineEvent::PRESENT_DROPPED, true, false,

                                               FrameTimelineEvent::JANK_DROPPED,

                                               FrameTimelineEvent::PREDICTION_VALID);

    auto protoSkippedActualDisplayFrameEnd = createProtoFrameEnd(traceCookie + 9);



    // Trigger a flush by finalizing the next DisplayFrame

    addEmptyDisplayFrame();

    flushTrace();

    tracingSession->StopBlocking();



    auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());

    // 8 Valid Display Frames + 8 Valid Surface Frames + 2 Skipped Display Frames

    EXPECT_EQ(packets.size(), 18u);



    // Packet - 16: Actual skipped Display Frame Start

    // the timestamp should be equal to the 2nd expected surface frame's end time

    const auto& packet16 = packets[16];

    ASSERT_TRUE(packet16.has_timestamp());

    EXPECT_EQ(packet16.timestamp(), 36u);

    ASSERT_TRUE(packet16.has_frame_timeline_event());



    const auto& event16 = packet16.frame_timeline_event();

    const auto& actualSkippedDisplayFrameStart = event16.actual_display_frame_start();

    validateTraceEvent(actualSkippedDisplayFrameStart, protoSkippedActualDisplayFrameStart);



    // Packet - 17: Actual skipped Display Frame End

    // the timestamp should be equal to the 2nd expected surface frame's present time

    const auto& packet17 = packets[17];

    ASSERT_TRUE(packet17.has_timestamp());

    EXPECT_EQ(packet17.timestamp(), 70u);

    ASSERT_TRUE(packet17.has_frame_timeline_event());



    const auto& event17 = packet17.frame_timeline_event();

    const auto& actualSkippedDisplayFrameEnd = event17.frame_end();

    validateTraceEvent(actualSkippedDisplayFrameEnd, protoSkippedActualDisplayFrameEnd);

}



TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) {

    auto tracingSession = getTracingSessionForTest();

    auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);