SF: add more traces when adding vsync timestamps

Bug: 316224736
Change-Id: I264e728c49f0500f2f868c3a25b0910d0d527340
Test: presubmit
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) {