Add a DequeueReady FrameEvent

Test: adb shell /data/nativetest/libgui_test/libgui_test
--gtest_filter=*GetFrameTimestamps*

Change-Id: I98ffd4123fc50b5f560e432f4078408c913c8edf
diff --git a/include/gui/FrameTimestamps.h b/include/gui/FrameTimestamps.h
index 7d62706..46ca2c2 100644
--- a/include/gui/FrameTimestamps.h
+++ b/include/gui/FrameTimestamps.h
@@ -44,6 +44,7 @@
     GL_COMPOSITION_DONE,
     DISPLAY_PRESENT,
     DISPLAY_RETIRE,
+    DEQUEUE_READY,
     RELEASE,
     EVENT_COUNT, // Not an actual event.
 };
@@ -61,6 +62,7 @@
     bool hasDisplayPresentInfo() const;
     bool hasDisplayRetireInfo() const;
     bool hasReleaseInfo() const;
+    bool hasDequeueReadyInfo() const;
 
     void checkFencesForCompletion();
     void dump(String8& outString) const;
@@ -84,6 +86,7 @@
     nsecs_t latchTime{-1};
     nsecs_t firstRefreshStartTime{-1};
     nsecs_t lastRefreshStartTime{-1};
+    nsecs_t dequeueReadyTime{-1};
 
     std::shared_ptr<FenceTime> acquireFence{FenceTime::NO_FENCE};
     std::shared_ptr<FenceTime> gpuCompositionDoneFence{FenceTime::NO_FENCE};
@@ -194,7 +197,7 @@
             const std::shared_ptr<FenceTime>& displayPresent);
     void addRetire(uint64_t frameNumber,
             const std::shared_ptr<FenceTime>& displayRetire);
-    void addRelease(uint64_t frameNumber,
+    void addRelease(uint64_t frameNumber, nsecs_t dequeueReadyTime,
             std::shared_ptr<FenceTime>&& release);
 
     void getAndResetDelta(FrameEventHistoryDelta* delta);
@@ -255,6 +258,7 @@
     nsecs_t mLatchTime{0};
     nsecs_t mFirstRefreshStartTime{0};
     nsecs_t mLastRefreshStartTime{0};
+    nsecs_t mDequeueReadyTime{0};
 
     FenceTime::Snapshot mGpuCompositionDoneFence;
     FenceTime::Snapshot mDisplayPresentFence;
diff --git a/libs/gui/FrameTimestamps.cpp b/libs/gui/FrameTimestamps.cpp
index fb242f7..73537bf 100644
--- a/libs/gui/FrameTimestamps.cpp
+++ b/libs/gui/FrameTimestamps.cpp
@@ -55,6 +55,10 @@
     return addRetireCalled || addReleaseCalled;
 }
 
+bool FrameEvents::hasDequeueReadyInfo() const {
+    return Fence::isValidTimestamp(dequeueReadyTime);
+}
+
 bool FrameEvents::hasAcquireInfo() const {
     return acquireFence->isValid();
 }
@@ -141,6 +145,14 @@
             !addPostCompositeCalled, *displayPresentFence);
     dumpFenceTime(outString, "Display Retire    \t",
             !addRetireCalled, *displayRetireFence);
+
+    outString.appendFormat("--- DequeueReady  \t");
+    if (Fence::isValidTimestamp(dequeueReadyTime)) {
+        outString.appendFormat("%" PRId64 "\n", dequeueReadyTime);
+    } else {
+        outString.appendFormat("Pending\n");
+    }
+
     dumpFenceTime(outString, "Release           \t",
             true, *releaseFence);
 }
@@ -262,6 +274,7 @@
         frame.latchTime = d.mLatchTime;
         frame.firstRefreshStartTime = d.mFirstRefreshStartTime;
         frame.lastRefreshStartTime = d.mLastRefreshStartTime;
+        frame.dequeueReadyTime = d.mDequeueReadyTime;
 
         if (frame.frameNumber != d.mFrameNumber) {
             // We got a new frame. Initialize some of the fields.
@@ -411,14 +424,15 @@
     mFramesDirty[mRetireOffset].setDirty<FrameEvent::DISPLAY_RETIRE>();
 }
 
-void ConsumerFrameEventHistory::addRelease(
-        uint64_t frameNumber, std::shared_ptr<FenceTime>&& release) {
+void ConsumerFrameEventHistory::addRelease(uint64_t frameNumber,
+        nsecs_t dequeueReadyTime, std::shared_ptr<FenceTime>&& release) {
     FrameEvents* frame = getFrame(frameNumber, &mReleaseOffset);
     if (frame == nullptr) {
         ALOGE("ConsumerFrameEventHistory::addRelease: Did not find frame.");
         return;
     }
     frame->addReleaseCalled = true;
+    frame->dequeueReadyTime = dequeueReadyTime;
     frame->releaseFence = std::move(release);
     mFramesDirty[mReleaseOffset].setDirty<FrameEvent::RELEASE>();
 }
@@ -467,7 +481,8 @@
       mRequestedPresentTime(frameTimestamps.requestedPresentTime),
       mLatchTime(frameTimestamps.latchTime),
       mFirstRefreshStartTime(frameTimestamps.firstRefreshStartTime),
-      mLastRefreshStartTime(frameTimestamps.lastRefreshStartTime) {
+      mLastRefreshStartTime(frameTimestamps.lastRefreshStartTime),
+      mDequeueReadyTime(frameTimestamps.dequeueReadyTime) {
     if (dirtyFields.isDirty<FrameEvent::GL_COMPOSITION_DONE>()) {
         mGpuCompositionDoneFence =
                 frameTimestamps.gpuCompositionDoneFence->getSnapshot();
@@ -495,7 +510,8 @@
             sizeof(FrameEventsDelta::mRequestedPresentTime) +
             sizeof(FrameEventsDelta::mLatchTime) +
             sizeof(FrameEventsDelta::mFirstRefreshStartTime) +
-            sizeof(FrameEventsDelta::mLastRefreshStartTime);
+            sizeof(FrameEventsDelta::mLastRefreshStartTime) +
+            sizeof(FrameEventsDelta::mDequeueReadyTime);
     return min;
 }
 
@@ -544,6 +560,7 @@
     FlattenableUtils::write(buffer, size, mLatchTime);
     FlattenableUtils::write(buffer, size, mFirstRefreshStartTime);
     FlattenableUtils::write(buffer, size, mLastRefreshStartTime);
+    FlattenableUtils::write(buffer, size, mDequeueReadyTime);
 
     // Fences
     for (auto fence : allFences(this)) {
@@ -582,6 +599,7 @@
     FlattenableUtils::read(buffer, size, mLatchTime);
     FlattenableUtils::read(buffer, size, mFirstRefreshStartTime);
     FlattenableUtils::read(buffer, size, mLastRefreshStartTime);
+    FlattenableUtils::read(buffer, size, mDequeueReadyTime);
 
     // Fences
     for (auto fence : allFences(this)) {
diff --git a/libs/gui/tests/Surface_test.cpp b/libs/gui/tests/Surface_test.cpp
index 2206902..858a2d3 100644
--- a/libs/gui/tests/Surface_test.cpp
+++ b/libs/gui/tests/Surface_test.cpp
@@ -522,8 +522,9 @@
               kProducerAcquireTime(frameStartTime + 300),
               kConsumerAcquireTime(frameStartTime + 301),
               kLatchTime(frameStartTime + 500),
-              kRetireTime(frameStartTime + 600),
-              kReleaseTime(frameStartTime + 700),
+              kDequeueReadyTime(frameStartTime + 600),
+              kRetireTime(frameStartTime + 700),
+              kReleaseTime(frameStartTime + 800),
               mRefreshes {
                     { mFenceMap, frameStartTime + 410 },
                     { mFenceMap, frameStartTime + 420 },
@@ -559,6 +560,7 @@
         const nsecs_t kProducerAcquireTime;
         const nsecs_t kConsumerAcquireTime;
         const nsecs_t kLatchTime;
+        const nsecs_t kDequeueReadyTime;
         const nsecs_t kRetireTime;
         const nsecs_t kReleaseTime;
 
@@ -654,7 +656,7 @@
         // HWC2 releases the previous buffer after a new latch just before
         // calling postComposition.
         if (oldFrame != nullptr) {
-            mCfeh->addRelease(nOldFrame,
+            mCfeh->addRelease(nOldFrame, oldFrame->kDequeueReadyTime,
                     std::shared_ptr<FenceTime>(oldFrame->mRelease.mFenceTime));
         }
         mCfeh->addPostComposition(nNewFrame, gpuDoneFenceTime,
diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp
index 9eaf57b..72f6a7e 100644
--- a/services/surfaceflinger/Layer.cpp
+++ b/services/surfaceflinger/Layer.cpp
@@ -1796,7 +1796,7 @@
 }
 
 #ifdef USE_HWC2
-void Layer::releasePendingBuffer() {
+void Layer::releasePendingBuffer(nsecs_t dequeueReadyTime) {
     mSurfaceFlingerConsumer->releasePendingBuffer();
     auto releaseFenceTime = std::make_shared<FenceTime>(
             mSurfaceFlingerConsumer->getPrevFinalReleaseFence());
@@ -1804,7 +1804,7 @@
 
     Mutex::Autolock lock(mFrameEventHistoryMutex);
     mFrameEventHistory.addRelease(
-            mPreviousFrameNumber, std::move(releaseFenceTime));
+            mPreviousFrameNumber, dequeueReadyTime, std::move(releaseFenceTime));
 }
 #endif
 
@@ -1981,7 +1981,7 @@
                 mSurfaceFlingerConsumer->getPrevFinalReleaseFence());
         mReleaseTimeline.push(releaseFenceTime);
         mFrameEventHistory.addRelease(
-                mPreviousFrameNumber, std::move(releaseFenceTime));
+                mPreviousFrameNumber, latchTime, std::move(releaseFenceTime));
 #endif
     }
 
diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h
index c3eab37..92d2292 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -286,7 +286,7 @@
 
 #ifdef USE_HWC2
     // If a buffer was replaced this frame, release the former buffer
-    void releasePendingBuffer();
+    void releasePendingBuffer(nsecs_t dequeueReadyTime);
 #endif
 
     /*
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index 193b702..23c4b30 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -1226,8 +1226,9 @@
     ALOGV("postComposition");
 
     // Release any buffers which were replaced this frame
+    nsecs_t dequeueReadyTime = systemTime();
     for (auto& layer : mLayersWithQueuedFrames) {
-        layer->releasePendingBuffer();
+        layer->releasePendingBuffer(dequeueReadyTime);
     }
 
     const sp<const DisplayDevice> hw(getDefaultDisplayDevice());