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

Commit 061c14c7 authored by Adithya Srinivasan's avatar Adithya Srinivasan
Browse files

Trace predictionExpired and dropped frames properly 

Allowing frames with prediction expired causes a undesirable skew in the
trace. Since the timestamps are zero for this case, the trace packets
are also sent out with zero timestamp. These zero timestamps are seen as
the earliest possible time in a trace and hence make it look like the
trace contains 1000s of seconds of data while it actually doesn't.
This change addresses this issue by making SurfaceFrames not send any
expected timeline packets if prediction is expired. For actual timeline
packets, we apply a delta to the end time so that it looks like the
frame has a start and an end.

For dropped SurfaceFrames, we don't have an actual end time so far. This
change adds a dropTime to the SurfaceFrame so that we can keep track of
it in trace and dumpsys.

Bug: 179905685
Test: libsurfaceflinger_unittest:FrameTimelineTest

Change-Id: I573037be27f8a74670a65cad791841fa6ed75e20
parent e06403fa

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+88 −40
Original line number Diff line number Diff line
@@ -30,6 +30,7 @@ namespace android::frametimeline { 


using base::StringAppendF;

using FrameTimelineEvent = perfetto::protos::pbzero::FrameTimelineEvent;

using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;



void dumpTable(std::string& result, TimelineItem predictions, TimelineItem actuals,

               const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {
@@ -305,11 +306,17 @@ void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) { 
    std::scoped_lock lock(mMutex);

    mActualQueueTime = actualQueueTime;

}



void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {

    std::scoped_lock lock(mMutex);

    mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);

}



void SurfaceFrame::setDropTime(nsecs_t dropTime) {

    std::scoped_lock lock(mMutex);

    mDropTime = dropTime;

}



void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {

    std::scoped_lock lock(mMutex);

    LOG_ALWAYS_FATAL_IF(mPresentState != PresentState::Unknown,
@@ -343,6 +350,11 @@ TimelineItem SurfaceFrame::getActuals() const { 
    return mActuals;

}



PredictionState SurfaceFrame::getPredictionState() const {

    std::scoped_lock lock(mMutex);

    return mPredictionState;

}



SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {

    std::scoped_lock lock(mMutex);

    return mPresentState;
@@ -358,6 +370,11 @@ FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const { 
    return mFrameReadyMetadata;

}



nsecs_t SurfaceFrame::getDropTime() const {

    std::scoped_lock lock(mMutex);

    return mDropTime;

}



void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {

    std::scoped_lock lock(mMutex);

    StringAppendF(&result, "%s", indent.c_str());
@@ -377,6 +394,12 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t 
    StringAppendF(&result, "%s", indent.c_str());

    StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());

    StringAppendF(&result, "%s", indent.c_str());

    if (mPresentState == PresentState::Dropped) {

        std::chrono::nanoseconds dropTime(mDropTime - baseTime);

        StringAppendF(&result, "Drop time : %10f\n",

                      std::chrono::duration<double, std::milli>(dropTime).count());

        StringAppendF(&result, "%s", indent.c_str());

    }

    StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());

    StringAppendF(&result, "%s", indent.c_str());

    StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
@@ -500,27 +523,12 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, 
                                      displayDeadlineDelta, displayPresentDelta, deadlineDelta});

}



/**

 * TODO(b/178637512): add inputEventId to the perfetto trace.

 */

void SurfaceFrame::trace(int64_t displayFrameToken) {

    using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;



void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {

    int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();

    bool missingToken = false;



    // Expected timeline start

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

        std::scoped_lock lock(mMutex);

        if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {

            ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());

            missingToken = true;

            return;

        } else if (displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {

            ALOGD("Cannot trace SurfaceFrame  - %s with invalid displayFrameToken",

                  mLayerName.c_str());

            missingToken = true;

            return;

        }

        auto packet = ctx.NewTracePacket();

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

        packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
@@ -537,12 +545,6 @@ void SurfaceFrame::trace(int64_t displayFrameToken) { 
        expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);

    });



    if (missingToken) {

        // If one packet can't be traced because of missing token, then no packets can be traced.

        // Exit early in this case.

        return;

    }



    // Expected timeline end

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

        std::scoped_lock lock(mMutex);
@@ -555,15 +557,26 @@ void SurfaceFrame::trace(int64_t displayFrameToken) { 


        expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);

    });

}



void SurfaceFrame::traceActuals(int64_t displayFrameToken) const {

    int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();



    // Actual timeline start

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

        std::scoped_lock lock(mMutex);

        auto packet = ctx.NewTracePacket();

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

        // Actual start time is not yet available, so use expected start instead

        if (mPredictionState == PredictionState::Expired) {

            // If prediction is expired, we can't use the predicted start time. Instead, just use a

            // start time a little earlier than the end time so that we have some info about this

            // frame in the trace.

            packet->set_timestamp(

                    static_cast<uint64_t>(mActuals.endTime - kPredictionExpiredStartTimeDelta));

        } else {

            packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));

        }



        auto* event = packet->set_frame_timeline_event();

        auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
@@ -588,12 +601,17 @@ void SurfaceFrame::trace(int64_t displayFrameToken) { 
        actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);

        actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));

    });



    // Actual timeline end

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

        std::scoped_lock lock(mMutex);

        auto packet = ctx.NewTracePacket();

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

        if (mPresentState == PresentState::Dropped) {

            packet->set_timestamp(static_cast<uint64_t>(mDropTime));

        } else {

            packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));

        }



        auto* event = packet->set_frame_timeline_event();

        auto* actualSurfaceFrameEndEvent = event->set_frame_end();
@@ -602,6 +620,23 @@ void SurfaceFrame::trace(int64_t displayFrameToken) { 
    });

}



/**

 * TODO(b/178637512): add inputEventId to the perfetto trace.

 */

void SurfaceFrame::trace(int64_t displayFrameToken) const {

    if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||

        displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {

        // No packets can be traced with a missing token.

        return;

    }

    if (getPredictionState() != PredictionState::Expired) {

        // Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in

        // a trace.

        tracePredictions(displayFrameToken);

    }

    traceActuals(displayFrameToken);

}



namespace impl {



int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
@@ -750,6 +785,11 @@ void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) { 


void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {

    mSurfaceFlingerActuals.presentTime = signalTime;

    if (mPredictionState == PredictionState::Expired) {

        // Cannot do jank classification with expired predictions

        mJankType = JankType::Unknown;

        return;

    }



    // Delta between the expected present and the actual present

    const nsecs_t presentDelta =
@@ -836,17 +876,12 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { 
    }

}



void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {

void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) const {

    int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();

    bool missingToken = false;



    // Expected timeline start

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

        auto packet = ctx.NewTracePacket();

        if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {

            ALOGD("Cannot trace DisplayFrame with invalid token");

            missingToken = true;

            return;

        }

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

        packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
@@ -859,12 +894,6 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const { 
        expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);

    });



    if (missingToken) {

        // If one packet can't be traced because of missing token, then no packets can be traced.

        // Exit early in this case.

        return;

    }



    // Expected timeline end

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

        auto packet = ctx.NewTracePacket();
@@ -876,9 +905,12 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const { 


        expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);

    });

}



void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const {

    int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();

    // Expected timeline start



    // Actual timeline start

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

        auto packet = ctx.NewTracePacket();

        packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
@@ -898,7 +930,8 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const { 
        actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);

        actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));

    });

    // Expected timeline end



    // Actual timeline end

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

        auto packet = ctx.NewTracePacket();

        packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
@@ -909,6 +942,21 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const { 


        actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);

    });

}



void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {

    if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {

        // DisplayFrame should not have an invalid token.

        ALOGE("Cannot trace DisplayFrame with invalid token");

        return;

    }



    if (mPredictionState == PredictionState::Valid) {

        // Expired and unknown predictions have zeroed timestamps. This cannot be used in any

        // meaningful way in a trace.

        tracePredictions(surfaceFlingerPid);

    }

    traceActuals(surfaceFlingerPid);



    for (auto& surfaceFrame : mSurfaceFrames) {

        surfaceFrame->trace(mToken);

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+19 −4
Original line number Diff line number Diff line
@@ -171,10 +171,12 @@ public: 
    TimelineItem getPredictions() const { return mPredictions; };

    // Actual timestamps of the app are set individually at different functions.

    // Start time (if the app provides) and Queue time are accessible after queueing the frame,

    // whereas Acquire Fence time is available only during latch.

    // whereas Acquire Fence time is available only during latch. Drop time is available at the time

    // the buffer was dropped.

    void setActualStartTime(nsecs_t actualStartTime);

    void setActualQueueTime(nsecs_t actualQueueTime);

    void setAcquireFenceTime(nsecs_t acquireFenceTime);

    void setDropTime(nsecs_t dropTime);

    void setPresentState(PresentState presentState, nsecs_t lastLatchTime = 0);

    void setRenderRate(Fps renderRate);
@@ -192,17 +194,27 @@ public: 
    // Emits a packet for perfetto tracing. The function body will be executed only if tracing is

    // enabled. The displayFrameToken is needed to link the SurfaceFrame to the corresponding

    // DisplayFrame at the trace processor side.

    void trace(int64_t displayFrameToken);

    void trace(int64_t displayFrameToken) const;



    // Getter functions used only by FrameTimelineTests

    // Getter functions used only by FrameTimelineTests and SurfaceFrame internally

    TimelineItem getActuals() const;

    pid_t getOwnerPid() const { return mOwnerPid; };

    PredictionState getPredictionState() const { return mPredictionState; };

    PredictionState getPredictionState() const;

    PresentState getPresentState() const;

    FrameReadyMetadata getFrameReadyMetadata() const;

    FramePresentMetadata getFramePresentMetadata() const;

    nsecs_t getDropTime() const;



    // For prediction expired frames, this delta is subtracted from the actual end time to get a

    // start time decent enough to see in traces.

    // TODO(b/172587309): Remove this when we have actual start times.

    static constexpr nsecs_t kPredictionExpiredStartTimeDelta =

            std::chrono::duration_cast<std::chrono::nanoseconds>(2ms).count();



private:

    void tracePredictions(int64_t displayFrameToken) const;

    void traceActuals(int64_t displayFrameToken) const;



    const int64_t mToken;

    const int32_t mInputEventId;

    const pid_t mOwnerPid;
@@ -216,6 +228,7 @@ private: 
    std::shared_ptr<TimeStats> mTimeStats;

    const JankClassificationThresholds mJankClassificationThresholds;

    nsecs_t mActualQueueTime GUARDED_BY(mMutex) = 0;

    nsecs_t mDropTime GUARDED_BY(mMutex) = 0;

    mutable std::mutex mMutex;

    // Bitmask for the type of jank

    int32_t mJankType GUARDED_BY(mMutex) = JankType::None;
@@ -359,6 +372,8 @@ public: 


    private:

        void dump(std::string& result, nsecs_t baseTime) const;

        void tracePredictions(pid_t surfaceFlingerPid) const;

        void traceActuals(pid_t surfaceFlingerPid) const;



        int64_t mToken = FrameTimelineInfo::INVALID_VSYNC_ID;

services/surfaceflinger/Layer.cpp

+1 −0
Original line number Diff line number Diff line
@@ -1560,6 +1560,7 @@ void Layer::setFrameTimelineVsyncForBufferlessTransaction(const FrameTimelineInf 


void Layer::addSurfaceFrameDroppedForBuffer(

        std::shared_ptr<frametimeline::SurfaceFrame>& surfaceFrame) {

    surfaceFrame->setDropTime(systemTime());

    surfaceFrame->setPresentState(PresentState::Dropped);

    mFlinger->mFrameTimeline->addSurfaceFrame(surfaceFrame);

}

services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp

+306 −125

File changed.

Preview size limit exceeded, changes collapsed.

services/surfaceflinger/tests/unittests/TransactionSurfaceFrameTest.cpp

+5 −0
Original line number Diff line number Diff line
@@ -157,8 +157,10 @@ public: 
        sp<Fence> fence2(new Fence());

        auto acquireFence2 = fenceFactory.createFenceTimeForTest(fence2);

        sp<GraphicBuffer> buffer2{new GraphicBuffer(1, 1, HAL_PIXEL_FORMAT_RGBA_8888, 1, 0)};

        nsecs_t start = systemTime();

        layer->setBuffer(buffer2, fence2, 10, 20, false, mClientCache, 1, std::nullopt,

                         {/*vsyncId*/ 1, /*inputEventId*/ 0});

        nsecs_t end = systemTime();

        acquireFence2->signalForTest(12);



        EXPECT_EQ(0u, layer->mCurrentState.bufferlessSurfaceFramesTX.size());
@@ -171,6 +173,9 @@ public: 


        EXPECT_EQ(1, droppedSurfaceFrame->getToken());

        EXPECT_EQ(PresentState::Dropped, droppedSurfaceFrame->getPresentState());

        EXPECT_EQ(0u, droppedSurfaceFrame->getActuals().endTime);

        auto dropTime = droppedSurfaceFrame->getDropTime();

        EXPECT_TRUE(dropTime > start && dropTime < end);



        EXPECT_EQ(1, presentedSurfaceFrame->getToken());

        EXPECT_EQ(PresentState::Presented, presentedSurfaceFrame->getPresentState());