Add debug logs to BlastBufferQueue

Bug: 168917217
Test: Enable logs and check logcat
Test: atest BLASTBufferQueueTest

Change-Id: I6139b01167ee9325fb4982cf4ece85ab37c9e8b5
diff --git a/libs/gui/BLASTBufferQueue.cpp b/libs/gui/BLASTBufferQueue.cpp
index 56591bd..3b2788a 100644
--- a/libs/gui/BLASTBufferQueue.cpp
+++ b/libs/gui/BLASTBufferQueue.cpp
@@ -18,6 +18,7 @@
 #define LOG_TAG "BLASTBufferQueue"
 
 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
+// #define LOG_NDEBUG 0
 
 #include <gui/BLASTBufferQueue.h>
 #include <gui/BufferItemConsumer.h>
@@ -29,8 +30,20 @@
 
 using namespace std::chrono_literals;
 
+namespace {
+inline const char* toString(bool b) {
+    return b ? "true" : "false";
+}
+} // namespace
+
 namespace android {
 
+// Macros to include adapter info in log messages
+#define BQA_LOGV(x, ...) \
+    ALOGV("[%s](f:%u,a:%u) " x, mName.c_str(), mNumFrameAvailable, mNumAcquired, ##__VA_ARGS__)
+#define BQA_LOGE(x, ...) \
+    ALOGE("[%s](f:%u,a:%u) " x, mName.c_str(), mNumFrameAvailable, mNumAcquired, ##__VA_ARGS__)
+
 void BLASTBufferItemConsumer::onDisconnect() {
     Mutex::Autolock lock(mFrameEventHistoryMutex);
     mPreviouslyConnected = mCurrentlyConnected;
@@ -93,9 +106,10 @@
     if (needsDisconnect != nullptr) *needsDisconnect = disconnect;
 }
 
-BLASTBufferQueue::BLASTBufferQueue(const sp<SurfaceControl>& surface, int width, int height,
-                                   bool enableTripleBuffering)
-      : mSurfaceControl(surface),
+BLASTBufferQueue::BLASTBufferQueue(const std::string& name, const sp<SurfaceControl>& surface,
+                                   int width, int height, bool enableTripleBuffering)
+      : mName(name),
+        mSurfaceControl(surface),
         mWidth(width),
         mHeight(height),
         mNextTransaction(nullptr) {
@@ -110,9 +124,9 @@
     mBufferItemConsumer =
         new BLASTBufferItemConsumer(mConsumer, GraphicBuffer::USAGE_HW_COMPOSER, 1, true);
     static int32_t id = 0;
-    auto name = std::string("BLAST Consumer") + std::to_string(id);
+    auto consumerName = mName + "(BLAST Consumer)" + std::to_string(id);
     id++;
-    mBufferItemConsumer->setName(String8(name.c_str()));
+    mBufferItemConsumer->setName(String8(consumerName.c_str()));
     mBufferItemConsumer->setFrameAvailableListener(this);
     mBufferItemConsumer->setBufferFreedListener(this);
     mBufferItemConsumer->setDefaultBufferSize(mWidth, mHeight);
@@ -127,7 +141,7 @@
     mPendingReleaseItem.releaseFence = nullptr;
 }
 
-void BLASTBufferQueue::update(const sp<SurfaceControl>& surface, int width, int height) {
+void BLASTBufferQueue::update(const sp<SurfaceControl>& surface, uint32_t width, uint32_t height) {
     std::unique_lock _lock{mMutex};
     mSurfaceControl = surface;
 
@@ -153,6 +167,8 @@
     std::unique_lock _lock{mMutex};
     ATRACE_CALL();
 
+    BQA_LOGV("transactionCallback");
+
     if (!stats.empty()) {
         mTransformHint = stats[0].transformHint;
         mBufferItemConsumer->setTransformHint(mTransformHint);
@@ -195,6 +211,8 @@
 
 void BLASTBufferQueue::processNextBufferLocked(bool useNextTransaction) {
     ATRACE_CALL();
+    BQA_LOGV("processNextBufferLocked useNextTransaction=%s", toString(useNextTransaction));
+
     if (mNumFrameAvailable == 0 || mNumAcquired == MAX_ACQUIRED_BUFFERS + 1) {
         return;
     }
@@ -246,7 +264,8 @@
                        bufferItem.mFence ? new Fence(bufferItem.mFence->dup()) : Fence::NO_FENCE);
     t->addTransactionCompletedCallback(transactionCallbackThunk, static_cast<void*>(this));
 
-    t->setFrame(mSurfaceControl, {0, 0, mWidth, mHeight});
+    t->setFrame(mSurfaceControl,
+                {0, 0, static_cast<int32_t>(mWidth), static_cast<int32_t>(mHeight)});
     t->setCrop(mSurfaceControl, computeCrop(bufferItem));
     t->setTransform(mSurfaceControl, bufferItem.mTransform);
     t->setTransformToDisplayInverse(mSurfaceControl, bufferItem.mTransformToDisplayInverse);
@@ -255,6 +274,11 @@
     if (applyTransaction) {
         t->apply();
     }
+
+    BQA_LOGV("processNextBufferLocked size=%dx%d mFrameNumber=%" PRIu64
+             " applyTransaction=%s mTimestamp=%" PRId64,
+             mWidth, mHeight, bufferItem.mFrameNumber, toString(applyTransaction),
+             bufferItem.mTimestamp);
 }
 
 Rect BLASTBufferQueue::computeCrop(const BufferItem& item) {
@@ -268,7 +292,10 @@
     ATRACE_CALL();
     std::unique_lock _lock{mMutex};
 
-    if (mNextTransaction != nullptr) {
+    const bool nextTransactionSet = mNextTransaction != nullptr;
+    BQA_LOGV("onFrameAvailable nextTransactionSet=%s", toString(nextTransactionSet));
+
+    if (nextTransactionSet) {
         while (mNumFrameAvailable > 0 || mNumAcquired == MAX_ACQUIRED_BUFFERS + 1) {
             mCallbackCV.wait(_lock);
         }
diff --git a/libs/gui/include/gui/BLASTBufferQueue.h b/libs/gui/include/gui/BLASTBufferQueue.h
index 2320771..35c656a 100644
--- a/libs/gui/include/gui/BLASTBufferQueue.h
+++ b/libs/gui/include/gui/BLASTBufferQueue.h
@@ -66,8 +66,8 @@
     : public ConsumerBase::FrameAvailableListener, public BufferItemConsumer::BufferFreedListener
 {
 public:
-    BLASTBufferQueue(const sp<SurfaceControl>& surface, int width, int height,
-                     bool enableTripleBuffering = true);
+    BLASTBufferQueue(const std::string& name, const sp<SurfaceControl>& surface, int width,
+                     int height, bool enableTripleBuffering = true);
 
     sp<IGraphicBufferProducer> getIGraphicBufferProducer() const {
         return mProducer;
@@ -81,7 +81,7 @@
             const std::vector<SurfaceControlStats>& stats);
     void setNextTransaction(SurfaceComposerClient::Transaction *t);
 
-    void update(const sp<SurfaceControl>& surface, int width, int height);
+    void update(const sp<SurfaceControl>& surface, uint32_t width, uint32_t height);
 
     virtual ~BLASTBufferQueue() = default;
 
@@ -95,6 +95,7 @@
     void processNextBufferLocked(bool useNextTransaction) REQUIRES(mMutex);
     Rect computeCrop(const BufferItem& item);
 
+    std::string mName;
     sp<SurfaceControl> mSurfaceControl;
 
     std::mutex mMutex;
@@ -106,17 +107,18 @@
 
     int32_t mNumFrameAvailable GUARDED_BY(mMutex);
     int32_t mNumAcquired GUARDED_BY(mMutex);
-
     struct PendingReleaseItem {
         BufferItem item;
         sp<Fence> releaseFence;
     };
 
     std::queue<const BufferItem> mSubmitted GUARDED_BY(mMutex);
+    // Keep a reference to the currently presented buffer so we can release it when the next buffer
+    // is ready to be presented.
     PendingReleaseItem mPendingReleaseItem GUARDED_BY(mMutex);
 
-    int mWidth GUARDED_BY(mMutex);
-    int mHeight GUARDED_BY(mMutex);
+    uint32_t mWidth GUARDED_BY(mMutex);
+    uint32_t mHeight GUARDED_BY(mMutex);
 
     uint32_t mTransformHint GUARDED_BY(mMutex);
 
diff --git a/libs/gui/tests/BLASTBufferQueue_test.cpp b/libs/gui/tests/BLASTBufferQueue_test.cpp
index da0d5f8..35fff0a 100644
--- a/libs/gui/tests/BLASTBufferQueue_test.cpp
+++ b/libs/gui/tests/BLASTBufferQueue_test.cpp
@@ -44,7 +44,7 @@
 class BLASTBufferQueueHelper {
 public:
     BLASTBufferQueueHelper(const sp<SurfaceControl>& sc, int width, int height) {
-        mBlastBufferQueueAdapter = new BLASTBufferQueue(sc, width, height);
+        mBlastBufferQueueAdapter = new BLASTBufferQueue("TestBLASTBufferQueue", sc, width, height);
     }
 
     void update(const sp<SurfaceControl>& sc, int width, int height) {