From 8fc601d6758de1d158da2c31eb6b7ce708f981bb Mon Sep 17 00:00:00 2001 From: Adithya Srinivasan Date: Fri, 25 Sep 2020 13:51:09 -0700 Subject: 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 --- .../surfaceflinger/FrameTimeline/FrameTimeline.cpp | 361 ++++++++++++++++++--- .../surfaceflinger/FrameTimeline/FrameTimeline.h | 97 +++++- 2 files changed, 402 insertions(+), 56 deletions(-) (limited to 'services/surfaceflinger/FrameTimeline') diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp index 9985253d2b..22d9d10d18 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp @@ -22,12 +22,127 @@ #include #include #include +#include #include +#include 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(startTime).count(), + std::chrono::duration(endTime).count(), + std::chrono::duration(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(0, actuals.startTime - baseTime)); + StringAppendF(&result, "\t%10.2f\t|", + std::chrono::duration(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(endTime).count()); + } + if (actuals.presentTime == 0) { + StringAppendF(&result, "\t\tN/A\n"); + } else { + std::chrono::nanoseconds presentTime(std::max(0, actuals.presentTime - baseTime)); + StringAppendF(&result, "\t%10.2f\n", + std::chrono::duration(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 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 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 lock(mMutex); mPresentState = state; } -PredictionState SurfaceFrame::getPredictionState() { - std::lock_guard lock(mMutex); - return mPredictionState; -} - -SurfaceFrame::PresentState SurfaceFrame::getPresentState() { +SurfaceFrame::PresentState SurfaceFrame::getPresentState() const { std::lock_guard lock(mMutex); return mPresentState; } -TimelineItem SurfaceFrame::getActuals() { +TimelineItem SurfaceFrame::getActuals() const { std::lock_guard lock(mMutex); return mActuals; } -nsecs_t SurfaceFrame::getActualQueueTime() { +nsecs_t SurfaceFrame::getActualQueueTime() const { std::lock_guard 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 lock(mMutex); - StringAppendF(&result, "Present State : %d\n", static_cast(mPresentState)); - StringAppendF(&result, "Prediction State : %d\n", static_cast(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); + mJankType = jankType; + mJankMetadata = jankMetadata; +} + +JankType SurfaceFrame::getJankType() const { + std::lock_guard lock(mMutex); + return mJankType; +} + +nsecs_t SurfaceFrame::getBaseTime() const { + std::lock_guard lock(mMutex); + nsecs_t baseTime = std::numeric_limits::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 lock(mMutex); + 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()) {} @@ -133,7 +290,9 @@ FrameTimeline::FrameTimeline() : mCurrentDisplayFrame(std::make_sharedsurfaceFrames.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(); } -void FrameTimeline::dump(std::string& result) { +nsecs_t FrameTimeline::findBaseTime(const std::shared_ptr& displayFrame) { + nsecs_t baseTime = std::numeric_limits::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, + 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 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(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(i)); + dumpDisplayFrame(result, mDisplayFrames[i], baseTime); + } +} + +void FrameTimeline::dumpJank(std::string& result) { + std::lock_guard 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(i)); + dumpDisplayFrame(result, displayFrame, baseTime); + } +} +void FrameTimeline::parseArgs(const Vector& args, std::string& result) { + ATRACE_CALL(); + std::unordered_map 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); } } diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h index cfe81704b3..1624c2b01e 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h @@ -22,10 +22,48 @@ #include #include #include +#include #include +#include namespace android::frametimeline { +/* + * The type of jank that is associated with a Display/Surface frame + */ +enum class JankType { + // No Jank + None, + // Jank not related to SurfaceFlinger or the App + Display, + // SF took too long on the CPU + SurfaceFlingerDeadlineMissed, + // Either App or GPU took too long on the frame + AppDeadlineMissed, + // Predictions live for 120ms, if prediction is expired for a frame, there is definitely a jank + // associated with the App if this is for a SurfaceFrame, and SF for a DisplayFrame. + PredictionExpired, + // Latching a buffer early might cause an early present of the frame + SurfaceFlingerEarlyLatch, +}; + +enum JankMetadata { + // Frame was presented earlier than expected + EarlyPresent = 0x1, + // Frame was presented later than expected + LatePresent = 0x2, + // App/SF started earlier than expected + EarlyStart = 0x4, + // App/SF started later than expected + LateStart = 0x8, + // App/SF finished work earlier than the deadline + EarlyFinish = 0x10, + // App/SF finished work later than the deadline + LateFinish = 0x20, + // SF was in GPU composition + GpuComposition = 0x40, +}; + class FrameTimelineTest; /* @@ -75,11 +113,11 @@ public: virtual ~SurfaceFrame() = default; - virtual TimelineItem getPredictions() = 0; - virtual TimelineItem getActuals() = 0; - virtual nsecs_t getActualQueueTime() = 0; - virtual PresentState getPresentState() = 0; - virtual PredictionState getPredictionState() = 0; + virtual TimelineItem getPredictions() const = 0; + virtual TimelineItem getActuals() const = 0; + virtual nsecs_t getActualQueueTime() const = 0; + virtual PresentState getPresentState() const = 0; + virtual PredictionState getPredictionState() const = 0; virtual void setPresentState(PresentState state) = 0; @@ -120,7 +158,11 @@ public: virtual void setSfPresent(nsecs_t sfPresentTime, const std::shared_ptr& presentFence) = 0; - virtual void dump(std::string& result) = 0; + // Args: + // -jank : Dumps only the Display Frames that are either janky themselves + // or contain janky Surface Frames. + // -all : Dumps the entire list of DisplayFrames and the SurfaceFrames contained within + virtual void parseArgs(const Vector& args, std::string& result) = 0; }; namespace impl { @@ -155,27 +197,33 @@ public: TimelineItem&& predictions); ~SurfaceFrame() = default; - TimelineItem getPredictions() override { return mPredictions; }; - TimelineItem getActuals() override; - nsecs_t getActualQueueTime() override; - PresentState getPresentState() override; - PredictionState getPredictionState() override; + TimelineItem getPredictions() const override { return mPredictions; }; + TimelineItem getActuals() const override; + nsecs_t getActualQueueTime() const override; + PresentState getPresentState() const override; + PredictionState getPredictionState() const override { return mPredictionState; }; void setActualStartTime(nsecs_t actualStartTime) override; void setActualQueueTime(nsecs_t actualQueueTime) override; void setAcquireFenceTime(nsecs_t acquireFenceTime) override; void setPresentState(PresentState state) override; void setActualPresentTime(nsecs_t presentTime); - void dump(std::string& result); + void setJankInfo(JankType jankType, int32_t jankMetadata); + JankType getJankType() const; + nsecs_t getBaseTime() const; + // All the timestamps are dumped relative to the baseTime + void dump(std::string& result, const std::string& indent, nsecs_t baseTime); private: const std::string mLayerName; PresentState mPresentState GUARDED_BY(mMutex); - PredictionState mPredictionState GUARDED_BY(mMutex); + const PredictionState mPredictionState; const TimelineItem mPredictions; TimelineItem mActuals GUARDED_BY(mMutex); - nsecs_t mActualQueueTime; - std::mutex mMutex; + nsecs_t mActualQueueTime GUARDED_BY(mMutex); + mutable std::mutex mMutex; + JankType mJankType GUARDED_BY(mMutex); // Enum for the type of jank + int32_t mJankMetadata GUARDED_BY(mMutex); // Additional details about the jank }; class FrameTimeline : public android::frametimeline::FrameTimeline { @@ -191,7 +239,7 @@ public: void setSfWakeUp(int64_t token, nsecs_t wakeupTime) override; void setSfPresent(nsecs_t sfPresentTime, const std::shared_ptr& presentFence) override; - void dump(std::string& result) override; + void parseArgs(const Vector& args, std::string& result) override; private: // Friend class for testing @@ -215,10 +263,19 @@ private: std::vector> surfaceFrames; PredictionState predictionState; + JankType jankType = JankType::None; // Enum for the type of jank + int32_t jankMetadata = 0x0; // Additional details about the jank }; void flushPendingPresentFences() REQUIRES(mMutex); void finalizeCurrentDisplayFrame() REQUIRES(mMutex); + // BaseTime is the smallest timestamp in a DisplayFrame. + // Used for dumping all timestamps relative to the oldest, making it easy to read. + nsecs_t findBaseTime(const std::shared_ptr&) REQUIRES(mMutex); + void dumpDisplayFrame(std::string& result, const std::shared_ptr&, + nsecs_t baseTime) REQUIRES(mMutex); + void dumpAll(std::string& result); + void dumpJank(std::string& result); // Sliding window of display frames. TODO(b/168072834): compare perf with fixed size array std::deque> mDisplayFrames GUARDED_BY(mMutex); @@ -233,6 +290,14 @@ private: // frame, this is a good starting size for the vector so that we can avoid the internal vector // resizing that happens with push_back. static constexpr uint32_t kNumSurfaceFramesInitial = 10; + // The various thresholds for App and SF. If the actual timestamp falls within the threshold + // compared to prediction, we don't treat it as a jank. + static constexpr nsecs_t kPresentThreshold = + std::chrono::duration_cast(2ms).count(); + static constexpr nsecs_t kDeadlineThreshold = + std::chrono::duration_cast(2ms).count(); + static constexpr nsecs_t kSFStartThreshold = + std::chrono::duration_cast(1ms).count(); }; } // namespace impl -- cgit v1.2.3-59-g8ed1b From 2d73632786885af1cfb2a92fe6b2f00f6671fd5a Mon Sep 17 00:00:00 2001 From: Adithya Srinivasan Date: Thu, 1 Oct 2020 16:53:48 -0700 Subject: Add a backdoor to change FrameTimeline's maxDisplayFrames This change adds a backdoor entry through SurfaceFlinger to allow modifying the max number of display frames stored in FrameTimeline. This is particularly useful for debugging, enabling to take a trace as well see the dump on the side. Bug: 169894383 Test: libsurfaceflinger_unittest Change-Id: I872e240597193d597dac4a9f096b6360edf5cce1 --- .../surfaceflinger/FrameTimeline/FrameTimeline.cpp | 19 +++++++- .../surfaceflinger/FrameTimeline/FrameTimeline.h | 11 ++++- services/surfaceflinger/SurfaceFlinger.cpp | 19 +++++++- services/surfaceflinger/SurfaceFlinger.h | 2 + .../tests/unittests/FrameTimelineTest.cpp | 54 ++++++++++++++++++++-- 5 files changed, 97 insertions(+), 8 deletions(-) (limited to 'services/surfaceflinger/FrameTimeline') diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp index 22d9d10d18..43176a3f10 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp @@ -285,7 +285,9 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime); } -FrameTimeline::FrameTimeline() : mCurrentDisplayFrame(std::make_shared()) {} +FrameTimeline::FrameTimeline() + : mCurrentDisplayFrame(std::make_shared()), + mMaxDisplayFrames(kDefaultMaxDisplayFrames) {} FrameTimeline::DisplayFrame::DisplayFrame() : surfaceFlingerPredictions(TimelineItem()), @@ -438,7 +440,7 @@ void FrameTimeline::flushPendingPresentFences() { } void FrameTimeline::finalizeCurrentDisplayFrame() { - while (mDisplayFrames.size() >= kMaxDisplayFrames) { + while (mDisplayFrames.size() >= mMaxDisplayFrames) { // We maintain only a fixed number of frames' data. Pop older frames mDisplayFrames.pop_front(); } @@ -530,4 +532,17 @@ void FrameTimeline::parseArgs(const Vector& args, std::string& result) } } +void FrameTimeline::setMaxDisplayFrames(uint32_t size) { + std::lock_guard lock(mMutex); + + // The size can either increase or decrease, clear everything, to be consistent + mDisplayFrames.clear(); + mPendingPresentFences.clear(); + mMaxDisplayFrames = size; +} + +void FrameTimeline::reset() { + setMaxDisplayFrames(kDefaultMaxDisplayFrames); +} + } // namespace android::frametimeline::impl diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h index 1624c2b01e..7da075796d 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h @@ -163,6 +163,12 @@ public: // or contain janky Surface Frames. // -all : Dumps the entire list of DisplayFrames and the SurfaceFrames contained within virtual void parseArgs(const Vector& args, std::string& result) = 0; + + // Sets the max number of display frames that can be stored. Called by SF backdoor. + virtual void setMaxDisplayFrames(uint32_t size); + + // Restores the max number of display frames to default. Called by SF backdoor. + virtual void reset() = 0; }; namespace impl { @@ -240,6 +246,8 @@ public: void setSfPresent(nsecs_t sfPresentTime, const std::shared_ptr& presentFence) override; void parseArgs(const Vector& args, std::string& result) override; + void setMaxDisplayFrames(uint32_t size) override; + void reset() override; private: // Friend class for testing @@ -284,7 +292,8 @@ private: std::shared_ptr mCurrentDisplayFrame GUARDED_BY(mMutex); TokenManager mTokenManager; std::mutex mMutex; - static constexpr uint32_t kMaxDisplayFrames = 64; + uint32_t mMaxDisplayFrames; + static constexpr uint32_t kDefaultMaxDisplayFrames = 64; // The initial container size for the vector inside display frame. Although this // number doesn't represent any bounds on the number of surface frames that can go in a display // frame, this is a good starting size for the vector so that we can avoid the internal vector diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp index e9eb63f4d9..619bc03f34 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/services/surfaceflinger/SurfaceFlinger.cpp @@ -4901,9 +4901,9 @@ status_t SurfaceFlinger::CheckTransactCodeCredentials(uint32_t code) { code == IBinder::SYSPROPS_TRANSACTION) { return OK; } - // Numbers from 1000 to 1037 are currently used for backdoors. The code + // Numbers from 1000 to 1038 are currently used for backdoors. The code // in onTransact verifies that the user is root, and has access to use SF. - if (code >= 1000 && code <= 1037) { + if (code >= 1000 && code <= 1038) { ALOGV("Accessing SurfaceFlinger through backdoor code: %u", code); return OK; } @@ -5259,6 +5259,21 @@ status_t SurfaceFlinger::onTransact(uint32_t code, const Parcel& data, Parcel* r return NO_ERROR; } + // Modify the max number of display frames stored within FrameTimeline + case 1038: { + n = data.readInt32(); + if (n < 0 || n > MAX_ALLOWED_DISPLAY_FRAMES) { + ALOGW("Invalid max size. Maximum allowed is %d", MAX_ALLOWED_DISPLAY_FRAMES); + return BAD_VALUE; + } + if (n == 0) { + // restore to default + mFrameTimeline->reset(); + return NO_ERROR; + } + mFrameTimeline->setMaxDisplayFrames(n); + return NO_ERROR; + } } } return err; diff --git a/services/surfaceflinger/SurfaceFlinger.h b/services/surfaceflinger/SurfaceFlinger.h index 738e05685d..d069f2b2de 100644 --- a/services/surfaceflinger/SurfaceFlinger.h +++ b/services/surfaceflinger/SurfaceFlinger.h @@ -499,6 +499,8 @@ private: } static const int MAX_TRACING_MEMORY = 100 * 1024 * 1024; // 100MB + // Maximum allowed number of display frames that can be set through backdoor + static const int MAX_ALLOWED_DISPLAY_FRAMES = 2048; // Implements IBinder. status_t onTransact(uint32_t code, const Parcel& data, Parcel* reply, uint32_t flags) override; diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp index 617f95abcc..69efd7f477 100644 --- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp +++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp @@ -43,7 +43,7 @@ public: void SetUp() override { mFrameTimeline = std::make_unique(); mTokenManager = &mFrameTimeline->mTokenManager; - maxDisplayFrames = mFrameTimeline->kMaxDisplayFrames; + maxDisplayFrames = &mFrameTimeline->mMaxDisplayFrames; maxTokenRetentionTime = mTokenManager->kMaxRetentionTime; } @@ -71,10 +71,15 @@ public: return mTokenManager->mPredictions; } + uint32_t getNumberOfDisplayFrames() { + std::lock_guard lock(mFrameTimeline->mMutex); + return static_cast(mFrameTimeline->mDisplayFrames.size()); + } + std::unique_ptr mFrameTimeline; impl::TokenManager* mTokenManager; FenceToFenceTimeMap fenceFactory; - uint64_t maxDisplayFrames; + uint32_t* maxDisplayFrames; nsecs_t maxTokenRetentionTime; }; @@ -178,7 +183,7 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_presentedFramesUpdated) { TEST_F(FrameTimelineTest, displayFramesSlidingWindowMovesAfterLimit) { // Insert kMaxDisplayFrames' count of DisplayFrames to fill the deque int frameTimeFactor = 0; - for (size_t i = 0; i < maxDisplayFrames; i++) { + for (size_t i = 0; i < *maxDisplayFrames; i++) { auto presentFence = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken = mTokenManager->generateTokenForPredictions( {10 + frameTimeFactor, 20 + frameTimeFactor, 30 + frameTimeFactor}); @@ -233,4 +238,47 @@ TEST_F(FrameTimelineTest, surfaceFrameEndTimeAcquireFenceBeforeQueue) { EXPECT_EQ(surfaceFrame->getActuals().endTime, 456); } +TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { + auto presentFence = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); + presentFence->signalForTest(2); + + // Size shouldn't exceed maxDisplayFrames - 64 + for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", std::nullopt); + int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); + mFrameTimeline->setSfWakeUp(sfToken, 22); + mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), + SurfaceFrame::PresentState::Presented); + mFrameTimeline->setSfPresent(27, presentFence); + } + EXPECT_EQ(getNumberOfDisplayFrames(), *maxDisplayFrames); + + // Increase the size to 256 + mFrameTimeline->setMaxDisplayFrames(256); + EXPECT_EQ(*maxDisplayFrames, 256); + + for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", std::nullopt); + int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); + mFrameTimeline->setSfWakeUp(sfToken, 22); + mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), + SurfaceFrame::PresentState::Presented); + mFrameTimeline->setSfPresent(27, presentFence); + } + EXPECT_EQ(getNumberOfDisplayFrames(), *maxDisplayFrames); + + // Shrink the size to 128 + mFrameTimeline->setMaxDisplayFrames(128); + EXPECT_EQ(*maxDisplayFrames, 128); + + for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", std::nullopt); + int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); + mFrameTimeline->setSfWakeUp(sfToken, 22); + mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), + SurfaceFrame::PresentState::Presented); + mFrameTimeline->setSfPresent(27, presentFence); + } + EXPECT_EQ(getNumberOfDisplayFrames(), *maxDisplayFrames); +} } // namespace android::frametimeline -- cgit v1.2.3-59-g8ed1b