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
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index 9985253..22d9d10 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -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 @@
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 @@
mActuals.presentTime = presentTime;
}
-void SurfaceFrame::dump(std::string& result) {
+void SurfaceFrame::setJankInfo(JankType jankType, int32_t jankMetadata) {
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);
+ 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, "%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::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 @@
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 @@
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);
}
}