commit 57ae4b20546df7666303fd649bd49ab89a3bcc7f
author chaviw <chaviw@google.com> Thu Feb 03 16:51:39 2022 -0600
committer chaviw <chaviw@google.com> Fri Feb 04 09:58:18 2022 -0600
tree b4978e3ea5d613203516834af124de0eece59fcd
parent f06d1361e03b3e1d9d855867516fbcab75abf459

Add more info in BBQ Tracing

Added the buffer name, mNumFrameAvailable,  mNumAcquired to all
traces in BBQ.

Also added frameNum for acquire and release to help match up when the
release is called.

Test: Trace shows new data
Bug: 217621394
Change-Id: I86bf0c12741a2651bb3802c6142ac341b0fb362e

libs/gui/BLASTBufferQueue.cpp

diff --git a/libs/gui/BLASTBufferQueue.cpp b/libs/gui/BLASTBufferQueue.cpp
index dd96683..aeb237d 100644
--- a/libs/gui/BLASTBufferQueue.cpp
+++ b/libs/gui/BLASTBufferQueue.cpp
@@ -28,6 +28,7 @@
 #include <gui/GLConsumer.h>
 #include <gui/IProducerListener.h>
 #include <gui/Surface.h>
+#include <gui/TraceUtils.h>
 #include <utils/Singleton.h>
 #include <utils/Trace.h>
 
@@ -57,6 +58,10 @@
 #define BQA_LOGE(x, ...) \
     ALOGE("[%s](f:%u,a:%u) " x, mName.c_str(), mNumFrameAvailable, mNumAcquired, ##__VA_ARGS__)
 
+#define BBQ_TRACE(x, ...)                                                                  \
+    ATRACE_FORMAT("%s - %s(f:%u,a:%u)" x, __FUNCTION__, mName.c_str(), mNumFrameAvailable, \
+                  mNumAcquired, ##__VA_ARGS__)
+
 void BLASTBufferItemConsumer::onDisconnect() {
     Mutex::Autolock lock(mMutex);
     mPreviouslyConnected = mCurrentlyConnected;
@@ -254,7 +259,7 @@
                                                     const std::vector<SurfaceControlStats>& stats) {
     {
         std::unique_lock _lock{mMutex};
-        ATRACE_CALL();
+        BBQ_TRACE();
         BQA_LOGV("transactionCommittedCallback");
         if (!mSurfaceControlsWithPendingCallback.empty()) {
             sp<SurfaceControl> pendingSC = mSurfaceControlsWithPendingCallback.front();
@@ -304,7 +309,7 @@
                                            const std::vector<SurfaceControlStats>& stats) {
     {
         std::unique_lock _lock{mMutex};
-        ATRACE_CALL();
+        BBQ_TRACE();
         BQA_LOGV("transactionCallback");
 
         if (!mSurfaceControlsWithPendingCallback.empty()) {
@@ -367,7 +372,7 @@
 void BLASTBufferQueue::releaseBufferCallback(
         const ReleaseCallbackId& id, const sp<Fence>& releaseFence,
         std::optional<uint32_t> currentMaxAcquiredBufferCount) {
-    ATRACE_CALL();
+    BBQ_TRACE();
     std::unique_lock _lock{mMutex};
     BQA_LOGV("releaseBufferCallback %s", id.to_string().c_str());
 
@@ -415,6 +420,7 @@
         return;
     }
     mNumAcquired--;
+    BBQ_TRACE("frame=%" PRIu64, callbackId.framenumber);
     BQA_LOGV("released %s", callbackId.to_string().c_str());
     mBufferItemConsumer->releaseBuffer(it->second, releaseFence);
     mSubmitted.erase(it);
@@ -422,7 +428,6 @@
 
 void BLASTBufferQueue::acquireNextBufferLocked(
         const std::optional<SurfaceComposerClient::Transaction*> transaction) {
-    ATRACE_CALL();
     // If the next transaction is set, we want to guarantee the our acquire will not fail, so don't
     // include the extra buffer when checking if we can acquire the next buffer.
     const bool includeExtraAcquire = !transaction;
@@ -456,8 +461,10 @@
         BQA_LOGE("Failed to acquire a buffer, err=%s", statusToString(status).c_str());
         return;
     }
+
     auto buffer = bufferItem.mGraphicBuffer;
     mNumFrameAvailable--;
+    BBQ_TRACE("frame=%" PRIu64, bufferItem.mFrameNumber);
 
     if (buffer == nullptr) {
         mBufferItemConsumer->releaseBuffer(bufferItem, Fence::NO_FENCE);
@@ -600,7 +607,7 @@
 }
 
 void BLASTBufferQueue::onFrameAvailable(const BufferItem& item) {
-    ATRACE_CALL();
+    BBQ_TRACE();
     std::unique_lock _lock{mMutex};
 
     const bool syncTransactionSet = mSyncTransaction != nullptr;
@@ -674,6 +681,7 @@
 
 void BLASTBufferQueue::setSyncTransaction(SurfaceComposerClient::Transaction* t,
                                           bool acquireSingleBuffer) {
+    BBQ_TRACE();
     std::lock_guard _lock{mMutex};
     mSyncTransaction = t;
     mAcquireSingleBuffer = mSyncTransaction ? acquireSingleBuffer : true;