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/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;
     }();