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

Commit 05bd2d11 authored by Adithya Srinivasan's avatar Adithya Srinivasan
Browse files

Send FrameTimeline packets as separate start and end messages 

To avoid scoped slices, the FrameTimelineEvent proto was updated to
contain separate Start and End messages for SurfaceFrame and
DisplayFrame. This change updates the platform to send packets according
to the new proto.

Bug: 173426914
Test: libsurfaceflinger_unittest
Change-Id: I678f5b2b94109409b57d2ac61db704f77d149c76
parent 54263095

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+143 −49
Original line number Diff line number Diff line
@@ -239,11 +239,16 @@ nsecs_t getMinTime(PredictionState predictionState, TimelineItem predictions, 
    return minTime;

}



int64_t TraceCookieCounter::getCookieForTracing() {

    return ++mTraceCookie;

}



SurfaceFrame::SurfaceFrame(int64_t token, pid_t ownerPid, uid_t ownerUid, std::string layerName,

                           std::string debugName, PredictionState predictionState,

                           frametimeline::TimelineItem&& predictions,

                           std::shared_ptr<TimeStats> timeStats,

                           JankClassificationThresholds thresholds)

                           JankClassificationThresholds thresholds,

                           TraceCookieCounter* traceCookieCounter)

      : mToken(token),

        mOwnerPid(ownerPid),

        mOwnerUid(ownerUid),
@@ -254,7 +259,8 @@ SurfaceFrame::SurfaceFrame(int64_t token, pid_t ownerPid, uid_t ownerUid, std::s 
        mPredictions(predictions),

        mActuals({0, 0, 0}),

        mTimeStats(timeStats),

        mJankClassificationThresholds(thresholds) {}

        mJankClassificationThresholds(thresholds),

        mTraceCookieCounter(*traceCookieCounter) {}



void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {

    std::lock_guard<std::mutex> lock(mMutex);
@@ -443,7 +449,7 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, 


void SurfaceFrame::trace(int64_t displayFrameToken) {

    using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;

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

    {

        std::lock_guard<std::mutex> lock(mMutex);

        if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {

            ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());
@@ -453,36 +459,83 @@ void SurfaceFrame::trace(int64_t displayFrameToken) { 
                  mLayerName.c_str());

            return;

        }

    }



    int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();

    // Expected timeline start

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

        std::lock_guard<std::mutex> lock(mMutex);

        auto packet = ctx.NewTracePacket();

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

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

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



        auto* event = packet->set_frame_timeline_event();

        auto* surfaceFrameEvent = event->set_surface_frame();

        auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();



        expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);



        surfaceFrameEvent->set_token(mToken);

        surfaceFrameEvent->set_display_frame_token(displayFrameToken);

        expectedSurfaceFrameStartEvent->set_token(mToken);

        expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);



        expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);

        expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);

    });

    // Expected timeline end

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

        std::lock_guard<std::mutex> lock(mMutex);

        auto packet = ctx.NewTracePacket();

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

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



        auto* event = packet->set_frame_timeline_event();

        auto* expectedSurfaceFrameEndEvent = event->set_frame_end();



        expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);

    });



    int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();

    // Actual timeline start

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

        std::lock_guard<std::mutex> 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

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



        auto* event = packet->set_frame_timeline_event();

        auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();



        actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);



        actualSurfaceFrameStartEvent->set_token(mToken);

        actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);



        actualSurfaceFrameStartEvent->set_pid(mOwnerPid);

        actualSurfaceFrameStartEvent->set_layer_name(mDebugName);



        if (mPresentState == PresentState::Dropped) {

            surfaceFrameEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);

            actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);

        } else if (mPresentState == PresentState::Unknown) {

            surfaceFrameEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);

            actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);

        } else {

            surfaceFrameEvent->set_present_type(toProto(mFramePresentMetadata));

            actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));

        }

        surfaceFrameEvent->set_on_time_finish(mFrameReadyMetadata ==

        actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==

                                                         FrameReadyMetadata::OnTimeFinish);

        surfaceFrameEvent->set_gpu_composition(mGpuComposition);

        surfaceFrameEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));



        surfaceFrameEvent->set_expected_start_ns(mPredictions.startTime);

        surfaceFrameEvent->set_expected_end_ns(mPredictions.endTime);

        actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);

        actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));

    });

    // Actual timeline end

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

        std::lock_guard<std::mutex> lock(mMutex);

        auto packet = ctx.NewTracePacket();

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

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



        surfaceFrameEvent->set_actual_start_ns(mActuals.startTime);

        surfaceFrameEvent->set_actual_end_ns(mActuals.endTime);

        auto* event = packet->set_frame_timeline_event();

        auto* actualSurfaceFrameEndEvent = event->set_frame_end();



        surfaceFrameEvent->set_layer_name(mDebugName);

        surfaceFrameEvent->set_pid(mOwnerPid);

        actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);

    });

}
@@ -520,11 +573,13 @@ void TokenManager::flushTokens(nsecs_t flushTime) { 


FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,

                             JankClassificationThresholds thresholds)

      : mCurrentDisplayFrame(std::make_shared<DisplayFrame>(timeStats, thresholds)),

        mMaxDisplayFrames(kDefaultMaxDisplayFrames),

      : mMaxDisplayFrames(kDefaultMaxDisplayFrames),

        mTimeStats(std::move(timeStats)),

        mSurfaceFlingerPid(surfaceFlingerPid),

        mJankClassificationThresholds(thresholds) {}

        mJankClassificationThresholds(thresholds) {

    mCurrentDisplayFrame =

            std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);

}



void FrameTimeline::onBootFinished() {

    perfetto::TracingInitArgs args;
@@ -547,27 +602,29 @@ std::shared_ptr<SurfaceFrame> FrameTimeline::createSurfaceFrameForToken( 
        return std::make_shared<SurfaceFrame>(ISurfaceComposer::INVALID_VSYNC_ID, ownerPid,

                                              ownerUid, std::move(layerName), std::move(debugName),

                                              PredictionState::None, TimelineItem(), mTimeStats,

                                              mJankClassificationThresholds);

                                              mJankClassificationThresholds, &mTraceCookieCounter);

    }

    std::optional<TimelineItem> predictions = mTokenManager.getPredictionsForToken(*token);

    if (predictions) {

        return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),

                                              std::move(debugName), PredictionState::Valid,

                                              std::move(*predictions), mTimeStats,

                                              mJankClassificationThresholds);

                                              mJankClassificationThresholds, &mTraceCookieCounter);

    }

    return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),

                                          std::move(debugName), PredictionState::Expired,

                                          TimelineItem(), mTimeStats,

                                          mJankClassificationThresholds);

                                          TimelineItem(), mTimeStats, mJankClassificationThresholds,

                                          &mTraceCookieCounter);

}



FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,

                                          JankClassificationThresholds thresholds)

                                          JankClassificationThresholds thresholds,

                                          TraceCookieCounter* traceCookieCounter)

      : mSurfaceFlingerPredictions(TimelineItem()),

        mSurfaceFlingerActuals(TimelineItem()),

        mTimeStats(timeStats),

        mJankClassificationThresholds(thresholds) {

        mJankClassificationThresholds(thresholds),

        mTraceCookieCounter(*traceCookieCounter) {

    mSurfaceFrames.reserve(kNumSurfaceFramesInitial);

}
@@ -725,32 +782,69 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { 
}



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

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

    if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {

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

        return;

    }



    int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();

    // Expected timeline start

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

        auto packet = ctx.NewTracePacket();

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

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

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



        auto* event = packet->set_frame_timeline_event();

        auto* displayFrameEvent = event->set_display_frame();

        auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();



        displayFrameEvent->set_token(mToken);

        displayFrameEvent->set_present_type(toProto(mFramePresentMetadata));

        displayFrameEvent->set_on_time_finish(mFrameReadyMetadata ==

                                              FrameReadyMetadata::OnTimeFinish);

        displayFrameEvent->set_gpu_composition(mGpuComposition);

        displayFrameEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));

        expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);



        expectedDisplayFrameStartEvent->set_token(mToken);

        expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);

    });

    // Expected timeline end

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

        auto packet = ctx.NewTracePacket();

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

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



        auto* event = packet->set_frame_timeline_event();

        auto* expectedDisplayFrameEndEvent = event->set_frame_end();



        displayFrameEvent->set_expected_start_ns(mSurfaceFlingerPredictions.startTime);

        displayFrameEvent->set_expected_end_ns(mSurfaceFlingerPredictions.endTime);

        expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);

    });



        displayFrameEvent->set_actual_start_ns(mSurfaceFlingerActuals.startTime);

        displayFrameEvent->set_actual_end_ns(mSurfaceFlingerActuals.endTime);

    int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();

    // Expected timeline start

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

        auto packet = ctx.NewTracePacket();

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

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



        displayFrameEvent->set_pid(surfaceFlingerPid);

        auto* event = packet->set_frame_timeline_event();

        auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();



        actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);



        actualDisplayFrameStartEvent->set_token(mToken);

        actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);



        actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));

        actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==

                                                         FrameReadyMetadata::OnTimeFinish);

        actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);

        actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));

    });

    // Expected timeline end

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

        auto packet = ctx.NewTracePacket();

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

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



        auto* event = packet->set_frame_timeline_event();

        auto* actualDisplayFrameEndEvent = event->set_frame_end();



        actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);

    });



    for (auto& surfaceFrame : mSurfaceFrames) {
@@ -786,8 +880,8 @@ void FrameTimeline::finalizeCurrentDisplayFrame() { 
    }

    mDisplayFrames.push_back(mCurrentDisplayFrame);

    mCurrentDisplayFrame.reset();

    mCurrentDisplayFrame =

            std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds);

    mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,

                                                          &mTraceCookieCounter);

}



nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+29 −2
Original line number Diff line number Diff line
@@ -127,6 +127,23 @@ enum class PredictionState { 
    None,    // Predictions are either not present or didn't come from TokenManager

};



/*

 * Trace cookie is used to send start and end timestamps of <Surface/Display>Frames separately

 * without needing to resend all the other information. We send all info to perfetto, along with a

 * new cookie, in the start of a frame. For the corresponding end, we just send the same cookie.

 * This helps in reducing the amount of data emitted by the producer.

 */

class TraceCookieCounter {

public:

    int64_t getCookieForTracing();



private:

    // Friend class for testing

    friend class android::frametimeline::FrameTimelineTest;



    std::atomic<int64_t> mTraceCookie = 0;

};



class SurfaceFrame {

public:

    enum class PresentState {
@@ -139,7 +156,8 @@ public: 
    // TokenManager), Thresholds and TimeStats pointer.

    SurfaceFrame(int64_t token, pid_t ownerPid, uid_t ownerUid, std::string layerName,

                 std::string debugName, PredictionState predictionState, TimelineItem&& predictions,

                 std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds);

                 std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds,

                 TraceCookieCounter* traceCookieCounter);

    ~SurfaceFrame() = default;



    // Returns std::nullopt if the frame hasn't been classified yet.
@@ -205,6 +223,9 @@ private: 
    // for BufferStuffing where the current buffer is expected to be ready but the previous buffer

    // was latched instead.

    nsecs_t mLastLatchTime GUARDED_BY(mMutex) = 0;

    // TraceCookieCounter is used to obtain the cookie for sendig trace packets to perfetto. Using a

    // reference here because the counter is owned by FrameTimeline, which outlives SurfaceFrame.

    TraceCookieCounter& mTraceCookieCounter;

};



/*
@@ -291,7 +312,8 @@ public: 
     */

    class DisplayFrame {

    public:

        DisplayFrame(std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds);

        DisplayFrame(std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds,

                     TraceCookieCounter* traceCookieCounter);

        virtual ~DisplayFrame() = default;

        // Dumpsys interface - dumps only if the DisplayFrame itself is janky or is at least one

        // SurfaceFrame is janky.
@@ -360,6 +382,10 @@ public: 
        // The refresh rate (vsync period) in nanoseconds as seen by SF during this DisplayFrame's

        // timeline

        nsecs_t mVsyncPeriod = 0;

        // TraceCookieCounter is used to obtain the cookie for sendig trace packets to perfetto.

        // Using a reference here because the counter is owned by FrameTimeline, which outlives

        // DisplayFrame.

        TraceCookieCounter& mTraceCookieCounter;

    };



    FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
@@ -402,6 +428,7 @@ private: 
            mPendingPresentFences GUARDED_BY(mMutex);

    std::shared_ptr<DisplayFrame> mCurrentDisplayFrame GUARDED_BY(mMutex);

    TokenManager mTokenManager;

    TraceCookieCounter mTraceCookieCounter;

    mutable std::mutex mMutex;

    uint32_t mMaxDisplayFrames;

    std::shared_ptr<TimeStats> mTimeStats;

services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp

+225 −106

File changed.

Preview size limit exceeded, changes collapsed.