SF: trace adjusted expected vsync time

If SF wakes up too late, it adjusts the vsync time. We want
to add this information to the trace.

Bug: 184298850
Test: systrace
Change-Id: Iddeb23f2bd4454af762ceaabb03836427f4d0c08
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index 2dace92..d6108c7 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -1741,12 +1741,6 @@
 }
 
 void SurfaceFlinger::onMessageReceived(int32_t what, int64_t vsyncId, nsecs_t expectedVSyncTime) {
-    const auto vsyncIn = [&] {
-        if (!ATRACE_ENABLED()) return 0.f;
-        return (expectedVSyncTime - systemTime()) / 1e6f;
-    }();
-
-    ATRACE_FORMAT("onMessageReceived %" PRId64 " vsyncIn %.2fms", vsyncId, vsyncIn);
     switch (what) {
         case MessageQueue::INVALIDATE: {
             onMessageInvalidate(vsyncId, expectedVSyncTime);
@@ -1760,8 +1754,6 @@
 }
 
 void SurfaceFlinger::onMessageInvalidate(int64_t vsyncId, nsecs_t expectedVSyncTime) {
-    ATRACE_CALL();
-
     const nsecs_t frameStart = systemTime();
     // calculate the expected present time once and use the cached
     // value throughout this frame to make sure all layers are
@@ -1776,6 +1768,13 @@
     const nsecs_t lastScheduledPresentTime = mScheduledPresentTime;
     mScheduledPresentTime = expectedVSyncTime;
 
+    const auto vsyncIn = [&] {
+        if (!ATRACE_ENABLED()) return 0.f;
+        return (mExpectedPresentTime - systemTime()) / 1e6f;
+    }();
+    ATRACE_FORMAT("onMessageInvalidate %" PRId64 " vsyncIn %.2fms%s", vsyncId, vsyncIn,
+                  mExpectedPresentTime == expectedVSyncTime ? "" : " (adjusted)");
+
     // When Backpressure propagation is enabled we want to give a small grace period
     // for the present fence to fire instead of just giving up on this frame to handle cases
     // where present fence is just about to get signaled.