commit f0b2bf94857bae86992feee2b6736138c3147c2d
author Ady Abraham <adyabr@google.com> Wed Dec 13 23:36:35 2023 +0000
committer Ady Abraham <adyabr@google.com> Thu Dec 14 00:29:11 2023 +0000
tree 0b5ce990dde2d98ee9fc2cd54d316baa14d9ea0f
parent f2f5f26192e10045d780e03b4e199503b4ba98c2

SF: add more traces when adding vsync timestamps

Bug: 316224736
Change-Id: I264e728c49f0500f2f868c3a25b0910d0d527340
Test: presubmit

services/surfaceflinger/Scheduler/Scheduler.cpp

diff --git a/services/surfaceflinger/Scheduler/Scheduler.cpp b/services/surfaceflinger/Scheduler/Scheduler.cpp
index 6a85788..4440177 100644
--- a/services/surfaceflinger/Scheduler/Scheduler.cpp
+++ b/services/surfaceflinger/Scheduler/Scheduler.cpp
@@ -630,6 +630,7 @@
 }
 
 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

services/surfaceflinger/Scheduler/VSyncPredictor.cpp

diff --git a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
index 7379a46..0d79a39 100644
--- a/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncPredictor.cpp
@@ -88,6 +88,7 @@
             (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 @@
     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 @@
 }
 
 bool VSyncPredictor::addVsyncTimestamp(nsecs_t timestamp) {
+    ATRACE_CALL();
+
     std::lock_guard lock(mMutex);
 
     if (!validate(timestamp)) {
@@ -144,6 +148,8 @@
         } else {
             mKnownTimestamp = timestamp;
         }
+        ATRACE_FORMAT_INSTANT("timestamp rejected. mKnownTimestamp was %.2fms ago",
+            (systemTime() - *mKnownTimestamp) / 1e6f);
         return false;
     }
 
@@ -515,6 +521,8 @@
 }
 
 void VSyncPredictor::clearTimestamps() {
+    ATRACE_CALL();
+
     if (!mTimestamps.empty()) {
         auto const maxRb = *std::max_element(mTimestamps.begin(), mTimestamps.end());
         if (mKnownTimestamp) {

services/surfaceflinger/Scheduler/VSyncReactor.cpp

diff --git a/services/surfaceflinger/Scheduler/VSyncReactor.cpp b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
index 24737e4..186a2d6 100644
--- a/services/surfaceflinger/Scheduler/VSyncReactor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
@@ -53,6 +53,8 @@
 VSyncReactor::~VSyncReactor() = default;
 
 bool VSyncReactor::addPresentFence(std::shared_ptr<FenceTime> fence) {
+    ATRACE_CALL();
+
     if (!fence) {
         return false;
     }
@@ -64,6 +66,8 @@
 
     std::lock_guard lock(mMutex);
     if (mExternalIgnoreFences || mInternalIgnoreFences) {
+        ATRACE_FORMAT_INSTANT("mExternalIgnoreFences=%d mInternalIgnoreFences=%d",
+            mExternalIgnoreFences, mInternalIgnoreFences);
         return true;
     }
 

services/surfaceflinger/Scheduler/VsyncSchedule.cpp

diff --git a/services/surfaceflinger/Scheduler/VsyncSchedule.cpp b/services/surfaceflinger/Scheduler/VsyncSchedule.cpp
index ff1c9e9..db6a187 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::enableHardwareVsyncLocked() {
+    ATRACE_CALL();
     if (mHwVsyncState == HwVsyncState::Disabled) {
         getTracker().resetModel();
         mRequestHardwareVsync(mId, true);
@@ -187,6 +189,7 @@
 }
 
 void VsyncSchedule::disableHardwareVsync(bool disallow) {
+    ATRACE_CALL();
     std::lock_guard<std::mutex> lock(mHwVsyncLock);
     switch (mHwVsyncState) {
         case HwVsyncState::Enabled: