SF: add more traces when adding vsync timestamps

Bug: 316224736
Change-Id: I264e728c49f0500f2f868c3a25b0910d0d527340
Test: presubmit

4 files changed, 16 insertions, 0 deletions

diff --git a/services/surfaceflinger/Scheduler/Scheduler.cpp b/services/surfaceflinger/Scheduler/Scheduler.cpp
index 6a85788623..4440177a49 100644
--- a/services/surfaceflinger/Scheduler/Scheduler.cpp
+++ b/services/surfaceflinger/Scheduler/Scheduler.cpp
@@ -630,6 +630,7 @@ bool Scheduler::addResyncSample(PhysicalDisplayId id, nsecs_t timestamp,
 }
 
 void Scheduler::addPresentFence(PhysicalDisplayId id, std::shared_ptr<FenceTime> fence) {
+    ATRACE_NAME(ftl::Concat(__func__, ' ', id.value).c_str());
     const auto scheduleOpt =
             (ftl::FakeGuard(mDisplayLock), mDisplays.get(id)).and_then([](const Display& display) {
                 return display.powerMode == hal::PowerMode::OFF
diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
index 7379a4605d..0d79a390a7 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
@@ -88,6 +88,7 @@ bool VSyncPredictor::validate(nsecs_t timestamp) const {
             (timestamp - aValidTimestamp) % idealPeriod() * kMaxPercent / idealPeriod();
     if (percent >= kOutlierTolerancePercent &&
         percent <= (kMaxPercent - kOutlierTolerancePercent)) {
+        ATRACE_FORMAT_INSTANT("timestamp is not aligned with model");
         return false;
     }
 
@@ -98,6 +99,7 @@ bool VSyncPredictor::validate(nsecs_t timestamp) const {
     const auto distancePercent = std::abs(*iter - timestamp) * kMaxPercent / idealPeriod();
     if (distancePercent < kOutlierTolerancePercent) {
         // duplicate timestamp
+        ATRACE_FORMAT_INSTANT("duplicate timestamp");
         return false;
     }
     return true;
@@ -126,6 +128,8 @@ Period VSyncPredictor::minFramePeriodLocked() const {
 }
 
 bool VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) {
+    ATRACE_CALL();
+
     std::lock_guard lock(mMutex);
 
     if (!validate(timestamp)) {
@@ -144,6 +148,8 @@ bool VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) {
         } else {
             mKnownTimestamp = timestamp;
         }
+        ATRACE_FORMAT_INSTANT("timestamp rejected. mKnownTimestamp was %.2fms ago",
+            (systemTime() - *mKnownTimestamp) / 1e6f);
         return false;
     }
 
@@ -515,6 +521,8 @@ VSyncPredictor::Model VSyncPredictor::getVSyncPredictionModelLocked() const {
 }
 
 void VSyncPredictor::clearTimestamps() {
+    ATRACE_CALL();
+
     if (!mTimestamps.empty()) {
         auto const maxRb = *std::max_element(mTimestamps.begin(), mTimestamps.end());
         if (mKnownTimestamp) {
diff --git a/services/surfaceflinger/Scheduler/VSyncReactor.cpp b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
index 24737e4fb2..186a2d6740 100644
--- a/services/surfaceflinger/Scheduler/VSyncReactor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
@@ -53,6 +53,8 @@ VSyncReactor::VSyncReactor(PhysicalDisplayId id, std::unique_ptr<Clock> clock,
 VSyncReactor::~VSyncReactor() = default;
 
 bool VSyncReactor::addPresentFence(std::shared_ptr<FenceTime> fence) {
+    ATRACE_CALL();
+
     if (!fence) {
         return false;
     }
@@ -64,6 +66,8 @@ bool VSyncReactor::addPresentFence(std::shared_ptr<FenceTime> fence) {
 
     std::lock_guard lock(mMutex);
     if (mExternalIgnoreFences || mInternalIgnoreFences) {
+        ATRACE_FORMAT_INSTANT("mExternalIgnoreFences=%d mInternalIgnoreFences=%d",
+            mExternalIgnoreFences, mInternalIgnoreFences);
         return true;
     }
 
diff --git a/services/surfaceflinger/Scheduler/VsyncSchedule.cpp b/services/surfaceflinger/Scheduler/VsyncSchedule.cpp
index ff1c9e909a..db6a1871a7 100644
--- a/services/surfaceflinger/Scheduler/VsyncSchedule.cpp
+++ b/services/surfaceflinger/Scheduler/VsyncSchedule.cpp
@@ -19,6 +19,7 @@
 #include <common/FlagManager.h>
 
 #include <ftl/fake_guard.h>
+#include <gui/TraceUtils.h>
 #include <scheduler/Fps.h>
 #include <scheduler/Timer.h>
 
@@ -179,6 +180,7 @@ void VsyncSchedule::enableHardwareVsync() {
 }
 
 void VsyncSchedule::enableHardwareVsyncLocked() {
+    ATRACE_CALL();
     if (mHwVsyncState == HwVsyncState::Disabled) {
         getTracker().resetModel();
         mRequestHardwareVsync(mId, true);
@@ -187,6 +189,7 @@ void VsyncSchedule::enableHardwareVsyncLocked() {
 }
 
 void VsyncSchedule::disableHardwareVsync(bool disallow) {
+    ATRACE_CALL();
     std::lock_guard<std::mutex> lock(mHwVsyncLock);
     switch (mHwVsyncState) {
         case HwVsyncState::Enabled: