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

Commit 8fc601d6 authored by Adithya Srinivasan's avatar Adithya Srinivasan
Browse files

Dumpsys for FrameTimeline 

Create a dumpsys interface for dumping the Display Frames and
SurfaceFrames stored within FrameTimeline. This change also adds
jankType and jankMetadata fields to SurfaceFrames and DisplayFrames to
classify the jank.

Bug: 162889501
Test: adb shell dumpsys SurfaceFlinger --frametimeline [-jank|-all]
Change-Id: Iac8c8377cf2039e982f59e6d45f7e88a42613154
parent aa4bbda7

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+321 −40
Original line number Diff line number Diff line
@@ -22,12 +22,127 @@ 
#include <android-base/stringprintf.h>

#include <utils/Log.h>

#include <utils/Trace.h>

#include <chrono>

#include <cinttypes>

#include <numeric>



namespace android::frametimeline::impl {



using base::StringAppendF;



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

               const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {

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

    StringAppendF(&result, "\t\t");

    StringAppendF(&result, "    Start time\t\t|");

    StringAppendF(&result, "    End time\t\t|");

    StringAppendF(&result, "    Present time\n");

    if (predictionState == PredictionState::Valid) {

        // Dump the Predictions only if they are valid

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

        StringAppendF(&result, "Expected\t|");

        std::chrono::nanoseconds startTime(predictions.startTime - baseTime);

        std::chrono::nanoseconds endTime(predictions.endTime - baseTime);

        std::chrono::nanoseconds presentTime(predictions.presentTime - baseTime);

        StringAppendF(&result, "\t%10.2f\t|\t%10.2f\t|\t%10.2f\n",

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

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

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

    }

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

    StringAppendF(&result, "Actual  \t|");



    if (actuals.startTime == 0) {

        StringAppendF(&result, "\t\tN/A\t|");

    } else {

        std::chrono::nanoseconds startTime(std::max<nsecs_t>(0, actuals.startTime - baseTime));

        StringAppendF(&result, "\t%10.2f\t|",

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

    }

    if (actuals.endTime == 0) {

        StringAppendF(&result, "\t\tN/A\t|");

    } else {

        std::chrono::nanoseconds endTime(actuals.endTime - baseTime);

        StringAppendF(&result, "\t%10.2f\t|",

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

    }

    if (actuals.presentTime == 0) {

        StringAppendF(&result, "\t\tN/A\n");

    } else {

        std::chrono::nanoseconds presentTime(std::max<nsecs_t>(0, actuals.presentTime - baseTime));

        StringAppendF(&result, "\t%10.2f\n",

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

    }



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

    StringAppendF(&result, "----------------------");

    StringAppendF(&result, "----------------------");

    StringAppendF(&result, "----------------------");

    StringAppendF(&result, "----------------------\n");

}



std::string toString(PredictionState predictionState) {

    switch (predictionState) {

        case PredictionState::Valid:

            return "Valid";

        case PredictionState::Expired:

            return "Expired";

        case PredictionState::None:

        default:

            return "None";

    }

}



std::string toString(JankType jankType) {

    switch (jankType) {

        case JankType::None:

            return "None";

        case JankType::Display:

            return "Composer/Display - outside SF and App";

        case JankType::SurfaceFlingerDeadlineMissed:

            return "SurfaceFlinger Deadline Missed";

        case JankType::AppDeadlineMissed:

            return "App Deadline Missed";

        case JankType::PredictionExpired:

            return "Prediction Expired";

        case JankType::SurfaceFlingerEarlyLatch:

            return "SurfaceFlinger Early Latch";

        default:

            return "Unclassified";

    }

}



std::string jankMetadataBitmaskToString(int32_t jankMetadata) {

    std::vector<std::string> jankInfo;



    if (jankMetadata & EarlyStart) {

        jankInfo.emplace_back("Early Start");

    } else if (jankMetadata & LateStart) {

        jankInfo.emplace_back("Late Start");

    }



    if (jankMetadata & EarlyFinish) {

        jankInfo.emplace_back("Early Finish");

    } else if (jankMetadata & LateFinish) {

        jankInfo.emplace_back("Late Finish");

    }



    if (jankMetadata & EarlyPresent) {

        jankInfo.emplace_back("Early Present");

    } else if (jankMetadata & LatePresent) {

        jankInfo.emplace_back("Late Present");

    }

    // TODO(b/169876734): add GPU composition metadata here



    if (jankInfo.empty()) {

        return "None";

    }

    return std::accumulate(jankInfo.begin(), jankInfo.end(), std::string(),

                           [](const std::string& l, const std::string& r) {

                               return l.empty() ? r : l + ", " + r;

                           });

}



int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {

    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
@@ -69,29 +184,26 @@ SurfaceFrame::SurfaceFrame(const std::string& layerName, PredictionState predict 
        mPredictionState(predictionState),

        mPredictions(predictions),

        mActuals({0, 0, 0}),

        mActualQueueTime(0) {}

        mActualQueueTime(0),

        mJankType(JankType::None),

        mJankMetadata(0) {}



void SurfaceFrame::setPresentState(PresentState state) {

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

    mPresentState = state;

}



PredictionState SurfaceFrame::getPredictionState() {

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

    return mPredictionState;

}



SurfaceFrame::PresentState SurfaceFrame::getPresentState() {

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

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

    return mPresentState;

}



TimelineItem SurfaceFrame::getActuals() {

TimelineItem SurfaceFrame::getActuals() const {

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

    return mActuals;

}



nsecs_t SurfaceFrame::getActualQueueTime() {

nsecs_t SurfaceFrame::getActualQueueTime() const {

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

    return mActualQueueTime;

}
@@ -115,17 +227,62 @@ void SurfaceFrame::setActualPresentTime(nsecs_t presentTime) { 
    mActuals.presentTime = presentTime;

}



void SurfaceFrame::dump(std::string& result) {

void SurfaceFrame::setJankInfo(JankType jankType, int32_t jankMetadata) {

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

    mJankType = jankType;

    mJankMetadata = jankMetadata;

}



JankType SurfaceFrame::getJankType() const {

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

    return mJankType;

}



nsecs_t SurfaceFrame::getBaseTime() const {

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

    nsecs_t baseTime = std::numeric_limits<nsecs_t>::max();

    if (mPredictionState == PredictionState::Valid) {

        baseTime = std::min(baseTime, mPredictions.startTime);

    }

    if (mActuals.startTime != 0) {

        baseTime = std::min(baseTime, mActuals.startTime);

    }

    baseTime = std::min(baseTime, mActuals.endTime);

    return baseTime;

}



std::string presentStateToString(SurfaceFrame::PresentState presentState) {

    using PresentState = SurfaceFrame::PresentState;

    switch (presentState) {

        case PresentState::Presented:

            return "Presented";

        case PresentState::Dropped:

            return "Dropped";

        case PresentState::Unknown:

        default:

            return "Unknown";

    }

}



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

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

    StringAppendF(&result, "Present State : %d\n", static_cast<int>(mPresentState));

    StringAppendF(&result, "Prediction State : %d\n", static_cast<int>(mPredictionState));

    StringAppendF(&result, "Predicted Start Time : %" PRId64 "\n", mPredictions.startTime);

    StringAppendF(&result, "Actual Start Time : %" PRId64 "\n", mActuals.startTime);

    StringAppendF(&result, "Actual Queue Time : %" PRId64 "\n", mActualQueueTime);

    StringAppendF(&result, "Predicted Render Complete Time : %" PRId64 "\n", mPredictions.endTime);

    StringAppendF(&result, "Actual Render Complete Time : %" PRId64 "\n", mActuals.endTime);

    StringAppendF(&result, "Predicted Present Time : %" PRId64 "\n", mPredictions.presentTime);

    StringAppendF(&result, "Actual Present Time : %" PRId64 "\n", mActuals.presentTime);

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

    StringAppendF(&result, "Layer - %s", mLayerName.c_str());

    if (mJankType != JankType::None) {

        // Easily identify a janky Surface Frame in the dump

        StringAppendF(&result, " [*] ");

    }

    StringAppendF(&result, "\n");

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

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

    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", toString(mJankType).c_str());

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

    StringAppendF(&result, "Jank Metadata: %s\n",

                  jankMetadataBitmaskToString(mJankMetadata).c_str());

    dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime);

}



FrameTimeline::FrameTimeline() : mCurrentDisplayFrame(std::make_shared<DisplayFrame>()) {}
@@ -133,7 +290,9 @@ FrameTimeline::FrameTimeline() : mCurrentDisplayFrame(std::make_shared<DisplayFr 
FrameTimeline::DisplayFrame::DisplayFrame()

      : surfaceFlingerPredictions(TimelineItem()),

        surfaceFlingerActuals(TimelineItem()),

        predictionState(PredictionState::None) {

        predictionState(PredictionState::None),

        jankType(JankType::None),

        jankMetadata(0) {

    this->surfaceFrames.reserve(kNumSurfaceFramesInitial);

}
@@ -200,10 +359,75 @@ void FrameTimeline::flushPendingPresentFences() { 
        if (signalTime != Fence::SIGNAL_TIME_INVALID) {

            auto& displayFrame = pendingPresentFence.second;

            displayFrame->surfaceFlingerActuals.presentTime = signalTime;



            // Jank Analysis for DisplayFrame

            const auto& sfActuals = displayFrame->surfaceFlingerActuals;

            const auto& sfPredictions = displayFrame->surfaceFlingerPredictions;

            if (std::abs(sfActuals.presentTime - sfPredictions.presentTime) > kPresentThreshold) {

                displayFrame->jankMetadata |= sfActuals.presentTime > sfPredictions.presentTime

                        ? LatePresent

                        : EarlyPresent;

            }

            if (std::abs(sfActuals.endTime - sfPredictions.endTime) > kDeadlineThreshold) {

                if (sfActuals.endTime > sfPredictions.endTime) {

                    displayFrame->jankMetadata |= LateFinish;

                } else {

                    displayFrame->jankMetadata |= EarlyFinish;

                }



                if (displayFrame->jankMetadata & EarlyFinish & EarlyPresent) {

                    displayFrame->jankType = JankType::SurfaceFlingerEarlyLatch;

                } else if (displayFrame->jankMetadata & LateFinish & LatePresent) {

                    displayFrame->jankType = JankType::SurfaceFlingerDeadlineMissed;

                } else if (displayFrame->jankMetadata & EarlyPresent ||

                           displayFrame->jankMetadata & LatePresent) {

                    // Cases where SF finished early but frame was presented late and vice versa

                    displayFrame->jankType = JankType::Display;

                }

            }

            if (std::abs(sfActuals.startTime - sfPredictions.startTime) > kSFStartThreshold) {

                displayFrame->jankMetadata |=

                        sfActuals.startTime > sfPredictions.startTime ? LateStart : EarlyStart;

            }



            for (auto& surfaceFrame : displayFrame->surfaceFrames) {

                if (surfaceFrame->getPresentState() == SurfaceFrame::PresentState::Presented) {

                    // Only presented SurfaceFrames need to be updated

                    surfaceFrame->setActualPresentTime(signalTime);



                    // Jank Analysis for SurfaceFrame

                    const auto& predictionState = surfaceFrame->getPredictionState();

                    if (predictionState == PredictionState::Expired) {

                        // Jank analysis cannot be done on apps that don't use predictions

                        surfaceFrame->setJankInfo(JankType::PredictionExpired, 0);

                        continue;

                    } else if (predictionState == PredictionState::Valid) {

                        const auto& actuals = surfaceFrame->getActuals();

                        const auto& predictions = surfaceFrame->getPredictions();

                        int32_t jankMetadata = 0;

                        JankType jankType = JankType::None;

                        if (std::abs(actuals.endTime - predictions.endTime) > kDeadlineThreshold) {

                            jankMetadata |= actuals.endTime > predictions.endTime ? LateFinish

                                                                                  : EarlyFinish;

                        }

                        if (std::abs(actuals.presentTime - predictions.presentTime) >

                            kPresentThreshold) {

                            jankMetadata |= actuals.presentTime > predictions.presentTime

                                    ? LatePresent

                                    : EarlyPresent;

                        }

                        if (jankMetadata & EarlyPresent) {

                            jankType = JankType::SurfaceFlingerEarlyLatch;

                        } else if (jankMetadata & LatePresent) {

                            if (jankMetadata & EarlyFinish) {

                                // TODO(b/169890654): Classify this properly

                                jankType = JankType::Display;

                            } else {

                                jankType = JankType::AppDeadlineMissed;

                            }

                        }

                        surfaceFrame->setJankInfo(jankType, jankMetadata);

                    }

                }

            }

        }
@@ -223,29 +447,86 @@ void FrameTimeline::finalizeCurrentDisplayFrame() { 
    mCurrentDisplayFrame = std::make_shared<DisplayFrame>();

}



void FrameTimeline::dump(std::string& result) {

nsecs_t FrameTimeline::findBaseTime(const std::shared_ptr<DisplayFrame>& displayFrame) {

    nsecs_t baseTime = std::numeric_limits<nsecs_t>::max();

    if (displayFrame->predictionState == PredictionState::Valid) {

        baseTime = std::min(baseTime, displayFrame->surfaceFlingerPredictions.startTime);

    }

    baseTime = std::min(baseTime, displayFrame->surfaceFlingerActuals.startTime);

    for (const auto& surfaceFrame : displayFrame->surfaceFrames) {

        nsecs_t surfaceFrameBaseTime = surfaceFrame->getBaseTime();

        if (surfaceFrameBaseTime != 0) {

            baseTime = std::min(baseTime, surfaceFrameBaseTime);

        }

    }

    return baseTime;

}



void FrameTimeline::dumpDisplayFrame(std::string& result,

                                     const std::shared_ptr<DisplayFrame>& displayFrame,

                                     nsecs_t baseTime) {

    if (displayFrame->jankType != JankType::None) {

        // Easily identify a janky Display Frame in the dump

        StringAppendF(&result, " [*] ");

    }

    StringAppendF(&result, "\n");

    StringAppendF(&result, "Prediction State : %s\n",

                  toString(displayFrame->predictionState).c_str());

    StringAppendF(&result, "Jank Type : %s\n", toString(displayFrame->jankType).c_str());

    StringAppendF(&result, "Jank Metadata: %s\n",

                  jankMetadataBitmaskToString(displayFrame->jankMetadata).c_str());

    dumpTable(result, displayFrame->surfaceFlingerPredictions, displayFrame->surfaceFlingerActuals,

              "", displayFrame->predictionState, baseTime);

    StringAppendF(&result, "\n");

    std::string indent = "    "; // 4 spaces

    for (const auto& surfaceFrame : displayFrame->surfaceFrames) {

        surfaceFrame->dump(result, indent, baseTime);

    }

    StringAppendF(&result, "\n");

}

void FrameTimeline::dumpAll(std::string& result) {

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

    StringAppendF(&result, "Number of display frames : %d\n", (int)mDisplayFrames.size());

    for (const auto& displayFrame : mDisplayFrames) {

        StringAppendF(&result, "---Display Frame---\n");

        StringAppendF(&result, "Prediction State : %d\n",

                      static_cast<int>(displayFrame->predictionState));

        StringAppendF(&result, "Predicted SF wake time : %" PRId64 "\n",

                      displayFrame->surfaceFlingerPredictions.startTime);

        StringAppendF(&result, "Actual SF wake time : %" PRId64 "\n",

                      displayFrame->surfaceFlingerActuals.startTime);

        StringAppendF(&result, "Predicted SF Complete time : %" PRId64 "\n",

                      displayFrame->surfaceFlingerPredictions.endTime);

        StringAppendF(&result, "Actual SF Complete time : %" PRId64 "\n",

                      displayFrame->surfaceFlingerActuals.endTime);

        StringAppendF(&result, "Predicted Present time : %" PRId64 "\n",

                      displayFrame->surfaceFlingerPredictions.presentTime);

        StringAppendF(&result, "Actual Present time : %" PRId64 "\n",

                      displayFrame->surfaceFlingerActuals.presentTime);

        for (size_t i = 0; i < displayFrame->surfaceFrames.size(); i++) {

            StringAppendF(&result, "Surface frame - %" PRId32 "\n", (int)i);

            displayFrame->surfaceFrames[i]->dump(result);

    nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : findBaseTime(mDisplayFrames[0]);

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

        StringAppendF(&result, "Display Frame %d", static_cast<int>(i));

        dumpDisplayFrame(result, mDisplayFrames[i], baseTime);

    }

}



void FrameTimeline::dumpJank(std::string& result) {

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

    nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : findBaseTime(mDisplayFrames[0]);

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

        const auto& displayFrame = mDisplayFrames[i];

        if (displayFrame->jankType == JankType::None) {

            // Check if any Surface Frame has been janky

            bool isJanky = false;

            for (const auto& surfaceFrame : displayFrame->surfaceFrames) {

                if (surfaceFrame->getJankType() != JankType::None) {

                    isJanky = true;

                    break;

                }

            }

            if (!isJanky) {

                continue;

            }

        }

        StringAppendF(&result, "Display Frame %d", static_cast<int>(i));

        dumpDisplayFrame(result, displayFrame, baseTime);

    }

}

void FrameTimeline::parseArgs(const Vector<String16>& args, std::string& result) {

    ATRACE_CALL();

    std::unordered_map<std::string, bool> argsMap;

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

        argsMap[std::string(String8(args[i]).c_str())] = true;

    }

    if (argsMap.count("-jank")) {

        dumpJank(result);

    }

    if (argsMap.count("-all")) {

        dumpAll(result);

    }

}

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+81 −16

File changed.

Preview size limit exceeded, changes collapsed.

services/surfaceflinger/SurfaceFlinger.cpp

+5 −1
Original line number Diff line number Diff line
@@ -4232,7 +4232,7 @@ status_t SurfaceFlinger::doDump(int fd, const DumpArgs& args, bool asProto) { 
                {"--timestats"s, protoDumper(&SurfaceFlinger::dumpTimeStats)},

                {"--vsync"s, dumper(&SurfaceFlinger::dumpVSync)},

                {"--wide-color"s, dumper(&SurfaceFlinger::dumpWideColorInfo)},

                {"--frametimeline"s, dumper([this](std::string& s) { mFrameTimeline->dump(s); })},

                {"--frametimeline"s, argsDumper(&SurfaceFlinger::dumpFrameTimeline)},

        };



        const auto flag = args.empty() ? ""s : std::string(String8(args[0]));
@@ -4315,6 +4315,10 @@ void SurfaceFlinger::dumpTimeStats(const DumpArgs& args, bool asProto, std::stri 
    mTimeStats->parseArgs(asProto, args, result);

}



void SurfaceFlinger::dumpFrameTimeline(const DumpArgs& args, std::string& result) const {

    mFrameTimeline->parseArgs(args, result);

}



// This should only be called from the main thread.  Otherwise it would need

// the lock and should use mCurrentState rather than mDrawingState.

void SurfaceFlinger::logFrameStats() {

services/surfaceflinger/SurfaceFlinger.h

+1 −0
Original line number Diff line number Diff line
@@ -978,6 +978,7 @@ private: 
    void dumpStatsLocked(const DumpArgs& args, std::string& result) const REQUIRES(mStateLock);

    void clearStatsLocked(const DumpArgs& args, std::string& result);

    void dumpTimeStats(const DumpArgs& args, bool asProto, std::string& result) const;

    void dumpFrameTimeline(const DumpArgs& args, std::string& result) const;

    void logFrameStats();



    void dumpVSync(std::string& result) const REQUIRES(mStateLock);