SurfaceFlinger: expected present time directly from VSyncReactor

When SurfaceFlinger calculates what is the vsync time, it does
that by asking VSyncReactor what is next anticipated vsync from the
wake up time. To handle negative offsets (when SF wakes up more than
a vsync period before a vsync event) SF adds a vsync period
to that anticipated vsync.

This creates a race condition where the offset used at the
time of invalidate may be different than the offset used by
VSyncReactor calculated at the time of the requestNextVsync().
To fix that, we plumb the first calculated vsync time to
SurfaceFlinger.

Bug: 154303002
Test: Run app transitions and collect systrace
Change-Id: I3f2670c7b0ecb52a85fb07df6d360694b51d5d66
diff --git a/services/surfaceflinger/Scheduler/DispSync.cpp b/services/surfaceflinger/Scheduler/DispSync.cpp
index fc6ccae..ff91bf7 100644
--- a/services/surfaceflinger/Scheduler/DispSync.cpp
+++ b/services/surfaceflinger/Scheduler/DispSync.cpp
@@ -200,7 +200,8 @@
                     }
                 }
 
-                callbackInvocations = gatherCallbackInvocationsLocked(now);
+                callbackInvocations =
+                        gatherCallbackInvocationsLocked(now, computeNextRefreshLocked(0, now));
             }
 
             if (callbackInvocations.size() > 0) {
@@ -303,6 +304,11 @@
         return BAD_VALUE;
     }
 
+    nsecs_t computeNextRefresh(int periodOffset, nsecs_t now) const {
+        Mutex::Autolock lock(mMutex);
+        return computeNextRefreshLocked(periodOffset, now);
+    }
+
 private:
     struct EventListener {
         const char* mName;
@@ -315,6 +321,7 @@
     struct CallbackInvocation {
         DispSync::Callback* mCallback;
         nsecs_t mEventTime;
+        nsecs_t mExpectedVSyncTime;
     };
 
     nsecs_t computeNextEventTimeLocked(nsecs_t now) {
@@ -340,7 +347,8 @@
         return duration < (3 * mPeriod) / 5;
     }
 
-    std::vector<CallbackInvocation> gatherCallbackInvocationsLocked(nsecs_t now) {
+    std::vector<CallbackInvocation> gatherCallbackInvocationsLocked(nsecs_t now,
+                                                                    nsecs_t expectedVSyncTime) {
         if (mTraceDetailedInfo) ATRACE_CALL();
         ALOGV("[%s] gatherCallbackInvocationsLocked @ %" PRId64, mName, ns2us(now));
 
@@ -361,6 +369,10 @@
                 CallbackInvocation ci;
                 ci.mCallback = eventListener.mCallback;
                 ci.mEventTime = t;
+                ci.mExpectedVSyncTime = expectedVSyncTime;
+                if (eventListener.mPhase < 0) {
+                    ci.mExpectedVSyncTime += mPeriod;
+                }
                 ALOGV("[%s] [%s] Preparing to fire, latency: %" PRId64, mName, eventListener.mName,
                       t - eventListener.mLastEventTime);
                 callbackInvocations.push_back(ci);
@@ -426,10 +438,19 @@
     void fireCallbackInvocations(const std::vector<CallbackInvocation>& callbacks) {
         if (mTraceDetailedInfo) ATRACE_CALL();
         for (size_t i = 0; i < callbacks.size(); i++) {
-            callbacks[i].mCallback->onDispSyncEvent(callbacks[i].mEventTime);
+            callbacks[i].mCallback->onDispSyncEvent(callbacks[i].mEventTime,
+                                                    callbacks[i].mExpectedVSyncTime);
         }
     }
 
+    nsecs_t computeNextRefreshLocked(int periodOffset, nsecs_t now) const {
+        nsecs_t phase = mReferenceTime + mPhase;
+        if (mPeriod == 0) {
+            return 0;
+        }
+        return (((now - phase) / mPeriod) + periodOffset + 1) * mPeriod + phase;
+    }
+
     const char* const mName;
 
     bool mStop;
@@ -444,7 +465,7 @@
 
     std::vector<EventListener> mEventListeners;
 
-    Mutex mMutex;
+    mutable Mutex mMutex;
     Condition mCond;
 
     // Flag to turn on logging in systrace.
@@ -458,7 +479,7 @@
 public:
     ZeroPhaseTracer() : mParity("ZERO_PHASE_VSYNC", false) {}
 
-    virtual void onDispSyncEvent(nsecs_t /*when*/) {
+    virtual void onDispSyncEvent(nsecs_t /*when*/, nsecs_t /*expectedVSyncTimestamp*/) {
         mParity = !mParity;
     }
 
@@ -845,7 +866,7 @@
     const uint32_t hwcLatency = 0;
 
     // Ask DispSync when the next refresh will be (CLOCK_MONOTONIC).
-    return computeNextRefresh(hwcLatency, now);
+    return mThread->computeNextRefresh(hwcLatency, now);
 }
 
 } // namespace impl
diff --git a/services/surfaceflinger/Scheduler/DispSync.h b/services/surfaceflinger/Scheduler/DispSync.h
index 2faa81c..832f08e 100644
--- a/services/surfaceflinger/Scheduler/DispSync.h
+++ b/services/surfaceflinger/Scheduler/DispSync.h
@@ -36,7 +36,7 @@
     public:
         Callback() = default;
         virtual ~Callback();
-        virtual void onDispSyncEvent(nsecs_t when) = 0;
+        virtual void onDispSyncEvent(nsecs_t when, nsecs_t expectedVSyncTimestamp) = 0;
 
     protected:
         Callback(Callback const&) = delete;
diff --git a/services/surfaceflinger/Scheduler/DispSyncSource.cpp b/services/surfaceflinger/Scheduler/DispSyncSource.cpp
index 4e3f85f..8752b66 100644
--- a/services/surfaceflinger/Scheduler/DispSyncSource.cpp
+++ b/services/surfaceflinger/Scheduler/DispSyncSource.cpp
@@ -92,7 +92,7 @@
     }
 }
 
-void DispSyncSource::onDispSyncEvent(nsecs_t when) {
+void DispSyncSource::onDispSyncEvent(nsecs_t when, nsecs_t expectedVSyncTimestamp) {
     VSyncSource::Callback* callback;
     {
         std::lock_guard lock(mCallbackMutex);
@@ -104,7 +104,7 @@
     }
 
     if (callback != nullptr) {
-        callback->onVSyncEvent(when);
+        callback->onVSyncEvent(when, expectedVSyncTimestamp);
     }
 }
 
diff --git a/services/surfaceflinger/Scheduler/DispSyncSource.h b/services/surfaceflinger/Scheduler/DispSyncSource.h
index f278712..2aee3f6 100644
--- a/services/surfaceflinger/Scheduler/DispSyncSource.h
+++ b/services/surfaceflinger/Scheduler/DispSyncSource.h
@@ -40,7 +40,7 @@
 
 private:
     // The following method is the implementation of the DispSync::Callback.
-    virtual void onDispSyncEvent(nsecs_t when);
+    void onDispSyncEvent(nsecs_t when, nsecs_t expectedVSyncTimestamp) override;
 
     const char* const mName;
     TracedOrdinal<int> mValue;
diff --git a/services/surfaceflinger/Scheduler/EventThread.cpp b/services/surfaceflinger/Scheduler/EventThread.cpp
index 8347650..5dedb6a 100644
--- a/services/surfaceflinger/Scheduler/EventThread.cpp
+++ b/services/surfaceflinger/Scheduler/EventThread.cpp
@@ -79,8 +79,9 @@
                                 event.hotplug.connected ? "connected" : "disconnected");
         case DisplayEventReceiver::DISPLAY_EVENT_VSYNC:
             return StringPrintf("VSync{displayId=%" ANDROID_PHYSICAL_DISPLAY_ID_FORMAT
-                                ", count=%u}",
-                                event.header.displayId, event.vsync.count);
+                                ", count=%u, expectedVSyncTimestamp=%" PRId64 "}",
+                                event.header.displayId, event.vsync.count,
+                                event.vsync.expectedVSyncTimestamp);
         case DisplayEventReceiver::DISPLAY_EVENT_CONFIG_CHANGED:
             return StringPrintf("ConfigChanged{displayId=%" ANDROID_PHYSICAL_DISPLAY_ID_FORMAT
                                 ", configId=%u}",
@@ -99,10 +100,11 @@
 }
 
 DisplayEventReceiver::Event makeVSync(PhysicalDisplayId displayId, nsecs_t timestamp,
-                                      uint32_t count) {
+                                      uint32_t count, nsecs_t expectedVSyncTimestamp) {
     DisplayEventReceiver::Event event;
     event.header = {DisplayEventReceiver::DISPLAY_EVENT_VSYNC, displayId, timestamp};
     event.vsync.count = count;
+    event.vsync.expectedVSyncTimestamp = expectedVSyncTimestamp;
     return event;
 }
 
@@ -312,11 +314,12 @@
     mCondition.notify_all();
 }
 
-void EventThread::onVSyncEvent(nsecs_t timestamp) {
+void EventThread::onVSyncEvent(nsecs_t timestamp, nsecs_t expectedVSyncTimestamp) {
     std::lock_guard<std::mutex> lock(mMutex);
 
     LOG_FATAL_IF(!mVSyncState);
-    mPendingEvents.push_back(makeVSync(mVSyncState->displayId, timestamp, ++mVSyncState->count));
+    mPendingEvents.push_back(makeVSync(mVSyncState->displayId, timestamp, ++mVSyncState->count,
+                                       expectedVSyncTimestamp));
     mCondition.notify_all();
 }
 
@@ -423,7 +426,8 @@
         } else {
             // Generate a fake VSYNC after a long timeout in case the driver stalls. When the
             // display is off, keep feeding clients at 60 Hz.
-            const auto timeout = mState == State::SyntheticVSync ? 16ms : 1000ms;
+            const std::chrono::nanoseconds timeout =
+                    mState == State::SyntheticVSync ? 16ms : 1000ms;
             if (mCondition.wait_for(lock, timeout) == std::cv_status::timeout) {
                 if (mState == State::VSync) {
                     ALOGW("Faking VSYNC due to driver stall for thread %s", mThreadName);
@@ -439,9 +443,10 @@
                 }
 
                 LOG_FATAL_IF(!mVSyncState);
-                mPendingEvents.push_back(makeVSync(mVSyncState->displayId,
-                                                   systemTime(SYSTEM_TIME_MONOTONIC),
-                                                   ++mVSyncState->count));
+                const auto now = systemTime(SYSTEM_TIME_MONOTONIC);
+                const auto expectedVSyncTime = now + timeout.count();
+                mPendingEvents.push_back(makeVSync(mVSyncState->displayId, now,
+                                                   ++mVSyncState->count, expectedVSyncTime));
             }
         }
     }
diff --git a/services/surfaceflinger/Scheduler/EventThread.h b/services/surfaceflinger/Scheduler/EventThread.h
index 98b1876..9e7086e 100644
--- a/services/surfaceflinger/Scheduler/EventThread.h
+++ b/services/surfaceflinger/Scheduler/EventThread.h
@@ -57,7 +57,7 @@
     class Callback {
     public:
         virtual ~Callback() {}
-        virtual void onVSyncEvent(nsecs_t when) = 0;
+        virtual void onVSyncEvent(nsecs_t when, nsecs_t expectedVSyncTimestamp) = 0;
     };
 
     virtual ~VSyncSource() {}
@@ -189,7 +189,7 @@
             REQUIRES(mMutex);
 
     // Implements VSyncSource::Callback
-    void onVSyncEvent(nsecs_t timestamp) override;
+    void onVSyncEvent(nsecs_t timestamp, nsecs_t expectedVSyncTimestamp) override;
 
     const std::unique_ptr<VSyncSource> mVSyncSource GUARDED_BY(mMutex);
 
diff --git a/services/surfaceflinger/Scheduler/InjectVSyncSource.h b/services/surfaceflinger/Scheduler/InjectVSyncSource.h
index 31da588..975c9db 100644
--- a/services/surfaceflinger/Scheduler/InjectVSyncSource.h
+++ b/services/surfaceflinger/Scheduler/InjectVSyncSource.h
@@ -35,10 +35,10 @@
         mCallback = callback;
     }
 
-    void onInjectSyncEvent(nsecs_t when) {
+    void onInjectSyncEvent(nsecs_t when, nsecs_t expectedVSyncTimestamp) {
         std::lock_guard<std::mutex> lock(mCallbackMutex);
         if (mCallback) {
-            mCallback->onVSyncEvent(when);
+            mCallback->onVSyncEvent(when, expectedVSyncTimestamp);
         }
     }
 
diff --git a/services/surfaceflinger/Scheduler/MessageQueue.cpp b/services/surfaceflinger/Scheduler/MessageQueue.cpp
index d8a666a..9d6e1d8 100644
--- a/services/surfaceflinger/Scheduler/MessageQueue.cpp
+++ b/services/surfaceflinger/Scheduler/MessageQueue.cpp
@@ -62,9 +62,9 @@
     }
 }
 
-void MessageQueue::Handler::dispatchInvalidate(nsecs_t timestamp) {
+void MessageQueue::Handler::dispatchInvalidate(nsecs_t expectedVSyncTimestamp) {
     if ((android_atomic_or(eventMaskInvalidate, &mEventMask) & eventMaskInvalidate) == 0) {
-        mLastVsyncTime = timestamp;
+        mExpectedVSyncTime = expectedVSyncTimestamp;
         mQueue.mLooper->sendMessage(this, Message(MessageQueue::INVALIDATE));
     }
 }
@@ -73,11 +73,11 @@
     switch (message.what) {
         case INVALIDATE:
             android_atomic_and(~eventMaskInvalidate, &mEventMask);
-            mQueue.mFlinger->onMessageReceived(message.what, mLastVsyncTime);
+            mQueue.mFlinger->onMessageReceived(message.what, mExpectedVSyncTime);
             break;
         case REFRESH:
             android_atomic_and(~eventMaskRefresh, &mEventMask);
-            mQueue.mFlinger->onMessageReceived(message.what, mLastVsyncTime);
+            mQueue.mFlinger->onMessageReceived(message.what, mExpectedVSyncTime);
             break;
     }
 }
@@ -152,7 +152,7 @@
     while ((n = DisplayEventReceiver::getEvents(&mEventTube, buffer, 8)) > 0) {
         for (int i = 0; i < n; i++) {
             if (buffer[i].header.type == DisplayEventReceiver::DISPLAY_EVENT_VSYNC) {
-                mHandler->dispatchInvalidate(buffer[i].header.timestamp);
+                mHandler->dispatchInvalidate(buffer[i].vsync.expectedVSyncTimestamp);
                 break;
             }
         }
diff --git a/services/surfaceflinger/Scheduler/MessageQueue.h b/services/surfaceflinger/Scheduler/MessageQueue.h
index dbd5e96..ebc4315 100644
--- a/services/surfaceflinger/Scheduler/MessageQueue.h
+++ b/services/surfaceflinger/Scheduler/MessageQueue.h
@@ -101,13 +101,13 @@
         enum { eventMaskInvalidate = 0x1, eventMaskRefresh = 0x2, eventMaskTransaction = 0x4 };
         MessageQueue& mQueue;
         int32_t mEventMask;
-        std::atomic<nsecs_t> mLastVsyncTime;
+        std::atomic<nsecs_t> mExpectedVSyncTime;
 
     public:
         explicit Handler(MessageQueue& queue) : mQueue(queue), mEventMask(0) {}
         virtual void handleMessage(const Message& message);
         void dispatchRefresh();
-        void dispatchInvalidate(nsecs_t timestamp);
+        void dispatchInvalidate(nsecs_t expectedVSyncTimestamp);
     };
 
     friend class Handler;
diff --git a/services/surfaceflinger/Scheduler/Scheduler.cpp b/services/surfaceflinger/Scheduler/Scheduler.cpp
index 3a84b67..86bb6eb 100644
--- a/services/surfaceflinger/Scheduler/Scheduler.cpp
+++ b/services/surfaceflinger/Scheduler/Scheduler.cpp
@@ -276,12 +276,12 @@
     return mInjectorConnectionHandle;
 }
 
-bool Scheduler::injectVSync(nsecs_t when) {
+bool Scheduler::injectVSync(nsecs_t when, nsecs_t expectedVSyncTime) {
     if (!mInjectVSyncs || !mVSyncInjector) {
         return false;
     }
 
-    mVSyncInjector->onInjectSyncEvent(when);
+    mVSyncInjector->onInjectSyncEvent(when, expectedVSyncTime);
     return true;
 }
 
diff --git a/services/surfaceflinger/Scheduler/Scheduler.h b/services/surfaceflinger/Scheduler/Scheduler.h
index 75c02f3..4a0280f 100644
--- a/services/surfaceflinger/Scheduler/Scheduler.h
+++ b/services/surfaceflinger/Scheduler/Scheduler.h
@@ -95,7 +95,7 @@
     ConnectionHandle enableVSyncInjection(bool enable);
 
     // Returns false if injection is disabled.
-    bool injectVSync(nsecs_t when);
+    bool injectVSync(nsecs_t when, nsecs_t expectedVSyncTime);
 
     void enableHardwareVsync();
     void disableHardwareVsync(bool makeUnavailable);
diff --git a/services/surfaceflinger/Scheduler/VSyncReactor.cpp b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
index 2f1faac..5f0c9ce 100644
--- a/services/surfaceflinger/Scheduler/VSyncReactor.cpp
+++ b/services/surfaceflinger/Scheduler/VSyncReactor.cpp
@@ -128,7 +128,7 @@
             mLastCallTime = vsynctime;
         }
 
-        mCallback->onDispSyncEvent(wakeupTime);
+        mCallback->onDispSyncEvent(wakeupTime, vsynctime);
 
         {
             std::lock_guard<std::mutex> lk(mMutex);