commit 9243bba2e7b770100ea76757ec9843d14cc7d31c
author Ady Abraham <adyabr@google.com> Fri Feb 10 15:31:14 2023 -0800
committer Ady Abraham <adyabr@google.com> Sat Feb 11 00:10:51 2023 +0000
tree 40fdc5c50231e865842923f383182a62ae9efd53
parent 87602ee3571ea617c62053f247027544cddd9c7a

SF: add traces for isVsyncValid

Add more debug information for isVsyncValid

Bug: 267780202
Test: manual
Change-Id: I84bc750cf490a4d04a5d86915367da4bf6681f8c

services/surfaceflinger/Scheduler/Scheduler.cpp

diff --git a/services/surfaceflinger/Scheduler/Scheduler.cpp b/services/surfaceflinger/Scheduler/Scheduler.cpp
index 5fc250b..ad803f9 100644
--- a/services/surfaceflinger/Scheduler/Scheduler.cpp
+++ b/services/surfaceflinger/Scheduler/Scheduler.cpp
@@ -28,10 +28,10 @@
 #include <ftl/enum.h>
 #include <ftl/fake_guard.h>
 #include <ftl/small_map.h>
+#include <gui/TraceUtils.h>
 #include <gui/WindowInfo.h>
 #include <system/window.h>
 #include <utils/Timers.h>
-#include <utils/Trace.h>
 
 #include <FrameTimeline/FrameTimeline.h>
 #include <scheduler/interface/ICompositor.h>
@@ -171,6 +171,7 @@
         return true;
     }
 
+    ATRACE_FORMAT("%s uid: %d frameRate: %s", __func__, uid, to_string(*frameRate).c_str());
     return mVsyncSchedule->getTracker().isVSyncInPhase(expectedVsyncTimestamp.ns(), *frameRate);
 }
 

services/surfaceflinger/Scheduler/VSyncPredictor.cpp

diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
index 02e12fd..f8cb323 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
@@ -31,8 +31,8 @@
 #include <android-base/stringprintf.h>
 #include <cutils/compiler.h>
 #include <cutils/properties.h>
+#include <gui/TraceUtils.h>
 #include <utils/Log.h>
-#include <utils/Trace.h>
 
 #include "RefreshRateSelector.h"
 #include "VSyncPredictor.h"
@@ -282,6 +282,13 @@
 }
 
 bool VSyncPredictor::isVSyncInPhaseLocked(nsecs_t timePoint, unsigned divisor) const {
+    const TimePoint now = TimePoint::now();
+    const auto getTimePointIn = [](TimePoint now, nsecs_t timePoint) -> float {
+        return ticks<std::milli, float>(TimePoint::fromNs(timePoint) - now);
+    };
+    ATRACE_FORMAT("%s timePoint in: %.2f divisor: %zu", __func__, getTimePointIn(now, timePoint),
+                  divisor);
+
     struct VsyncError {
         nsecs_t vsyncTimestamp;
         float error;
@@ -304,6 +311,7 @@
     if (knownTimestampIter == mRateDivisorKnownTimestampMap.end()) {
         const auto vsync = nextAnticipatedVSyncTimeFromLocked(justBeforeTimePoint);
         mRateDivisorKnownTimestampMap[dividedPeriod] = vsync;
+        ATRACE_FORMAT_INSTANT("(first) knownVsync in: %.2f", getTimePointIn(now, vsync));
         return true;
     }
 
@@ -323,6 +331,8 @@
 
     const auto minVsyncError = std::min_element(vsyncs.begin(), vsyncs.end());
     mRateDivisorKnownTimestampMap[dividedPeriod] = minVsyncError->vsyncTimestamp;
+    ATRACE_FORMAT_INSTANT("knownVsync in: %.2f",
+                          getTimePointIn(now, minVsyncError->vsyncTimestamp));
     return std::abs(minVsyncError->vsyncTimestamp - timePoint) < period / 2;
 }