commit 7abbc353b3b9699eff1c9902c7712077bc29144d
author Ady Abraham <adyabr@google.com> Tue Nov 19 16:19:28 2024 -0800
committer Ady Abraham <adyabr@google.com> Tue Nov 19 16:21:29 2024 -0800
tree 2a770d2c7d8955b46b7db423b165bb42578e0b01
parent 4f5e583fd898ff187bf4ff0e438b5e98b1a60baa

SF: add trace points to debug 4ms jank

Bug: 346503493
Test: manual
Flag: EXEMPT logging
Change-Id: Ia2afef930b19a0833a43fe1c6cd23edaf58466c3

services/surfaceflinger/Scheduler/VSyncPredictor.cpp

diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
index 6e36f02..ff360b7 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
@@ -458,7 +458,8 @@
 
 Duration VSyncPredictor::ensureMinFrameDurationIsKept(TimePoint expectedPresentTime,
                                                       TimePoint lastConfirmedPresentTime) {
-    SFTRACE_CALL();
+    SFTRACE_FORMAT("%s mNumVsyncsForFrame=%d mPastExpectedPresentTimes.size()=%zu", __func__,
+                   mNumVsyncsForFrame, mPastExpectedPresentTimes.size());
 
     if (mNumVsyncsForFrame <= 1) {
         return 0ns;
@@ -470,12 +471,8 @@
 
     auto prev = lastConfirmedPresentTime.ns();
     for (auto& current : mPastExpectedPresentTimes) {
-        if (CC_UNLIKELY(mTraceOn)) {
-            SFTRACE_FORMAT_INSTANT("current %.2f past last signaled fence",
-                                   static_cast<float>(current.ns() -
-                                                      lastConfirmedPresentTime.ns()) /
-                                           1e6f);
-        }
+        SFTRACE_FORMAT_INSTANT("current %.2f past last signaled fence",
+                               static_cast<float>(current.ns() - prev) / 1e6f);
 
         const auto minPeriodViolation = current.ns() - prev + threshold < minFramePeriod.ns();
         if (minPeriodViolation) {
@@ -522,11 +519,9 @@
         const auto front = mPastExpectedPresentTimes.front().ns();
         const bool frontIsBeforeConfirmed = front < lastConfirmedPresentTime.ns() + threshold;
         if (frontIsBeforeConfirmed) {
-            if (CC_UNLIKELY(mTraceOn)) {
-                SFTRACE_FORMAT_INSTANT("Discarding old vsync - %.2f before last signaled fence",
-                                       static_cast<float>(lastConfirmedPresentTime.ns() - front) /
-                                               1e6f);
-            }
+            SFTRACE_FORMAT_INSTANT("Discarding old vsync - %.2f before last signaled fence",
+                                   static_cast<float>(lastConfirmedPresentTime.ns() - front) /
+                                           1e6f);
             mPastExpectedPresentTimes.pop_front();
         } else {
             break;

services/surfaceflinger/Scheduler/src/FrameTargeter.cpp

diff --git a/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp b/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp
index 4f16130..5019949 100644
--- a/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp
+++ b/services/surfaceflinger/Scheduler/src/FrameTargeter.cpp
@@ -31,6 +31,7 @@
 
 std::pair<bool /* wouldBackpressure */, FrameTarget::PresentFence>
 FrameTarget::expectedSignaledPresentFence(Period vsyncPeriod, Period minFramePeriod) const {
+    SFTRACE_CALL();
     if (!FlagManager::getInstance().allow_n_vsyncs_in_targeter()) {
         const size_t i = static_cast<size_t>(targetsVsyncsAhead<2>(minFramePeriod));
         return {true, mPresentFencesLegacy[i]};
@@ -40,17 +41,28 @@
     auto expectedPresentTime = mExpectedPresentTime;
     for (size_t i = mPresentFences.size(); i != 0; --i) {
         const auto& fence = mPresentFences[i - 1];
+        SFTRACE_FORMAT_INSTANT("fence at idx: %zu expectedPresentTime in %.2f", i - 1,
+                               ticks<std::milli, float>(fence.expectedPresentTime -
+                                                        TimePoint::now()));
 
         if (fence.expectedPresentTime + minFramePeriod < expectedPresentTime - vsyncPeriod / 2) {
+            SFTRACE_FORMAT_INSTANT("would not backpressure");
             wouldBackpressure = false;
         }
 
         if (fence.expectedPresentTime <= mFrameBeginTime) {
+            SFTRACE_FORMAT_INSTANT("fence at idx: %zu is %.2f before frame begin "
+                                   "(wouldBackpressure=%s)",
+                                   i - 1,
+                                   ticks<std::milli, float>(mFrameBeginTime -
+                                                            fence.expectedPresentTime),
+                                   wouldBackpressure ? "true" : "false");
             return {wouldBackpressure, fence};
         }
 
         expectedPresentTime = fence.expectedPresentTime;
     }
+    SFTRACE_FORMAT_INSTANT("No fence found");
     return {wouldBackpressure, PresentFence{}};
 }
 
@@ -154,6 +166,12 @@
         if (pastPresentTime < 0) return false;
         mLastSignaledFrameTime = {.signalTime = TimePoint::fromNs(pastPresentTime),
                                   .expectedPresentTime = fence.expectedPresentTime};
+        SFTRACE_FORMAT_INSTANT("LastSignaledFrameTime expectedPresentTime %.2f ago, signalTime "
+                               "%.2f ago",
+                               ticks<std::milli, float>(mLastSignaledFrameTime.expectedPresentTime -
+                                                        TimePoint::now()),
+                               ticks<std::milli, float>(mLastSignaledFrameTime.signalTime -
+                                                        TimePoint::now()));
         const nsecs_t frameMissedSlop = vsyncPeriod.ns() / 2;
         return lastScheduledPresentTime.ns() < pastPresentTime - frameMissedSlop;
     }();