Added trace data for latch and release buffers

It's helpful to see the specific layer and frame number that is being
latched and released in SF to ensure we can trace where buffers go.

Additionally, added new traces to BBQ where it could be flushing buffers
or waiting until there's a free buffer

Test: perfetto trace
Bug: 238328090
Change-Id: I88fa6db62092438ed7ada12c3f0740dc3ac282d5

5 files changed, 37 insertions, 8 deletions

diff --git a/libs/gui/BLASTBufferQueue.cpp b/libs/gui/BLASTBufferQueue.cpp
index 2212e58e4d..3bf2e195c5 100644
--- a/libs/gui/BLASTBufferQueue.cpp
+++ b/libs/gui/BLASTBufferQueue.cpp
@@ -599,6 +599,7 @@ Rect BLASTBufferQueue::computeCrop(const BufferItem& item) {
 }
 
 void BLASTBufferQueue::acquireAndReleaseBuffer() {
+    BBQ_TRACE();
     BufferItem bufferItem;
     status_t status =
             mBufferItemConsumer->acquireBuffer(&bufferItem, 0 /* expectedPresent */, false);
@@ -612,6 +613,7 @@ void BLASTBufferQueue::acquireAndReleaseBuffer() {
 }
 
 void BLASTBufferQueue::flushAndWaitForFreeBuffer(std::unique_lock<std::mutex>& lock) {
+    BBQ_TRACE();
     if (!mSyncedFrameNumbers.empty() && mNumFrameAvailable > 0) {
         // We are waiting on a previous sync's transaction callback so allow another sync
         // transaction to proceed.
@@ -642,8 +644,8 @@ void BLASTBufferQueue::onFrameAvailable(const BufferItem& item) {
     bool waitForTransactionCallback = !mSyncedFrameNumbers.empty();
 
     {
-        BBQ_TRACE();
         std::unique_lock _lock{mMutex};
+        BBQ_TRACE();
         const bool syncTransactionSet = mTransactionReadyCallback != nullptr;
         BQA_LOGV("onFrameAvailable-start syncTransactionSet=%s", boolToString(syncTransactionSet));
 
diff --git a/libs/gui/include/gui/TraceUtils.h b/libs/gui/include/gui/TraceUtils.h
index e5d268445c..00096158e7 100644
--- a/libs/gui/include/gui/TraceUtils.h
+++ b/libs/gui/include/gui/TraceUtils.h
@@ -27,6 +27,8 @@
 
 #define ATRACE_FORMAT_BEGIN(fmt, ...) TraceUtils::atraceFormatBegin(fmt, ##__VA_ARGS__)
 
+#define ATRACE_FORMAT_INSTANT(fmt, ...) TraceUtils::intantFormat(fmt, ##__VA_ARGS__)
+
 namespace android {
 
 class TraceUtils {
@@ -50,6 +52,20 @@ public:
         ATRACE_BEGIN(buf);
     }
 
+    static void intantFormat(const char* fmt, ...) {
+        if (CC_LIKELY(!ATRACE_ENABLED())) return;
+
+        const int BUFFER_SIZE = 256;
+        va_list ap;
+        char buf[BUFFER_SIZE];
+
+        va_start(ap, fmt);
+        vsnprintf(buf, BUFFER_SIZE, fmt, ap);
+        va_end(ap);
+
+        ATRACE_INSTANT(buf);
+    }
+
 }; // class TraceUtils
 
 } /* namespace android */
diff --git a/services/surfaceflinger/BufferLayer.cpp b/services/surfaceflinger/BufferLayer.cpp
index fb15f1d06c..4ba5e907a7 100644
--- a/services/surfaceflinger/BufferLayer.cpp
+++ b/services/surfaceflinger/BufferLayer.cpp
@@ -37,6 +37,7 @@
 #include <gui/GLConsumer.h>
 #include <gui/LayerDebugInfo.h>
 #include <gui/Surface.h>
+#include <gui/TraceUtils.h>
 #include <renderengine/RenderEngine.h>
 #include <ui/DebugUtils.h>
 #include <utils/Errors.h>
@@ -457,7 +458,8 @@ bool BufferLayer::shouldPresentNow(nsecs_t expectedPresentTime) const {
 
 bool BufferLayer::latchBuffer(bool& recomputeVisibleRegions, nsecs_t latchTime,
                               nsecs_t expectedPresentTime) {
-    ATRACE_CALL();
+    ATRACE_FORMAT_INSTANT("latchBuffer %s - %" PRIu64, getDebugName(),
+                          getDrawingState().frameNumber);
 
     bool refreshRequired = latchSidebandStream(recomputeVisibleRegions);
 
diff --git a/services/surfaceflinger/BufferStateLayer.cpp b/services/surfaceflinger/BufferStateLayer.cpp
index d88d7c99e9..574e2f5bed 100644
--- a/services/surfaceflinger/BufferStateLayer.cpp
+++ b/services/surfaceflinger/BufferStateLayer.cpp
@@ -30,6 +30,7 @@
 #include <renderengine/Image.h>
 #include "TunnelModeEnabledReporter.h"
 
+#include <gui/TraceUtils.h>
 #include "EffectLayer.h"
 #include "FrameTracer/FrameTracer.h"
 #include "TimeStats/TimeStats.h"
@@ -39,19 +40,20 @@
 namespace android {
 
 using PresentState = frametimeline::SurfaceFrame::PresentState;
-namespace {
-void callReleaseBufferCallback(const sp<ITransactionCompletedListener>& listener,
-                               const sp<GraphicBuffer>& buffer, uint64_t framenumber,
-                               const sp<Fence>& releaseFence,
-                               uint32_t currentMaxAcquiredBufferCount) {
+
+void BufferStateLayer::callReleaseBufferCallback(const sp<ITransactionCompletedListener>& listener,
+                                                 const sp<GraphicBuffer>& buffer,
+                                                 uint64_t framenumber,
+                                                 const sp<Fence>& releaseFence,
+                                                 uint32_t currentMaxAcquiredBufferCount) {
     if (!listener) {
         return;
     }
+    ATRACE_FORMAT_INSTANT("callReleaseBufferCallback %s - %" PRIu64, getDebugName(), framenumber);
     listener->onReleaseBuffer({buffer->getId(), framenumber},
                               releaseFence ? releaseFence : Fence::NO_FENCE,
                               currentMaxAcquiredBufferCount);
 }
-} // namespace
 
 BufferStateLayer::BufferStateLayer(const LayerCreationArgs& args)
       : BufferLayer(args), mHwcSlotGenerator(new HwcSlotGenerator()) {
@@ -145,6 +147,8 @@ void BufferStateLayer::releasePendingBuffer(nsecs_t dequeueReadyTime) {
         handle->dequeueReadyTime = dequeueReadyTime;
         handle->currentMaxAcquiredBufferCount =
                 mFlinger->getMaxAcquiredBufferCountForCurrentRefreshRate(mOwnerUid);
+        ATRACE_FORMAT_INSTANT("releasePendingBuffer %s - %" PRIu64, getDebugName(),
+                              handle->previousReleaseCallbackId.framenumber);
     }
 
     for (auto& handle : mDrawingState.callbackHandles) {
diff --git a/services/surfaceflinger/BufferStateLayer.h b/services/surfaceflinger/BufferStateLayer.h
index 3f0dbe4039..bf98a279a3 100644
--- a/services/surfaceflinger/BufferStateLayer.h
+++ b/services/surfaceflinger/BufferStateLayer.h
@@ -135,6 +135,11 @@ private:
 
     bool simpleBufferUpdate(const layer_state_t& s) const override;
 
+    void callReleaseBufferCallback(const sp<ITransactionCompletedListener>& listener,
+                                   const sp<GraphicBuffer>& buffer, uint64_t framenumber,
+                                   const sp<Fence>& releaseFence,
+                                   uint32_t currentMaxAcquiredBufferCount);
+
     ReleaseCallbackId mPreviousReleaseCallbackId = ReleaseCallbackId::INVALID_ID;
     uint64_t mPreviousReleasedFrameNumber = 0;