Merge "SF: add trace points to debug 4ms jank" into main

Author: Ram Indani

services/surfaceflinger/Scheduler/VSyncPredictor.cpp

@@ -458,7 +458,8 @@ void VSyncPredictor::setDisplayModePtr(ftl::NonNull<DisplayModePtr> modePtr) {
 
 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 @@ Duration VSyncPredictor::ensureMinFrameDurationIsKept(TimePoint expectedPresentT
 
     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 @@ void VSyncPredictor::onFrameBegin(TimePoint expectedPresentTime, FrameTime lastS
         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

@@ -31,6 +31,7 @@ FrameTarget::FrameTarget(const std::string& displayLabel)
 
 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 @@ FrameTarget::expectedSignaledPresentFence(Period vsyncPeriod, Period minFramePer
     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 @@ void FrameTargeter::beginFrame(const BeginFrameArgs& args, const IVsyncSource& v
         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;
     }();