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

Commit 57f8e18f authored by Ady Abraham's avatar Ady Abraham
Browse files

SF: use CLOCK_BOOTTIME for frame timeline 

Using CLOCK_BOOTTIME avoids the need to resync CLOCK_MONOTONIC in
perfetto after suspend.

Bug: 185346474
Test: Collect perfetto traces and observe timeline slices
Change-Id: Ifda1fb43c6ac205ec60cb331c139e950a24a60cb
parent a692e0fd

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+48 −34
Original line number Diff line number Diff line
@@ -618,15 +618,15 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, 
    }

}



void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {

void SurfaceFrame::tracePredictions(int64_t displayFrameToken, nsecs_t monoBootOffset) const {

    int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();



    // Expected 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);

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

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

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



        auto* event = packet->set_frame_timeline_event();

        auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
@@ -644,8 +644,8 @@ void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const { 
    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);

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

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

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



        auto* event = packet->set_frame_timeline_event();

        auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
@@ -654,14 +654,14 @@ void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const { 
    });

}



void SurfaceFrame::traceActuals(int64_t displayFrameToken) const {

void SurfaceFrame::traceActuals(int64_t displayFrameToken, nsecs_t monoBootOffset) 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);

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

        // 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
@@ -669,11 +669,12 @@ void SurfaceFrame::traceActuals(int64_t displayFrameToken) const { 
            // frame in the trace.

            nsecs_t endTime =

                    (mPresentState == PresentState::Dropped ? mDropTime : mActuals.endTime);

            packet->set_timestamp(

                    static_cast<uint64_t>(endTime - kPredictionExpiredStartTimeDelta));

            packet->set_timestamp(static_cast<uint64_t>(endTime - kPredictionExpiredStartTimeDelta +

                                                        monoBootOffset));

        } else {

            packet->set_timestamp(static_cast<uint64_t>(

                    mActuals.startTime == 0 ? mPredictions.startTime : mActuals.startTime));

            packet->set_timestamp(static_cast<uint64_t>(monoBootOffset + mActuals.startTime == 0

                                                                ? mPredictions.startTime

                                                                : mActuals.startTime));

        }



        auto* event = packet->set_frame_timeline_event();
@@ -706,11 +707,11 @@ void SurfaceFrame::traceActuals(int64_t displayFrameToken) const { 
    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);

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

        if (mPresentState == PresentState::Dropped) {

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

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

        } else {

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

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

        }



        auto* event = packet->set_frame_timeline_event();
@@ -723,7 +724,7 @@ void SurfaceFrame::traceActuals(int64_t displayFrameToken) const { 
/**

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

 */

void SurfaceFrame::trace(int64_t displayFrameToken) const {

void SurfaceFrame::trace(int64_t displayFrameToken, nsecs_t monoBootOffset) const {

    if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||

        displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {

        // No packets can be traced with a missing token.
@@ -732,9 +733,9 @@ void SurfaceFrame::trace(int64_t displayFrameToken) const { 
    if (getPredictionState() != PredictionState::Expired) {

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

        // a trace.

        tracePredictions(displayFrameToken);

        tracePredictions(displayFrameToken, monoBootOffset);

    }

    traceActuals(displayFrameToken);

    traceActuals(displayFrameToken, monoBootOffset);

}



namespace impl {
@@ -760,8 +761,9 @@ std::optional<TimelineItem> TokenManager::getPredictionsForToken(int64_t token) 
}



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

                             JankClassificationThresholds thresholds)

      : mMaxDisplayFrames(kDefaultMaxDisplayFrames),

                             JankClassificationThresholds thresholds, bool useBootTimeClock)

      : mUseBootTimeClock(useBootTimeClock),

        mMaxDisplayFrames(kDefaultMaxDisplayFrames),

        mTimeStats(std::move(timeStats)),

        mSurfaceFlingerPid(surfaceFlingerPid),

        mJankClassificationThresholds(thresholds) {
@@ -1016,14 +1018,16 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime, nsecs_t previous 
    }

}



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

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

                                                   nsecs_t monoBootOffset) const {

    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>(mSurfaceFlingerPredictions.startTime));

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

        packet->set_timestamp(

                static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime + monoBootOffset));



        auto* event = packet->set_frame_timeline_event();

        auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
@@ -1037,8 +1041,9 @@ void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) cons 
    // 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));

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

        packet->set_timestamp(

                static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime + monoBootOffset));



        auto* event = packet->set_frame_timeline_event();

        auto* expectedDisplayFrameEndEvent = event->set_frame_end();
@@ -1047,14 +1052,16 @@ void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) cons 
    });

}



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

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

                                               nsecs_t monoBootOffset) const {

    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_MONOTONIC);

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

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

        packet->set_timestamp(

                static_cast<uint64_t>(mSurfaceFlingerActuals.startTime + monoBootOffset));



        auto* event = packet->set_frame_timeline_event();

        auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
@@ -1075,8 +1082,9 @@ void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const { 
    // Actual 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.presentTime));

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

        packet->set_timestamp(

                static_cast<uint64_t>(mSurfaceFlingerActuals.presentTime + monoBootOffset));



        auto* event = packet->set_frame_timeline_event();

        auto* actualDisplayFrameEndEvent = event->set_frame_end();
@@ -1085,7 +1093,7 @@ void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const { 
    });

}



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

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

    if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {

        // DisplayFrame should not have an invalid token.

        ALOGE("Cannot trace DisplayFrame with invalid token");
@@ -1095,12 +1103,12 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const { 
    if (mPredictionState == PredictionState::Valid) {

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

        // meaningful way in a trace.

        tracePredictions(surfaceFlingerPid);

        tracePredictions(surfaceFlingerPid, monoBootOffset);

    }

    traceActuals(surfaceFlingerPid);

    traceActuals(surfaceFlingerPid, monoBootOffset);



    for (auto& surfaceFrame : mSurfaceFrames) {

        surfaceFrame->trace(mToken);

        surfaceFrame->trace(mToken, monoBootOffset);

    }

}
@@ -1164,6 +1172,12 @@ float FrameTimeline::computeFps(const std::unordered_set<int32_t>& layerIds) { 
}



void FrameTimeline::flushPendingPresentFences() {

    // Perfetto is using boottime clock to void drifts when the device goes

    // to suspend.

    const auto monoBootOffset = mUseBootTimeClock

            ? (systemTime(SYSTEM_TIME_BOOTTIME) - systemTime(SYSTEM_TIME_MONOTONIC))

            : 0;



    for (size_t i = 0; i < mPendingPresentFences.size(); i++) {

        const auto& pendingPresentFence = mPendingPresentFences[i];

        nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
@@ -1175,7 +1189,7 @@ void FrameTimeline::flushPendingPresentFences() { 
        }

        auto& displayFrame = pendingPresentFence.second;

        displayFrame->onPresent(signalTime, mPreviousPresentTime);

        displayFrame->trace(mSurfaceFlingerPid);

        displayFrame->trace(mSurfaceFlingerPid, monoBootOffset);

        mPreviousPresentTime = signalTime;



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

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+12 −9
Original line number Diff line number Diff line
@@ -204,8 +204,9 @@ public: 
    std::string miniDump() const;

    // 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) const;

    // DisplayFrame at the trace processor side. monoBootOffset is the difference

    // between SYSTEM_TIME_BOOTTIME and SYSTEM_TIME_MONOTONIC.

    void trace(int64_t displayFrameToken, nsecs_t monoBootOffset) const;



    // Getter functions used only by FrameTimelineTests and SurfaceFrame internally

    TimelineItem getActuals() const;
@@ -225,8 +226,8 @@ public: 
            std::chrono::duration_cast<std::chrono::nanoseconds>(2ms).count();



private:

    void tracePredictions(int64_t displayFrameToken) const;

    void traceActuals(int64_t displayFrameToken) const;

    void tracePredictions(int64_t displayFrameToken, nsecs_t monoBootOffset) const;

    void traceActuals(int64_t displayFrameToken, nsecs_t monoBootOffset) const;

    void classifyJankLocked(int32_t displayFrameJankType, const Fps& refreshRate,

                            nsecs_t& deadlineDelta) REQUIRES(mMutex);
@@ -369,8 +370,9 @@ public: 
        // Dumpsys interface - dumps all data irrespective of jank

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

        // Emits a packet for perfetto tracing. The function body will be executed only if tracing

        // is enabled.

        void trace(pid_t surfaceFlingerPid) const;

        // is enabled. monoBootOffset is the difference between SYSTEM_TIME_BOOTTIME

        // and SYSTEM_TIME_MONOTONIC.

        void trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;

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

        void onSfWakeUp(int64_t token, Fps refreshRate, std::optional<TimelineItem> predictions,

                        nsecs_t wakeUpTime);
@@ -401,8 +403,8 @@ public: 


    private:

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

        void tracePredictions(pid_t surfaceFlingerPid) const;

        void traceActuals(pid_t surfaceFlingerPid) const;

        void tracePredictions(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;

        void traceActuals(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;

        void classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,

                          nsecs_t previousPresentTime);
@@ -442,7 +444,7 @@ public: 
    };



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

                  JankClassificationThresholds thresholds = {});

                  JankClassificationThresholds thresholds = {}, bool useBootTimeClock = true);

    ~FrameTimeline() = default;



    frametimeline::TokenManager* getTokenManager() override { return &mTokenManager; }
@@ -484,6 +486,7 @@ private: 
    TokenManager mTokenManager;

    TraceCookieCounter mTraceCookieCounter;

    mutable std::mutex mMutex;

    const bool mUseBootTimeClock;

    uint32_t mMaxDisplayFrames;

    std::shared_ptr<TimeStats> mTimeStats;

    const pid_t mSurfaceFlingerPid;

services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp

+2 −1
Original line number Diff line number Diff line
@@ -66,9 +66,10 @@ public: 
    }



    void SetUp() override {

        constexpr bool kUseBootTimeClock = true;

        mTimeStats = std::make_shared<mock::TimeStats>();

        mFrameTimeline = std::make_unique<impl::FrameTimeline>(mTimeStats, kSurfaceFlingerPid,

                                                               kTestThresholds);

                                                               kTestThresholds, !kUseBootTimeClock);

        mFrameTimeline->registerDataSource();

        mTokenManager = &mFrameTimeline->mTokenManager;

        mTraceCookieCounter = &mFrameTimeline->mTraceCookieCounter;