Change hwui jank detection to use deadline & gpu completion (1/2)
- Use GPU finish time as well as actual deadline to determine jank
rate.
- Use dynamic interval to adjust for 60/90hz switching
- Move frame metrics reporting into JankTracker to adjust the
deadline communicated to the app when in stuffing scenario.
- Adjust double-stuffing detection to be a bit more readable.
Test: GraphicsStatsValidationTest.java
Test: adb shell dumpsys gfxinfo
Test: FrameMetricsListenerTest
Test: Log output of FrameMetricsObserver
Bug: 169858044
Change-Id: I3a6b8ed163e2cf9cf2b67667110340ebe35f98a1
diff --git a/libs/hwui/JankTracker.cpp b/libs/hwui/JankTracker.cpp
index 4eefe92..7702f9b 100644
--- a/libs/hwui/JankTracker.cpp
+++ b/libs/hwui/JankTracker.cpp
@@ -95,27 +95,18 @@
// SF will begin composition at VSYNC-app + offsetDelta. If we are triple
// buffered, this is the expected time at which dequeueBuffer will
// return due to the staggering of VSYNC-app & VSYNC-sf.
- mDequeueTimeForgiveness = offsetDelta + 4_ms;
+ mDequeueTimeForgivenessLegacy = offsetDelta + 4_ms;
}
- setFrameInterval(frameIntervalNanos);
+ mFrameIntervalLegacy = frameIntervalNanos;
}
-void JankTracker::setFrameInterval(nsecs_t frameInterval) {
- mFrameInterval = frameInterval;
-
- for (auto& comparison : COMPARISONS) {
- mThresholds[comparison.type] = comparison.computeThreadshold(frameInterval);
- }
-}
-
-void JankTracker::finishFrame(const FrameInfo& frame) {
- std::lock_guard lock(mDataMutex);
-
+void JankTracker::calculateLegacyJank(FrameInfo& frame) {
// Fast-path for jank-free frames
int64_t totalDuration = frame.duration(sFrameStart, FrameInfoIndex::SwapBuffersCompleted);
- if (mDequeueTimeForgiveness && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) {
- nsecs_t expectedDequeueDuration = mDequeueTimeForgiveness + frame[FrameInfoIndex::Vsync] -
- frame[FrameInfoIndex::IssueDrawCommandsStart];
+ if (mDequeueTimeForgivenessLegacy && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) {
+ nsecs_t expectedDequeueDuration = mDequeueTimeForgivenessLegacy
+ + frame[FrameInfoIndex::Vsync]
+ - frame[FrameInfoIndex::IssueDrawCommandsStart];
if (expectedDequeueDuration > 0) {
// Forgive only up to the expected amount, but not more than
// the actual time spent blocked.
@@ -134,6 +125,56 @@
frame[FrameInfoIndex::IntendedVsync],
frame[FrameInfoIndex::GpuCompleted]);
+
+ // Only things like Surface.lockHardwareCanvas() are exempt from tracking
+ if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) {
+ return;
+ }
+
+ if (totalDuration > mFrameIntervalLegacy) {
+ mData->reportJankLegacy();
+ (*mGlobalData)->reportJankLegacy();
+ }
+
+ if (mSwapDeadlineLegacy < 0) {
+ mSwapDeadlineLegacy = frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy;
+ }
+ bool isTripleBuffered = (mSwapDeadlineLegacy - frame[FrameInfoIndex::IntendedVsync])
+ > (mFrameIntervalLegacy * 0.1);
+
+ mSwapDeadlineLegacy = std::max(mSwapDeadlineLegacy + mFrameIntervalLegacy,
+ frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy);
+
+ // If we hit the deadline, cool!
+ if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadlineLegacy
+ || totalDuration < mFrameIntervalLegacy) {
+ if (isTripleBuffered) {
+ mData->reportJankType(JankType::kHighInputLatency);
+ (*mGlobalData)->reportJankType(JankType::kHighInputLatency);
+ }
+ return;
+ }
+
+ mData->reportJankType(JankType::kMissedDeadlineLegacy);
+ (*mGlobalData)->reportJankType(JankType::kMissedDeadlineLegacy);
+
+ // Janked, reset the swap deadline
+ nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync];
+ nsecs_t lastFrameOffset = jitterNanos % mFrameIntervalLegacy;
+ mSwapDeadlineLegacy = frame[FrameInfoIndex::FrameCompleted]
+ - lastFrameOffset + mFrameIntervalLegacy;
+}
+
+void JankTracker::finishFrame(FrameInfo& frame, std::unique_ptr<FrameMetricsReporter>& reporter) {
+ std::lock_guard lock(mDataMutex);
+
+ calculateLegacyJank(frame);
+
+ // Fast-path for jank-free frames
+ int64_t totalDuration = frame.duration(FrameInfoIndex::IntendedVsync,
+ FrameInfoIndex::FrameCompleted);
+
+ LOG_ALWAYS_FATAL_IF(totalDuration <= 0, "Impossible totalDuration %" PRId64, totalDuration);
mData->reportFrame(totalDuration);
(*mGlobalData)->reportFrame(totalDuration);
@@ -142,55 +183,88 @@
return;
}
- if (totalDuration > mFrameInterval) {
- mData->reportJank();
- (*mGlobalData)->reportJank();
- }
+ int64_t frameInterval = frame[FrameInfoIndex::FrameInterval];
- if (mSwapDeadline < 0) {
- mSwapDeadline = frame[FrameInfoIndex::IntendedVsync] + mFrameInterval;
- }
- bool isTripleBuffered = (mSwapDeadline - frame[FrameInfoIndex::IntendedVsync]) > (mFrameInterval * 0.1);
+ // If we starter earlier than the intended frame start assuming an unstuffed scenario, it means
+ // that we are in a triple buffering situation.
+ bool isTripleBuffered = (mNextFrameStartUnstuffed - frame[FrameInfoIndex::IntendedVsync])
+ > (frameInterval * 0.1);
- mSwapDeadline = std::max(mSwapDeadline + mFrameInterval,
- frame[FrameInfoIndex::IntendedVsync] + mFrameInterval);
+ int64_t deadline = frame[FrameInfoIndex::FrameDeadline];
+
+ // If we are in triple buffering, we have enough buffers in queue to sustain a single frame
+ // drop without jank, so adjust the frame interval to the deadline.
+ if (isTripleBuffered) {
+ deadline += frameInterval;
+ frame.set(FrameInfoIndex::FrameDeadline) += frameInterval;
+ }
// If we hit the deadline, cool!
- if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadline || totalDuration < mFrameInterval) {
+ if (frame[FrameInfoIndex::GpuCompleted] < deadline) {
if (isTripleBuffered) {
mData->reportJankType(JankType::kHighInputLatency);
(*mGlobalData)->reportJankType(JankType::kHighInputLatency);
+
+ // Buffer stuffing state gets carried over to next frame, unless there is a "pause"
+ mNextFrameStartUnstuffed += frameInterval;
}
+ } else {
+ mData->reportJankType(JankType::kMissedDeadline);
+ (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
+ mData->reportJank();
+ (*mGlobalData)->reportJank();
+
+ // Janked, store the adjust deadline to detect triple buffering in next frame correctly.
+ nsecs_t jitterNanos = frame[FrameInfoIndex::GpuCompleted]
+ - frame[FrameInfoIndex::Vsync];
+ nsecs_t lastFrameOffset = jitterNanos % frameInterval;
+
+ // Note the time when the next frame would start in an unstuffed situation. If it starts
+ // earlier, we are in a stuffed situation.
+ mNextFrameStartUnstuffed = frame[FrameInfoIndex::GpuCompleted]
+ - lastFrameOffset + frameInterval;
+
+ recomputeThresholds(frameInterval);
+ for (auto& comparison : COMPARISONS) {
+ int64_t delta = frame.duration(comparison.start, comparison.end);
+ if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) {
+ mData->reportJankType(comparison.type);
+ (*mGlobalData)->reportJankType(comparison.type);
+ }
+ }
+
+ // Log daveys since they are weird and we don't know what they are (b/70339576)
+ if (totalDuration >= 700_ms) {
+ static int sDaveyCount = 0;
+ std::stringstream ss;
+ ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; ";
+ for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
+ ss << FrameInfoNames[i] << "=" << frame[i] << ", ";
+ }
+ ALOGI("%s", ss.str().c_str());
+ // Just so we have something that counts up, the value is largely irrelevant
+ ATRACE_INT(ss.str().c_str(), ++sDaveyCount);
+ }
+ }
+
+ int64_t totalGPUDrawTime = frame.gpuDrawTime();
+ if (totalGPUDrawTime >= 0) {
+ mData->reportGPUFrame(totalGPUDrawTime);
+ (*mGlobalData)->reportGPUFrame(totalGPUDrawTime);
+ }
+
+ if (CC_UNLIKELY(reporter.get() != nullptr)) {
+ reporter->reportFrameMetrics(frame.data(), false /* hasPresentTime */);
+ }
+}
+
+void JankTracker::recomputeThresholds(int64_t frameBudget) {
+ if (mThresholdsFrameBudget == frameBudget) {
return;
}
-
- mData->reportJankType(JankType::kMissedDeadline);
- (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
-
- // Janked, reset the swap deadline
- nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync];
- nsecs_t lastFrameOffset = jitterNanos % mFrameInterval;
- mSwapDeadline = frame[FrameInfoIndex::FrameCompleted] - lastFrameOffset + mFrameInterval;
-
+ mThresholdsFrameBudget = frameBudget;
for (auto& comparison : COMPARISONS) {
- int64_t delta = frame.duration(comparison.start, comparison.end);
- if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) {
- mData->reportJankType(comparison.type);
- (*mGlobalData)->reportJankType(comparison.type);
- }
- }
-
- // Log daveys since they are weird and we don't know what they are (b/70339576)
- if (totalDuration >= 700_ms) {
- static int sDaveyCount = 0;
- std::stringstream ss;
- ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; ";
- for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
- ss << FrameInfoNames[i] << "=" << frame[i] << ", ";
- }
- ALOGI("%s", ss.str().c_str());
- // Just so we have something that counts up, the value is largely irrelevant
- ATRACE_INT(ss.str().c_str(), ++sDaveyCount);
+ mThresholds[comparison.type] = comparison.computeThreadshold(frameBudget);
}
}
@@ -243,14 +317,5 @@
: FrameInfoIndex::IntendedVsync;
}
-void JankTracker::finishGpuDraw(const FrameInfo& frame) {
- std::lock_guard lock(mDataMutex);
- int64_t totalGPUDrawTime = frame.gpuDrawTime();
- if (totalGPUDrawTime >= 0) {
- mData->reportGPUFrame(totalGPUDrawTime);
- (*mGlobalData)->reportGPUFrame(totalGPUDrawTime);
- }
-}
-
} /* namespace uirenderer */
} /* namespace android */