Assign previous release fence to previous frame ID

...as otherwise the release timestamps for EGL/Vk timing apis are
shifted by one frame.

Bug: 295456126
Bug: 301055892
Bug: 303385401
Bug: 310927247
Test: Log and inspect timestamps
Change-Id: If1d8a525053591f15b95aeec8dc0bad8a13e6833

11 files changed, 148 insertions, 16 deletions

diff --git a/libs/gui/BLASTBufferQueue.cpp b/libs/gui/BLASTBufferQueue.cpp
index 8d0331ebb5..f317a2eea0 100644
--- a/libs/gui/BLASTBufferQueue.cpp
+++ b/libs/gui/BLASTBufferQueue.cpp
@@ -41,6 +41,8 @@
 #include <android-base/thread_annotations.h>
 #include <chrono>
 
+#include <com_android_graphics_libgui_flags.h>
+
 using namespace com::android::graphics::libgui;
 using namespace std::chrono_literals;
 
@@ -102,12 +104,11 @@ void BLASTBufferItemConsumer::addAndGetFrameTimestamps(const NewFrameEventsEntry
     }
 }
 
-void BLASTBufferItemConsumer::updateFrameTimestamps(uint64_t frameNumber, nsecs_t refreshStartTime,
-                                                    const sp<Fence>& glDoneFence,
-                                                    const sp<Fence>& presentFence,
-                                                    const sp<Fence>& prevReleaseFence,
-                                                    CompositorTiming compositorTiming,
-                                                    nsecs_t latchTime, nsecs_t dequeueReadyTime) {
+void BLASTBufferItemConsumer::updateFrameTimestamps(
+        uint64_t frameNumber, uint64_t previousFrameNumber, nsecs_t refreshStartTime,
+        const sp<Fence>& glDoneFence, const sp<Fence>& presentFence,
+        const sp<Fence>& prevReleaseFence, CompositorTiming compositorTiming, nsecs_t latchTime,
+        nsecs_t dequeueReadyTime) {
     Mutex::Autolock lock(mMutex);
 
     // if the producer is not connected, don't bother updating,
@@ -118,7 +119,15 @@ void BLASTBufferItemConsumer::updateFrameTimestamps(uint64_t frameNumber, nsecs_
     std::shared_ptr<FenceTime> releaseFenceTime = std::make_shared<FenceTime>(prevReleaseFence);
 
     mFrameEventHistory.addLatch(frameNumber, latchTime);
-    mFrameEventHistory.addRelease(frameNumber, dequeueReadyTime, std::move(releaseFenceTime));
+    if (flags::frametimestamps_previousrelease()) {
+        if (previousFrameNumber > 0) {
+            mFrameEventHistory.addRelease(previousFrameNumber, dequeueReadyTime,
+                                          std::move(releaseFenceTime));
+        }
+    } else {
+        mFrameEventHistory.addRelease(frameNumber, dequeueReadyTime, std::move(releaseFenceTime));
+    }
+
     mFrameEventHistory.addPreComposition(frameNumber, refreshStartTime);
     mFrameEventHistory.addPostComposition(frameNumber, glDoneFenceTime, presentFenceTime,
                                           compositorTiming);
@@ -364,6 +373,7 @@ void BLASTBufferQueue::transactionCallback(nsecs_t /*latchTime*/, const sp<Fence
                 if (stat.latchTime > 0) {
                     mBufferItemConsumer
                             ->updateFrameTimestamps(stat.frameEventStats.frameNumber,
+                                                    stat.frameEventStats.previousFrameNumber,
                                                     stat.frameEventStats.refreshStartTime,
                                                     stat.frameEventStats.gpuCompositionDoneFence,
                                                     stat.presentFence, stat.previousReleaseFence,
diff --git a/libs/gui/ITransactionCompletedListener.cpp b/libs/gui/ITransactionCompletedListener.cpp
index 29d64afb24..f5d19aac78 100644
--- a/libs/gui/ITransactionCompletedListener.cpp
+++ b/libs/gui/ITransactionCompletedListener.cpp
@@ -25,6 +25,10 @@
 #include <gui/LayerState.h>
 #include <private/gui/ParcelUtils.h>
 
+#include <com_android_graphics_libgui_flags.h>
+
+using namespace com::android::graphics::libgui;
+
 namespace android {
 
 namespace { // Anonymous
@@ -49,6 +53,11 @@ status_t FrameEventHistoryStats::writeToParcel(Parcel* output) const {
     status_t err = output->writeUint64(frameNumber);
     if (err != NO_ERROR) return err;
 
+    if (flags::frametimestamps_previousrelease()) {
+        err = output->writeUint64(previousFrameNumber);
+        if (err != NO_ERROR) return err;
+    }
+
     if (gpuCompositionDoneFence) {
         err = output->writeBool(true);
         if (err != NO_ERROR) return err;
@@ -79,6 +88,11 @@ status_t FrameEventHistoryStats::readFromParcel(const Parcel* input) {
     status_t err = input->readUint64(&frameNumber);
     if (err != NO_ERROR) return err;
 
+    if (flags::frametimestamps_previousrelease()) {
+        err = input->readUint64(&previousFrameNumber);
+        if (err != NO_ERROR) return err;
+    }
+
     bool hasFence = false;
     err = input->readBool(&hasFence);
     if (err != NO_ERROR) return err;
diff --git a/libs/gui/fuzzer/libgui_bufferQueue_fuzzer.cpp b/libs/gui/fuzzer/libgui_bufferQueue_fuzzer.cpp
index 17f4c630ce..2e270b721f 100644
--- a/libs/gui/fuzzer/libgui_bufferQueue_fuzzer.cpp
+++ b/libs/gui/fuzzer/libgui_bufferQueue_fuzzer.cpp
@@ -141,8 +141,8 @@ void BufferQueueFuzzer::invokeBlastBufferQueue() {
     CompositorTiming compTiming;
     sp<Fence> previousFence = new Fence(memfd_create("pfd", MFD_ALLOW_SEALING));
     sp<Fence> gpuFence = new Fence(memfd_create("gfd", MFD_ALLOW_SEALING));
-    FrameEventHistoryStats frameStats(frameNumber, gpuFence, compTiming,
-                                      mFdp.ConsumeIntegral<int64_t>(),
+    FrameEventHistoryStats frameStats(frameNumber, mFdp.ConsumeIntegral<uint64_t>(), gpuFence,
+                                      compTiming, mFdp.ConsumeIntegral<int64_t>(),
                                       mFdp.ConsumeIntegral<int64_t>());
     std::vector<SurfaceControlStats> stats;
     sp<Fence> presentFence = new Fence(memfd_create("fd", MFD_ALLOW_SEALING));
diff --git a/libs/gui/include/gui/BLASTBufferQueue.h b/libs/gui/include/gui/BLASTBufferQueue.h
index 892215ec32..0e1a505c69 100644
--- a/libs/gui/include/gui/BLASTBufferQueue.h
+++ b/libs/gui/include/gui/BLASTBufferQueue.h
@@ -50,8 +50,8 @@ public:
     void onDisconnect() override EXCLUDES(mMutex);
     void addAndGetFrameTimestamps(const NewFrameEventsEntry* newTimestamps,
                                   FrameEventHistoryDelta* outDelta) override EXCLUDES(mMutex);
-    void updateFrameTimestamps(uint64_t frameNumber, nsecs_t refreshStartTime,
-                               const sp<Fence>& gpuCompositionDoneFence,
+    void updateFrameTimestamps(uint64_t frameNumber, uint64_t previousFrameNumber,
+                               nsecs_t refreshStartTime, const sp<Fence>& gpuCompositionDoneFence,
                                const sp<Fence>& presentFence, const sp<Fence>& prevReleaseFence,
                                CompositorTiming compositorTiming, nsecs_t latchTime,
                                nsecs_t dequeueReadyTime) EXCLUDES(mMutex);
diff --git a/libs/gui/include/gui/ITransactionCompletedListener.h b/libs/gui/include/gui/ITransactionCompletedListener.h
index 364a57b8dd..bc97cd0828 100644
--- a/libs/gui/include/gui/ITransactionCompletedListener.h
+++ b/libs/gui/include/gui/ITransactionCompletedListener.h
@@ -95,15 +95,18 @@ public:
     status_t readFromParcel(const Parcel* input) override;
 
     FrameEventHistoryStats() = default;
-    FrameEventHistoryStats(uint64_t fn, const sp<Fence>& gpuCompFence, CompositorTiming compTiming,
+    FrameEventHistoryStats(uint64_t frameNumber, uint64_t previousFrameNumber,
+                           const sp<Fence>& gpuCompFence, CompositorTiming compTiming,
                            nsecs_t refreshTime, nsecs_t dequeueReadyTime)
-          : frameNumber(fn),
+          : frameNumber(frameNumber),
+            previousFrameNumber(previousFrameNumber),
             gpuCompositionDoneFence(gpuCompFence),
             compositorTiming(compTiming),
             refreshStartTime(refreshTime),
             dequeueReadyTime(dequeueReadyTime) {}
 
     uint64_t frameNumber;
+    uint64_t previousFrameNumber;
     sp<Fence> gpuCompositionDoneFence;
     CompositorTiming compositorTiming;
     nsecs_t refreshStartTime;
diff --git a/libs/gui/libgui_flags.aconfig b/libs/gui/libgui_flags.aconfig
index a16be786be..b081030c9f 100644
--- a/libs/gui/libgui_flags.aconfig
+++ b/libs/gui/libgui_flags.aconfig
@@ -8,3 +8,10 @@ flag {
   is_fixed_read_only: true
 }
 
+flag {
+  name: "frametimestamps_previousrelease"
+  namespace: "core_graphics"
+  description: "Controls a fence fixup for timestamp apis"
+  bug: "310927247"
+  is_fixed_read_only: true
+}
diff --git a/libs/gui/tests/BLASTBufferQueue_test.cpp b/libs/gui/tests/BLASTBufferQueue_test.cpp
index 9893c7146e..ea7078dd05 100644
--- a/libs/gui/tests/BLASTBufferQueue_test.cpp
+++ b/libs/gui/tests/BLASTBufferQueue_test.cpp
@@ -42,9 +42,12 @@
 
 #include <gtest/gtest.h>
 
+#include <com_android_graphics_libgui_flags.h>
+
 using namespace std::chrono_literals;
 
 namespace android {
+using namespace com::android::graphics::libgui;
 
 using Transaction = SurfaceComposerClient::Transaction;
 using android::hardware::graphics::common::V1_2::BufferUsage;
@@ -1581,6 +1584,9 @@ TEST_F(BLASTFrameEventHistoryTest, FrameEventHistory_Basic) {
     nsecs_t postedTimeB = 0;
     setUpAndQueueBuffer(igbProducer, &requestedPresentTimeB, &postedTimeB, &qbOutput, true);
     history.applyDelta(qbOutput.frameTimestamps);
+
+    adapter.waitForCallback(2);
+
     events = history.getFrame(1);
     ASSERT_NE(nullptr, events);
 
@@ -1590,7 +1596,9 @@ TEST_F(BLASTFrameEventHistoryTest, FrameEventHistory_Basic) {
     ASSERT_GE(events->postedTime, postedTimeA);
 
     ASSERT_GE(events->latchTime, postedTimeA);
-    ASSERT_GE(events->dequeueReadyTime, events->latchTime);
+    if (flags::frametimestamps_previousrelease()) {
+        ASSERT_EQ(events->dequeueReadyTime, FrameEvents::TIMESTAMP_PENDING);
+    }
     ASSERT_NE(nullptr, events->gpuCompositionDoneFence);
     ASSERT_NE(nullptr, events->displayPresentFence);
     ASSERT_NE(nullptr, events->releaseFence);
@@ -1602,6 +1610,50 @@ TEST_F(BLASTFrameEventHistoryTest, FrameEventHistory_Basic) {
     ASSERT_EQ(requestedPresentTimeB, events->requestedPresentTime);
     ASSERT_GE(events->postedTime, postedTimeB);
 
+    // Now do the same as above with a third buffer, so that timings related to
+    // buffer releases make it back to the first frame.
+    nsecs_t requestedPresentTimeC = 0;
+    nsecs_t postedTimeC = 0;
+    setUpAndQueueBuffer(igbProducer, &requestedPresentTimeC, &postedTimeC, &qbOutput, true);
+    history.applyDelta(qbOutput.frameTimestamps);
+
+    adapter.waitForCallback(3);
+
+    // Check the first frame...
+    events = history.getFrame(1);
+    ASSERT_NE(nullptr, events);
+    ASSERT_EQ(1, events->frameNumber);
+    ASSERT_EQ(requestedPresentTimeA, events->requestedPresentTime);
+    ASSERT_GE(events->postedTime, postedTimeA);
+    ASSERT_GE(events->latchTime, postedTimeA);
+    // Now dequeueReadyTime is valid, because the release timings finally
+    // propaged to queueBuffer()
+    ASSERT_GE(events->dequeueReadyTime, events->latchTime);
+    ASSERT_NE(nullptr, events->gpuCompositionDoneFence);
+    ASSERT_NE(nullptr, events->displayPresentFence);
+    ASSERT_NE(nullptr, events->releaseFence);
+
+    // ...and the second
+    events = history.getFrame(2);
+    ASSERT_NE(nullptr, events);
+    ASSERT_EQ(2, events->frameNumber);
+    ASSERT_EQ(requestedPresentTimeB, events->requestedPresentTime);
+    ASSERT_GE(events->postedTime, postedTimeB);
+    ASSERT_GE(events->latchTime, postedTimeB);
+    if (flags::frametimestamps_previousrelease()) {
+        ASSERT_EQ(events->dequeueReadyTime, FrameEvents::TIMESTAMP_PENDING);
+    }
+    ASSERT_NE(nullptr, events->gpuCompositionDoneFence);
+    ASSERT_NE(nullptr, events->displayPresentFence);
+    ASSERT_NE(nullptr, events->releaseFence);
+
+    // ...and finally the third!
+    events = history.getFrame(3);
+    ASSERT_NE(nullptr, events);
+    ASSERT_EQ(3, events->frameNumber);
+    ASSERT_EQ(requestedPresentTimeC, events->requestedPresentTime);
+    ASSERT_GE(events->postedTime, postedTimeC);
+
     // wait for any callbacks that have not been received
     adapter.waitForCallbacks();
 }
@@ -1660,6 +1712,8 @@ TEST_F(BLASTFrameEventHistoryTest, FrameEventHistory_DroppedFrame) {
     setUpAndQueueBuffer(igbProducer, &requestedPresentTimeC, &postedTimeC, &qbOutput, true);
     history.applyDelta(qbOutput.frameTimestamps);
 
+    adapter.waitForCallback(3);
+
     // frame number, requestedPresentTime, and postTime should not have changed
     ASSERT_EQ(1, events->frameNumber);
     ASSERT_EQ(requestedPresentTimeA, events->requestedPresentTime);
@@ -1679,6 +1733,42 @@ TEST_F(BLASTFrameEventHistoryTest, FrameEventHistory_DroppedFrame) {
     ASSERT_EQ(requestedPresentTimeB, events->requestedPresentTime);
     ASSERT_GE(events->postedTime, postedTimeB);
     ASSERT_GE(events->latchTime, postedTimeB);
+
+    if (flags::frametimestamps_previousrelease()) {
+        ASSERT_EQ(events->dequeueReadyTime, FrameEvents::TIMESTAMP_PENDING);
+    }
+    ASSERT_NE(nullptr, events->gpuCompositionDoneFence);
+    ASSERT_NE(nullptr, events->displayPresentFence);
+    ASSERT_NE(nullptr, events->releaseFence);
+
+    // Queue another buffer to check for timestamps that came late
+    nsecs_t requestedPresentTimeD = 0;
+    nsecs_t postedTimeD = 0;
+    setUpAndQueueBuffer(igbProducer, &requestedPresentTimeD, &postedTimeD, &qbOutput, true);
+    history.applyDelta(qbOutput.frameTimestamps);
+
+    adapter.waitForCallback(4);
+
+    // frame number, requestedPresentTime, and postTime should not have changed
+    events = history.getFrame(1);
+    ASSERT_EQ(1, events->frameNumber);
+    ASSERT_EQ(requestedPresentTimeA, events->requestedPresentTime);
+    ASSERT_GE(events->postedTime, postedTimeA);
+
+    // a valid latchtime and pre and post composition info should not be set for the dropped frame
+    ASSERT_FALSE(events->hasLatchInfo());
+    ASSERT_FALSE(events->hasDequeueReadyInfo());
+    ASSERT_FALSE(events->hasGpuCompositionDoneInfo());
+    ASSERT_FALSE(events->hasDisplayPresentInfo());
+    ASSERT_FALSE(events->hasReleaseInfo());
+
+    // we should also have gotten values for the presented frame
+    events = history.getFrame(2);
+    ASSERT_NE(nullptr, events);
+    ASSERT_EQ(2, events->frameNumber);
+    ASSERT_EQ(requestedPresentTimeB, events->requestedPresentTime);
+    ASSERT_GE(events->postedTime, postedTimeB);
+    ASSERT_GE(events->latchTime, postedTimeB);
     ASSERT_GE(events->dequeueReadyTime, events->latchTime);
     ASSERT_NE(nullptr, events->gpuCompositionDoneFence);
     ASSERT_NE(nullptr, events->displayPresentFence);
diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp
index 66ea15ca2d..63dba93792 100644
--- a/services/surfaceflinger/Layer.cpp
+++ b/services/surfaceflinger/Layer.cpp
@@ -165,6 +165,7 @@ Layer::Layer(const surfaceflinger::LayerCreationArgs& args)
     mDrawingState.sequence = 0;
     mDrawingState.transform.set(0, 0);
     mDrawingState.frameNumber = 0;
+    mDrawingState.previousFrameNumber = 0;
     mDrawingState.barrierFrameNumber = 0;
     mDrawingState.producerId = 0;
     mDrawingState.barrierProducerId = 0;
@@ -2931,7 +2932,6 @@ void Layer::onLayerDisplayed(ftl::SharedFuture<FenceResult> futureFenceResult,
             break;
         }
     }
-
     if (ch != nullptr) {
         ch->previousReleaseCallbackId = mPreviousReleaseCallbackId;
         ch->previousReleaseFences.emplace_back(std::move(futureFenceResult));
@@ -2940,6 +2940,10 @@ void Layer::onLayerDisplayed(ftl::SharedFuture<FenceResult> futureFenceResult,
     if (mBufferInfo.mBuffer) {
         mPreviouslyPresentedLayerStacks.push_back(layerStack);
     }
+
+    if (mDrawingState.frameNumber > 0) {
+        mDrawingState.previousFrameNumber = mDrawingState.frameNumber;
+    }
 }
 
 void Layer::onSurfaceFrameCreated(
@@ -3144,6 +3148,7 @@ void Layer::releasePreviousBuffer() {
 void Layer::resetDrawingStateBufferInfo() {
     mDrawingState.producerId = 0;
     mDrawingState.frameNumber = 0;
+    mDrawingState.previousFrameNumber = 0;
     mDrawingState.releaseBufferListener = nullptr;
     mDrawingState.buffer = nullptr;
     mDrawingState.acquireFence = sp<Fence>::make(-1);
@@ -3420,6 +3425,7 @@ bool Layer::setTransactionCompletedListeners(const std::vector<sp<CallbackHandle
             // If this transaction set an acquire fence on this layer, set its acquire time
             handle->acquireTimeOrFence = mCallbackHandleAcquireTimeOrFence;
             handle->frameNumber = mDrawingState.frameNumber;
+            handle->previousFrameNumber = mDrawingState.previousFrameNumber;
 
             // Store so latched time and release fence can be set
             mDrawingState.callbackHandles.push_back(handle);
diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h
index f71591044d..28168c3f65 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -138,6 +138,7 @@ public:
         ui::Dataspace dataspace;
 
         uint64_t frameNumber;
+        uint64_t previousFrameNumber;
         // high watermark framenumber to use to check for barriers to protect ourselves
         // from out of order transactions
         uint64_t barrierFrameNumber;
diff --git a/services/surfaceflinger/TransactionCallbackInvoker.cpp b/services/surfaceflinger/TransactionCallbackInvoker.cpp
index 3587a726cd..6a155c17df 100644
--- a/services/surfaceflinger/TransactionCallbackInvoker.cpp
+++ b/services/surfaceflinger/TransactionCallbackInvoker.cpp
@@ -158,7 +158,7 @@ status_t TransactionCallbackInvoker::addCallbackHandle(const sp<CallbackHandle>&
         handle->previousReleaseFence = prevFence;
         handle->previousReleaseFences.clear();
 
-        FrameEventHistoryStats eventStats(handle->frameNumber,
+        FrameEventHistoryStats eventStats(handle->frameNumber, handle->previousFrameNumber,
                                           handle->gpuCompositionDoneFence->getSnapshot().fence,
                                           handle->compositorTiming, handle->refreshStartTime,
                                           handle->dequeueReadyTime);
diff --git a/services/surfaceflinger/TransactionCallbackInvoker.h b/services/surfaceflinger/TransactionCallbackInvoker.h
index 3074795f62..245398f2f4 100644
--- a/services/surfaceflinger/TransactionCallbackInvoker.h
+++ b/services/surfaceflinger/TransactionCallbackInvoker.h
@@ -56,6 +56,7 @@ public:
     nsecs_t refreshStartTime = 0;
     nsecs_t dequeueReadyTime = 0;
     uint64_t frameNumber = 0;
+    uint64_t previousFrameNumber = 0;
     ReleaseCallbackId previousReleaseCallbackId = ReleaseCallbackId::INVALID_ID;
 };