BlastBufferQueue: Pass client dequeue times to SurfaceFlinger

SF keeps track of client dequeue, queue, acquire etc. timestamps to
construct frame rendering timelines for developers. With BBQ, SF no
longer has access to this data, so pass the dequeue time along with
the buffers.

Ideally this data should flow to the perfetto trace directly from the client
but this is a temp solution while some perf issues with client logging
is sorted out.

Bug: 176931912
Test: manual tests
Change-Id: Ic88170c1fb20850662cb99325ac42b7232a02817

10 files changed, 59 insertions, 7 deletions

diff --git a/aidl/gui/android/view/LayerMetadataKey.aidl b/aidl/gui/android/view/LayerMetadataKey.aidl
index 491c629278..a1d8ce5962 100644
--- a/aidl/gui/android/view/LayerMetadataKey.aidl
+++ b/aidl/gui/android/view/LayerMetadataKey.aidl
@@ -25,4 +25,5 @@ enum LayerMetadataKey {
     METADATA_MOUSE_CURSOR = 4,
     METADATA_ACCESSIBILITY_ID = 5,
     METADATA_OWNER_PID = 6,
+    METADATA_DEQUEUE_TIME = 7,
 }
diff --git a/libs/gui/BLASTBufferQueue.cpp b/libs/gui/BLASTBufferQueue.cpp
index eaa47f9680..f4b5a26033 100644
--- a/libs/gui/BLASTBufferQueue.cpp
+++ b/libs/gui/BLASTBufferQueue.cpp
@@ -354,6 +354,16 @@ void BLASTBufferQueue::processNextBufferLocked(bool useNextTransaction) {
         t->setAutoRefresh(mSurfaceControl, bufferItem.mAutoRefresh);
         mAutoRefresh = bufferItem.mAutoRefresh;
     }
+    {
+        std::unique_lock _lock{mTimestampMutex};
+        auto dequeueTime = mDequeueTimestamps.find(buffer->getId());
+        if (dequeueTime != mDequeueTimestamps.end()) {
+            Parcel p;
+            p.writeInt64(dequeueTime->second);
+            t->setMetadata(mSurfaceControl, METADATA_DEQUEUE_TIME, p);
+            mDequeueTimestamps.erase(dequeueTime);
+        }
+    }
 
     auto mergeTransaction =
             [&t, currentFrameNumber = bufferItem.mFrameNumber](
@@ -412,6 +422,16 @@ void BLASTBufferQueue::onFrameReplaced(const BufferItem& item) {
     // Do nothing since we are not storing unacquired buffer items locally.
 }
 
+void BLASTBufferQueue::onFrameDequeued(const uint64_t bufferId) {
+    std::unique_lock _lock{mTimestampMutex};
+    mDequeueTimestamps[bufferId] = systemTime();
+};
+
+void BLASTBufferQueue::onFrameCancelled(const uint64_t bufferId) {
+    std::unique_lock _lock{mTimestampMutex};
+    mDequeueTimestamps.erase(bufferId);
+};
+
 void BLASTBufferQueue::setNextTransaction(SurfaceComposerClient::Transaction* t) {
     std::lock_guard _lock{mMutex};
     mNextTransaction = t;
diff --git a/libs/gui/LayerMetadata.cpp b/libs/gui/LayerMetadata.cpp
index 30c9b373ef..634d8b7df0 100644
--- a/libs/gui/LayerMetadata.cpp
+++ b/libs/gui/LayerMetadata.cpp
@@ -17,6 +17,7 @@
 #include <android-base/stringprintf.h>
 #include <binder/Parcel.h>
 #include <gui/LayerMetadata.h>
+#include <inttypes.h>
 
 #include "android/view/LayerMetadataKey.h"
 
@@ -113,6 +114,15 @@ void LayerMetadata::setInt32(uint32_t key, int32_t value) {
     memcpy(data.data(), p.data(), p.dataSize());
 }
 
+std::optional<int64_t> LayerMetadata::getInt64(uint32_t key) const {
+    if (!has(key)) return std::nullopt;
+    const std::vector<uint8_t>& data = mMap.at(key);
+    if (data.size() < sizeof(int64_t)) return std::nullopt;
+    Parcel p;
+    p.setData(data.data(), data.size());
+    return p.readInt64();
+}
+
 std::string LayerMetadata::itemToString(uint32_t key, const char* separator) const {
     if (!has(key)) return std::string();
     switch (static_cast<view::LayerMetadataKey>(key)) {
@@ -124,6 +134,8 @@ std::string LayerMetadata::itemToString(uint32_t key, const char* separator) con
             return StringPrintf("taskId%s%d", separator, getInt32(key, 0));
         case view::LayerMetadataKey::METADATA_OWNER_PID:
             return StringPrintf("ownerPID%s%d", separator, getInt32(key, 0));
+        case view::LayerMetadataKey::METADATA_DEQUEUE_TIME:
+            return StringPrintf("dequeueTime%s%" PRId64, separator, *getInt64(key));
         default:
             return StringPrintf("%d%s%dbytes", key, separator,
                                 static_cast<int>(mMap.at(key).size()));
diff --git a/libs/gui/include/gui/BLASTBufferQueue.h b/libs/gui/include/gui/BLASTBufferQueue.h
index 1198135b0c..0fbcbdc50f 100644
--- a/libs/gui/include/gui/BLASTBufferQueue.h
+++ b/libs/gui/include/gui/BLASTBufferQueue.h
@@ -78,6 +78,8 @@ public:
     void onBufferFreed(const wp<GraphicBuffer>&/* graphicBuffer*/) override { /* TODO */ }
     void onFrameReplaced(const BufferItem& item) override;
     void onFrameAvailable(const BufferItem& item) override;
+    void onFrameDequeued(const uint64_t) override;
+    void onFrameCancelled(const uint64_t) override;
 
     void transactionCallback(nsecs_t latchTime, const sp<Fence>& presentFence,
             const std::vector<SurfaceControlStats>& stats);
@@ -168,7 +170,15 @@ private:
 
     // Queues up transactions using this token in SurfaceFlinger. This prevents queued up
     // transactions from other parts of the client from blocking this transaction.
-    const sp<IBinder> mApplyToken = new BBinder();
+    const sp<IBinder> mApplyToken GUARDED_BY(mMutex) = new BBinder();
+
+    // Guards access to mDequeueTimestamps since we cannot hold to mMutex in onFrameDequeued or
+    // we will deadlock.
+    std::mutex mTimestampMutex;
+    // Tracks buffer dequeue times by the client. This info is sent to SurfaceFlinger which uses
+    // it for debugging purposes.
+    std::unordered_map<uint64_t /* bufferId */, nsecs_t> mDequeueTimestamps
+            GUARDED_BY(mTimestampMutex);
 };
 
 } // namespace android
diff --git a/libs/gui/include/gui/LayerMetadata.h b/libs/gui/include/gui/LayerMetadata.h
index ac48aefae6..41982c28a2 100644
--- a/libs/gui/include/gui/LayerMetadata.h
+++ b/libs/gui/include/gui/LayerMetadata.h
@@ -29,6 +29,7 @@ enum {
     METADATA_MOUSE_CURSOR = 4,
     METADATA_ACCESSIBILITY_ID = 5,
     METADATA_OWNER_PID = 6,
+    METADATA_DEQUEUE_TIME = 7
 };
 
 struct LayerMetadata : public Parcelable {
@@ -51,6 +52,8 @@ struct LayerMetadata : public Parcelable {
     bool has(uint32_t key) const;
     int32_t getInt32(uint32_t key, int32_t fallback) const;
     void setInt32(uint32_t key, int32_t value);
+    std::optional<int64_t> getInt64(uint32_t key) const;
+    void setInt64(uint32_t key, int64_t value);
 
     std::string itemToString(uint32_t key, const char* separator) const;
 };
diff --git a/services/surfaceflinger/BufferStateLayer.cpp b/services/surfaceflinger/BufferStateLayer.cpp
index bca1c69c0f..a431028bde 100644
--- a/services/surfaceflinger/BufferStateLayer.cpp
+++ b/services/surfaceflinger/BufferStateLayer.cpp
@@ -343,7 +343,8 @@ bool BufferStateLayer::addFrameEvent(const sp<Fence>& acquireFence, nsecs_t post
 
 bool BufferStateLayer::setBuffer(const sp<GraphicBuffer>& buffer, const sp<Fence>& acquireFence,
                                  nsecs_t postTime, nsecs_t desiredPresentTime, bool isAutoTimestamp,
-                                 const client_cache_t& clientCacheId, uint64_t frameNumber) {
+                                 const client_cache_t& clientCacheId, uint64_t frameNumber,
+                                 std::optional<nsecs_t> /* dequeueTime */) {
     ATRACE_CALL();
 
     if (mCurrentState.buffer) {
diff --git a/services/surfaceflinger/BufferStateLayer.h b/services/surfaceflinger/BufferStateLayer.h
index 6414e6be60..1098606cbb 100644
--- a/services/surfaceflinger/BufferStateLayer.h
+++ b/services/surfaceflinger/BufferStateLayer.h
@@ -71,7 +71,8 @@ public:
     bool setFrame(const Rect& frame) override;
     bool setBuffer(const sp<GraphicBuffer>& buffer, const sp<Fence>& acquireFence, nsecs_t postTime,
                    nsecs_t desiredPresentTime, bool isAutoTimestamp,
-                   const client_cache_t& clientCacheId, uint64_t frameNumber) override;
+                   const client_cache_t& clientCacheId, uint64_t frameNumber,
+                   std::optional<nsecs_t> dequeueTime) override;
     bool setAcquireFence(const sp<Fence>& fence) override;
     bool setDataspace(ui::Dataspace dataspace) override;
     bool setHdrMetadata(const HdrMetadata& hdrMetadata) override;
diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h
index d6023b66ac..f78b5f31e9 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -446,7 +446,7 @@ public:
     virtual bool setBuffer(const sp<GraphicBuffer>& /*buffer*/, const sp<Fence>& /*acquireFence*/,
                            nsecs_t /*postTime*/, nsecs_t /*desiredPresentTime*/,
                            bool /*isAutoTimestamp*/, const client_cache_t& /*clientCacheId*/,
-                           uint64_t /* frameNumber */) {
+                           uint64_t /* frameNumber */, std::optional<nsecs_t> /* dequeueTime */) {
         return false;
     };
     virtual bool setAcquireFence(const sp<Fence>& /*fence*/) { return false; };
diff --git a/services/surfaceflinger/RefreshRateOverlay.cpp b/services/surfaceflinger/RefreshRateOverlay.cpp
index 6a511a85a0..32110e9547 100644
--- a/services/surfaceflinger/RefreshRateOverlay.cpp
+++ b/services/surfaceflinger/RefreshRateOverlay.cpp
@@ -237,7 +237,8 @@ void RefreshRateOverlay::changeRefreshRate(const RefreshRate& refreshRate) {
     mCurrentFps = refreshRate.getFps().getIntValue();
     auto buffer = getOrCreateBuffers(*mCurrentFps)[mFrame];
     mLayer->setBuffer(buffer, Fence::NO_FENCE, 0, 0, true, {},
-                      mLayer->getHeadFrameNumber(-1 /* expectedPresentTime */));
+                      mLayer->getHeadFrameNumber(-1 /* expectedPresentTime */),
+                      std::nullopt /* dequeueTime */);
 
     mFlinger.mTransactionFlags.fetch_or(eTransactionMask);
 }
@@ -249,7 +250,8 @@ void RefreshRateOverlay::onInvalidate() {
     mFrame = (mFrame + 1) % buffers.size();
     auto buffer = buffers[mFrame];
     mLayer->setBuffer(buffer, Fence::NO_FENCE, 0, 0, true, {},
-                      mLayer->getHeadFrameNumber(-1 /* expectedPresentTime */));
+                      mLayer->getHeadFrameNumber(-1 /* expectedPresentTime */),
+                      std::nullopt /* dequeueTime */);
 
     mFlinger.mTransactionFlags.fetch_or(eTransactionMask);
 }
diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index 6967f69876..6938d5de57 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -3840,7 +3840,9 @@ uint32_t SurfaceFlinger::setClientStateLocked(
             ALOGE("Attempt to update InputWindowInfo without permission ACCESS_SURFACE_FLINGER");
         }
     }
+    std::optional<nsecs_t> dequeueBufferTimestamp;
     if (what & layer_state_t::eMetadataChanged) {
+        dequeueBufferTimestamp = s.metadata.getInt64(METADATA_DEQUEUE_TIME);
         if (layer->setMetadata(s.metadata)) flags |= eTraversalNeeded;
     }
     if (what & layer_state_t::eColorSpaceAgnosticChanged) {
@@ -3928,7 +3930,7 @@ uint32_t SurfaceFlinger::setClientStateLocked(
                 : layer->getHeadFrameNumber(-1 /* expectedPresentTime */) + 1;
 
         if (layer->setBuffer(buffer, s.acquireFence, postTime, desiredPresentTime, isAutoTimestamp,
-                             s.cachedBuffer, frameNumber)) {
+                             s.cachedBuffer, frameNumber, dequeueBufferTimestamp)) {
             flags |= eTraversalNeeded;
         }
     }