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

Commit 363faf0f authored by Alec Mouri's avatar Alec Mouri
Browse files

Add deadline histograms into timestats 

* SF deadline histogram
* Present time jitter histogram
* app deadline histogram

Histograms are only incremented if the associated (actual - predicted)
deltas are positive and jank is reported by the timeline.

Bug: 178003475
Test: builds, boots
Change-Id: Ic348cf9f2ed8d4e30bd0b26835cc0abf22cedfb2
parent 7d436ecf

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+12 −5
Original line number Diff line number Diff line
@@ -399,10 +399,10 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t 
    dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);

}



void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate) {

void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,

                             nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) {

    std::scoped_lock lock(mMutex);



    const Fps renderRate = mRenderRate ? *mRenderRate : refreshRate;

    if (mPresentState != PresentState::Presented) {

        // No need to update dropped buffers

        return;
@@ -421,7 +421,10 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, 
        mJankType = JankType::Unknown;

        mFramePresentMetadata = FramePresentMetadata::UnknownPresent;

        mFrameReadyMetadata = FrameReadyMetadata::UnknownFinish;

        mTimeStats->incrementJankyFrames(refreshRate, renderRate, mOwnerUid, mLayerName, mJankType);

        const constexpr nsecs_t kAppDeadlineDelta = -1;

        mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName,

                                          mJankType, displayDeadlineDelta, displayPresentDelta,

                                          kAppDeadlineDelta});

        return;

    }
@@ -493,7 +496,8 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, 
            }

        }

    }

    mTimeStats->incrementJankyFrames(refreshRate, renderRate, mOwnerUid, mLayerName, mJankType);

    mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName, mJankType,

                                      displayDeadlineDelta, displayPresentDelta, deadlineDelta});

}



/**
@@ -750,6 +754,9 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { 
    // Delta between the expected present and the actual present

    const nsecs_t presentDelta =

            mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime;

    const nsecs_t deadlineDelta =

            mSurfaceFlingerActuals.endTime - mSurfaceFlingerPredictions.endTime;



    // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there

    // was a prediction error or not.

    nsecs_t deltaToVsync = std::abs(presentDelta) % mRefreshRate.getPeriodNsecs();
@@ -825,7 +832,7 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { 
        }

    }

    for (auto& surfaceFrame : mSurfaceFrames) {

        surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate);

        surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync);

    }

}

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+4 −1
Original line number Diff line number Diff line
@@ -183,7 +183,10 @@ public: 
    // Used for dumping all timestamps relative to the oldest, making it easy to read.

    nsecs_t getBaseTime() const;

    // Sets the actual present time, appropriate metadata and classifies the jank.

    void onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate);

    // displayRefreshRate, displayDeadlineDelta, and displayPresentDelta are propagated from the

    // display frame.

    void onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate,

                   nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta);

    // All the timestamps are dumped relative to the baseTime

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

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

services/surfaceflinger/TimeStats/TimeStats.cpp

+40 −28
Original line number Diff line number Diff line
@@ -147,17 +147,17 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateGlobalAtom(AStatsEventLi 
        mStatsDelegate->statsEventWriteInt32(event, 0); // total_jank_frames_app_buffer_stuffing

        mStatsDelegate->statsEventWriteInt32(event, globalSlice.first.displayRefreshRateBucket);

        std::string sfDeadlineMissedBytes =

                histogramToProtoByteString(std::unordered_map<int32_t, int32_t>(),

                histogramToProtoByteString(globalSlice.second.displayDeadlineDeltas.hist,

                                           mMaxPulledHistogramBuckets);

        mStatsDelegate

                ->statsEventWriteByteArray(event, (const uint8_t*)sfDeadlineMissedBytes.c_str(),

                                           sfDeadlineMissedBytes.size()); // sf_deadline_misses

        mStatsDelegate->statsEventWriteByteArray(event,

                                                 (const uint8_t*)sfDeadlineMissedBytes.c_str(),

                                                 sfDeadlineMissedBytes.size());

        std::string sfPredictionErrorBytes =

                histogramToProtoByteString(std::unordered_map<int32_t, int32_t>(),

                histogramToProtoByteString(globalSlice.second.displayPresentDeltas.hist,

                                           mMaxPulledHistogramBuckets);

        mStatsDelegate

                ->statsEventWriteByteArray(event, (const uint8_t*)sfPredictionErrorBytes.c_str(),

                                           sfPredictionErrorBytes.size()); // sf_prediction_errors

        mStatsDelegate->statsEventWriteByteArray(event,

                                                 (const uint8_t*)sfPredictionErrorBytes.c_str(),

                                                 sfPredictionErrorBytes.size());

        mStatsDelegate->statsEventWriteInt32(event, globalSlice.first.renderRateBucket);

        mStatsDelegate->statsEventBuild(event);

    }
@@ -170,7 +170,7 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateGlobalAtom(AStatsEventLi 
AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventList* data) {

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



    std::vector<TimeStatsHelper::TimeStatsLayer const*> dumpStats;

    std::vector<TimeStatsHelper::TimeStatsLayer*> dumpStats;

    uint32_t numLayers = 0;

    for (const auto& globalSlice : mTimeStats.stats) {

        numLayers += globalSlice.second.stats.size();
@@ -178,8 +178,8 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventLis 


    dumpStats.reserve(numLayers);



    for (const auto& globalSlice : mTimeStats.stats) {

        for (const auto& layerSlice : globalSlice.second.stats) {

    for (auto& globalSlice : mTimeStats.stats) {

        for (auto& layerSlice : globalSlice.second.stats) {

            dumpStats.push_back(&layerSlice.second);

        }

    }
@@ -194,7 +194,7 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventLis 
        dumpStats.resize(mMaxPulledLayers);

    }



    for (const auto& layer : dumpStats) {

    for (auto& layer : dumpStats) {

        AStatsEvent* event = mStatsDelegate->addStatsEventToPullData(data);

        mStatsDelegate->statsEventSetAtomId(event, android::util::SURFACEFLINGER_STATS_LAYER_INFO);

        mStatsDelegate->statsEventWriteString8(event, layer->layerName.c_str());
@@ -234,11 +234,11 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventLis 
        mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)frameRateVoteBytes.c_str(),

                                                 frameRateVoteBytes.size()); // set_frame_rate_vote

        std::string appDeadlineMissedBytes =

                histogramToProtoByteString(std::unordered_map<int32_t, int32_t>(),

                histogramToProtoByteString(layer->deltas["appDeadlineDeltas"].hist,

                                           mMaxPulledHistogramBuckets);

        mStatsDelegate

                ->statsEventWriteByteArray(event, (const uint8_t*)appDeadlineMissedBytes.c_str(),

                                           appDeadlineMissedBytes.size()); // app_deadline_misses

        mStatsDelegate->statsEventWriteByteArray(event,

                                                 (const uint8_t*)appDeadlineMissedBytes.c_str(),

                                                 appDeadlineMissedBytes.size());



        mStatsDelegate->statsEventBuild(event);

    }
@@ -772,13 +772,14 @@ void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber, 
    flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate);

}



static const constexpr int32_t kValidJankyReason = JankType::SurfaceFlingerCpuDeadlineMissed |

        JankType::SurfaceFlingerGpuDeadlineMissed | JankType::AppDeadlineMissed |

        JankType::DisplayHAL;



template <class T>

static void updateJankPayload(T& t, int32_t reasons) {

    t.jankPayload.totalFrames++;



    static const constexpr int32_t kValidJankyReason = JankType::SurfaceFlingerCpuDeadlineMissed |

            JankType::SurfaceFlingerGpuDeadlineMissed | JankType::AppDeadlineMissed |

            JankType::DisplayHAL;

    if (reasons & kValidJankyReason) {

        t.jankPayload.totalJankyFrames++;

        if ((reasons & JankType::SurfaceFlingerCpuDeadlineMissed) != 0) {
@@ -796,8 +797,7 @@ static void updateJankPayload(T& t, int32_t reasons) { 
    }

}



void TimeStats::incrementJankyFrames(Fps refreshRate, std::optional<Fps> renderRate, uid_t uid,

                                     const std::string& layerName, int32_t reasons) {

void TimeStats::incrementJankyFrames(const JankyFramesInfo& info) {

    if (!mEnabled.load()) return;



    ATRACE_CALL();
@@ -816,9 +816,11 @@ void TimeStats::incrementJankyFrames(Fps refreshRate, std::optional<Fps> renderR 


    static const std::string kDefaultLayerName = "none";



    const int32_t refreshRateBucket = clampToSmallestBucket(refreshRate, REFRESH_RATE_BUCKET_WIDTH);

    const int32_t refreshRateBucket =

            clampToSmallestBucket(info.refreshRate, REFRESH_RATE_BUCKET_WIDTH);

    const int32_t renderRateBucket =

            clampToSmallestBucket(renderRate ? *renderRate : refreshRate, RENDER_RATE_BUCKET_WIDTH);

            clampToSmallestBucket(info.renderRate ? *info.renderRate : info.refreshRate,

                                  RENDER_RATE_BUCKET_WIDTH);

    const TimeStatsHelper::TimelineStatsKey timelineKey = {refreshRateBucket, renderRateBucket};



    if (!mTimeStats.stats.count(timelineKey)) {
@@ -827,19 +829,29 @@ void TimeStats::incrementJankyFrames(Fps refreshRate, std::optional<Fps> renderR 


    TimeStatsHelper::TimelineStats& timelineStats = mTimeStats.stats[timelineKey];



    updateJankPayload<TimeStatsHelper::TimelineStats>(timelineStats, reasons);

    updateJankPayload<TimeStatsHelper::TimelineStats>(timelineStats, info.reasons);



    TimeStatsHelper::LayerStatsKey layerKey = {uid, layerName};

    TimeStatsHelper::LayerStatsKey layerKey = {info.uid, info.layerName};

    if (!timelineStats.stats.count(layerKey)) {

        layerKey = {uid, kDefaultLayerName};

        layerKey = {info.uid, kDefaultLayerName};

        timelineStats.stats[layerKey].displayRefreshRateBucket = refreshRateBucket;

        timelineStats.stats[layerKey].renderRateBucket = renderRateBucket;

        timelineStats.stats[layerKey].uid = uid;

        timelineStats.stats[layerKey].uid = info.uid;

        timelineStats.stats[layerKey].layerName = kDefaultLayerName;

    }



    TimeStatsHelper::TimeStatsLayer& timeStatsLayer = timelineStats.stats[layerKey];

    updateJankPayload<TimeStatsHelper::TimeStatsLayer>(timeStatsLayer, reasons);

    updateJankPayload<TimeStatsHelper::TimeStatsLayer>(timeStatsLayer, info.reasons);



    if (info.reasons & kValidJankyReason) {

        // TimeStats Histograms only retain positive values, so we don't need to check if these

        // deadlines were really missed if we know that the frame had jank, since deadlines

        // that were met will be dropped.

        timelineStats.displayDeadlineDeltas.insert(static_cast<int32_t>(info.displayDeadlineDelta));

        timelineStats.displayPresentDeltas.insert(static_cast<int32_t>(info.displayPresentJitter));

        timeStatsLayer.deltas["appDeadlineDeltas"].insert(

                static_cast<int32_t>(info.appDeadlineDelta));

    }

}



void TimeStats::onDestroy(int32_t layerId) {

services/surfaceflinger/TimeStats/TimeStats.h

+44 −6
Original line number Diff line number Diff line
@@ -121,10 +121,48 @@ public: 
    // from FrameTimeline, rather than directly from SurfaceFlinger or individual layers. If there

    // are no jank reasons, then total frames are incremented but jank is not, for accurate

    // accounting of janky frames.

    // When these frame counts are incremented, these are also aggregated into a global reporting

    // packet to help with data validation and assessing of overall device health.

    virtual void incrementJankyFrames(Fps refreshRate, std::optional<Fps> renderRate, uid_t uid,

                                      const std::string& layerName, int32_t reasons) = 0;

    // displayDeadlineDelta, displayPresentJitter, and appDeadlineDelta are also provided in order

    // to provide contextual information about a janky frame. These values may only be uploaded if

    // there was an associated valid jank reason, and they must be positive. When these frame counts

    // are incremented, these are also aggregated into a global reporting packet to help with data

    // validation and assessing of overall device health.

    struct JankyFramesInfo {

        Fps refreshRate;

        std::optional<Fps> renderRate;

        uid_t uid = 0;

        std::string layerName;

        int32_t reasons = 0;

        nsecs_t displayDeadlineDelta = 0;

        nsecs_t displayPresentJitter = 0;

        nsecs_t appDeadlineDelta = 0;



        bool operator==(const JankyFramesInfo& o) const {

            return Fps::EqualsInBuckets{}(refreshRate, o.refreshRate) &&

                    ((renderRate == std::nullopt && o.renderRate == std::nullopt) ||

                     (renderRate != std::nullopt && o.renderRate != std::nullopt &&

                      Fps::EqualsInBuckets{}(*renderRate, *o.renderRate))) &&

                    uid == o.uid && layerName == o.layerName && reasons == o.reasons &&

                    displayDeadlineDelta == o.displayDeadlineDelta &&

                    displayPresentJitter == o.displayPresentJitter &&

                    appDeadlineDelta == o.appDeadlineDelta;

        }



        friend std::ostream& operator<<(std::ostream& os, const JankyFramesInfo& info) {

            os << "JankyFramesInfo {";

            os << "\n    .refreshRate = " << info.refreshRate;

            os << "\n    .renderRate = "

               << (info.renderRate ? to_string(*info.renderRate) : "nullopt");

            os << "\n    .uid = " << info.uid;

            os << "\n    .layerName = " << info.layerName;

            os << "\n    .reasons = " << info.reasons;

            os << "\n    .displayDeadlineDelta = " << info.displayDeadlineDelta;

            os << "\n    .displayPresentJitter = " << info.displayPresentJitter;

            os << "\n    .appDeadlineDelta = " << info.appDeadlineDelta;

            return os << "\n}";

        }

    };



    virtual void incrementJankyFrames(const JankyFramesInfo& info) = 0;

    // Clean up the layer record

    virtual void onDestroy(int32_t layerId) = 0;

    // If SF skips or rejects a buffer, remove the corresponding TimeRecord.
@@ -273,8 +311,8 @@ public: 
    void setPresentFence(int32_t layerId, uint64_t frameNumber,

                         const std::shared_ptr<FenceTime>& presentFence, Fps displayRefreshRate,

                         std::optional<Fps> renderRate) override;

    void incrementJankyFrames(Fps refreshRate, std::optional<Fps> renderRate, uid_t uid,

                              const std::string& layerName, int32_t reasons) override;



    void incrementJankyFrames(const JankyFramesInfo& info) override;

    // Clean up the layer record

    void onDestroy(int32_t layerId) override;

    // If SF skips or rejects a buffer, remove the corresponding TimeRecord.

services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp

+5 −1
Original line number Diff line number Diff line
@@ -41,7 +41,7 @@ void TimeStatsHelper::Histogram::insert(int32_t delta) { 
    if (delta < 0) return;

    // std::lower_bound won't work on out of range values

    if (delta > histogramConfig[HISTOGRAM_SIZE - 1]) {

        hist[histogramConfig[HISTOGRAM_SIZE - 1]] += delta / histogramConfig[HISTOGRAM_SIZE - 1];

        hist[histogramConfig[HISTOGRAM_SIZE - 1]]++;

        return;

    }

    auto iter = std::lower_bound(histogramConfig.begin(), histogramConfig.end(), delta);
@@ -154,6 +154,10 @@ std::string TimeStatsHelper::TimeStatsGlobal::toString(std::optional<uint32_t> m 
                      ele.second.key.displayRefreshRateBucket);

        StringAppendF(&result, "renderRate = %d fps\n", ele.second.key.renderRateBucket);

        result.append(ele.second.jankPayload.toString());

        StringAppendF(&result, "sfDeadlineMisses histogram is as below:\n");

        result.append(ele.second.displayDeadlineDeltas.toString());

        StringAppendF(&result, "sfPredictionErrors histogram is as below:\n");

        result.append(ele.second.displayPresentDeltas.toString());

    }



    const auto dumpStats = generateDumpStats(maxLayers);