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

1 files changed, 121 insertions, 56 deletions

diff --git a/libs/hwui/JankTracker.cpp b/libs/hwui/JankTracker.cpp
index 4eefe921fbe9..7702f9bba0e4 100644
--- a/libs/hwui/JankTracker.cpp
+++ b/libs/hwui/JankTracker.cpp
@@ -95,27 +95,18 @@ JankTracker::JankTracker(ProfileDataContainer* globalData)
         // 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,29 +125,29 @@ void JankTracker::finishFrame(const FrameInfo& frame) {
                         frame[FrameInfoIndex::IntendedVsync],
                         frame[FrameInfoIndex::GpuCompleted]);
 
-    mData->reportFrame(totalDuration);
-    (*mGlobalData)->reportFrame(totalDuration);
 
     // Only things like Surface.lockHardwareCanvas() are exempt from tracking
     if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) {
         return;
     }
 
-    if (totalDuration > mFrameInterval) {
-        mData->reportJank();
-        (*mGlobalData)->reportJank();
+    if (totalDuration > mFrameIntervalLegacy) {
+        mData->reportJankLegacy();
+        (*mGlobalData)->reportJankLegacy();
     }
 
-    if (mSwapDeadline < 0) {
-        mSwapDeadline = frame[FrameInfoIndex::IntendedVsync] + mFrameInterval;
+    if (mSwapDeadlineLegacy < 0) {
+        mSwapDeadlineLegacy = frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy;
     }
-    bool isTripleBuffered = (mSwapDeadline - frame[FrameInfoIndex::IntendedVsync]) > (mFrameInterval * 0.1);
+    bool isTripleBuffered = (mSwapDeadlineLegacy - frame[FrameInfoIndex::IntendedVsync])
+            > (mFrameIntervalLegacy * 0.1);
 
-    mSwapDeadline = std::max(mSwapDeadline + mFrameInterval,
-                             frame[FrameInfoIndex::IntendedVsync] + mFrameInterval);
+    mSwapDeadlineLegacy = std::max(mSwapDeadlineLegacy + mFrameIntervalLegacy,
+                             frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy);
 
     // If we hit the deadline, cool!
-    if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadline || totalDuration < mFrameInterval) {
+    if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadlineLegacy
+            || totalDuration < mFrameIntervalLegacy) {
         if (isTripleBuffered) {
             mData->reportJankType(JankType::kHighInputLatency);
             (*mGlobalData)->reportJankType(JankType::kHighInputLatency);
@@ -164,33 +155,116 @@ void JankTracker::finishFrame(const FrameInfo& frame) {
         return;
     }
 
-    mData->reportJankType(JankType::kMissedDeadline);
-    (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
+    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 % mFrameInterval;
-    mSwapDeadline = frame[FrameInfoIndex::FrameCompleted] - lastFrameOffset + mFrameInterval;
+    nsecs_t lastFrameOffset = jitterNanos % mFrameIntervalLegacy;
+    mSwapDeadlineLegacy = frame[FrameInfoIndex::FrameCompleted]
+            - lastFrameOffset + mFrameIntervalLegacy;
+}
 
-    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);
-        }
+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);
+
+    // Only things like Surface.lockHardwareCanvas() are exempt from tracking
+    if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) {
+        return;
+    }
+
+    int64_t frameInterval = frame[FrameInfoIndex::FrameInterval];
+
+    // 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);
+
+    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;
     }
 
-    // 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] << ", ";
+    // If we hit the deadline, cool!
+    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);
         }
-        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;
+    }
+    mThresholdsFrameBudget = frameBudget;
+    for (auto& comparison : COMPARISONS) {
+        mThresholds[comparison.type] = comparison.computeThreadshold(frameBudget);
     }
 }
 
@@ -243,14 +317,5 @@ void JankTracker::reset() {
                                                     : 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 */