Fix broken FrameLifecycle due to Blast adapter

Since the BLASTBQ adapter removed the BQ path from SurfaceViews to
SurfaecFlinger, FrameLifecycle is completely broken as it works only for
BQ so far. This change adds FrameLifecycle coverage to BLAST buffers
that send dequeueTime along with the Transaction.

Bug: 176931912
Test: TransactionFrameTracerTest
Test: Take a trace of any game and make sure Frame Lifecycle events show
up.

Change-Id: I1429c86f2890c3ff8e5a06d6136df0282cf439ea

6 files changed, 180 insertions, 4 deletions

diff --git a/services/surfaceflinger/BufferStateLayer.cpp b/services/surfaceflinger/BufferStateLayer.cpp
index e470eb940c..076c7072e3 100644
--- a/services/surfaceflinger/BufferStateLayer.cpp
+++ b/services/surfaceflinger/BufferStateLayer.cpp
@@ -35,6 +35,7 @@
 #include <renderengine/Image.h>
 
 #include "EffectLayer.h"
+#include "FrameTracer/FrameTracer.h"
 #include "TimeStats/TimeStats.h"
 
 namespace android {
@@ -337,7 +338,7 @@ 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,
-                                 std::optional<nsecs_t> /* dequeueTime */,
+                                 std::optional<nsecs_t> dequeueTime,
                                  const FrameTimelineInfo& info) {
     ATRACE_CALL();
 
@@ -377,6 +378,14 @@ bool BufferStateLayer::setBuffer(const sp<GraphicBuffer>& buffer, const sp<Fence
         setFrameTimelineVsyncForBufferTransaction(info, postTime);
     }
 
+    if (dequeueTime && *dequeueTime != 0) {
+        const uint64_t bufferId = buffer->getId();
+        mFlinger->mFrameTracer->traceNewLayer(layerId, getName().c_str());
+        mFlinger->mFrameTracer->traceTimestamp(layerId, bufferId, frameNumber, *dequeueTime,
+                                               FrameTracer::FrameEvent::DEQUEUE);
+        mFlinger->mFrameTracer->traceTimestamp(layerId, bufferId, frameNumber, postTime,
+                                               FrameTracer::FrameEvent::QUEUE);
+    }
     return true;
 }
 
@@ -628,9 +637,16 @@ status_t BufferStateLayer::updateTexImage(bool& /*recomputeVisibleRegions*/, nse
     }
 
     const int32_t layerId = getSequence();
-    mFlinger->mTimeStats->setAcquireFence(layerId, mDrawingState.frameNumber,
-                                          std::make_shared<FenceTime>(mDrawingState.acquireFence));
-    mFlinger->mTimeStats->setLatchTime(layerId, mDrawingState.frameNumber, latchTime);
+    const uint64_t bufferId = mDrawingState.buffer->getId();
+    const uint64_t frameNumber = mDrawingState.frameNumber;
+    const auto acquireFence = std::make_shared<FenceTime>(mDrawingState.acquireFence);
+    mFlinger->mTimeStats->setAcquireFence(layerId, frameNumber, acquireFence);
+    mFlinger->mTimeStats->setLatchTime(layerId, frameNumber, latchTime);
+
+    mFlinger->mFrameTracer->traceFence(layerId, bufferId, frameNumber, acquireFence,
+                                       FrameTracer::FrameEvent::ACQUIRE_FENCE);
+    mFlinger->mFrameTracer->traceTimestamp(layerId, bufferId, frameNumber, latchTime,
+                                           FrameTracer::FrameEvent::LATCH);
 
     auto& bufferSurfaceFrame = mDrawingState.bufferSurfaceFrameTX;
     if (bufferSurfaceFrame != nullptr &&
diff --git a/services/surfaceflinger/BufferStateLayer.h b/services/surfaceflinger/BufferStateLayer.h
index ea832a2078..175a40b80e 100644
--- a/services/surfaceflinger/BufferStateLayer.h
+++ b/services/surfaceflinger/BufferStateLayer.h
@@ -124,6 +124,7 @@ protected:
 
 private:
     friend class SlotGenerationTest;
+    friend class TransactionFrameTracerTest;
     friend class TransactionSurfaceFrameTest;
 
     inline void tracePendingBufferCount();
diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h
index 9cd15e8705..4c2fd448c0 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -1004,6 +1004,7 @@ protected:
     friend class TestableSurfaceFlinger;
     friend class RefreshRateSelectionTest;
     friend class SetFrameRateTest;
+    friend class TransactionFrameTracerTest;
     friend class TransactionSurfaceFrameTest;
 
     virtual void setInitialValuesForClone(const sp<Layer>& clonedFrom);
diff --git a/services/surfaceflinger/tests/unittests/Android.bp b/services/surfaceflinger/tests/unittests/Android.bp
index 17928a0d61..e55821f690 100644
--- a/services/surfaceflinger/tests/unittests/Android.bp
+++ b/services/surfaceflinger/tests/unittests/Android.bp
@@ -73,6 +73,7 @@ cc_test {
         "FrameTracerTest.cpp",
         "TimerTest.cpp",
         "TransactionApplicationTest.cpp",
+        "TransactionFrameTracerTest.cpp",
         "TransactionSurfaceFrameTest.cpp",
         "StrongTypingTest.cpp",
         "VSyncDispatchTimerQueueTest.cpp",
diff --git a/services/surfaceflinger/tests/unittests/TestableSurfaceFlinger.h b/services/surfaceflinger/tests/unittests/TestableSurfaceFlinger.h
index 3787c436a0..a94b9bd0f7 100644
--- a/services/surfaceflinger/tests/unittests/TestableSurfaceFlinger.h
+++ b/services/surfaceflinger/tests/unittests/TestableSurfaceFlinger.h
@@ -405,6 +405,10 @@ public:
 
     const auto& getCompositorTiming() const { return mFlinger->getBE().mCompositorTiming; }
 
+    mock::FrameTracer* getFrameTracer() const {
+        return static_cast<mock::FrameTracer*>(mFlinger->mFrameTracer.get());
+    }
+
     /* ------------------------------------------------------------------------
      * Read-write access to private data to set up preconditions and assert
      * post-conditions.
diff --git a/services/surfaceflinger/tests/unittests/TransactionFrameTracerTest.cpp b/services/surfaceflinger/tests/unittests/TransactionFrameTracerTest.cpp
new file mode 100644
index 0000000000..dbadf75d44
--- /dev/null
+++ b/services/surfaceflinger/tests/unittests/TransactionFrameTracerTest.cpp
@@ -0,0 +1,153 @@
+/*
+ * Copyright (C) 2021 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#undef LOG_TAG
+#define LOG_TAG "LibSurfaceFlingerUnittests"
+
+#include <gmock/gmock.h>
+#include <gtest/gtest.h>
+#include <gui/SurfaceComposerClient.h>
+#include <log/log.h>
+#include <utils/String8.h>
+
+#include "TestableSurfaceFlinger.h"
+#include "mock/DisplayHardware/MockComposer.h"
+#include "mock/MockEventThread.h"
+#include "mock/MockVsyncController.h"
+
+namespace android {
+
+using testing::_;
+using testing::Mock;
+using testing::Return;
+using FakeHwcDisplayInjector = TestableSurfaceFlinger::FakeHwcDisplayInjector;
+using PresentState = frametimeline::SurfaceFrame::PresentState;
+
+class TransactionFrameTracerTest : public testing::Test {
+public:
+    TransactionFrameTracerTest() {
+        const ::testing::TestInfo* const test_info =
+                ::testing::UnitTest::GetInstance()->current_test_info();
+        ALOGD("**** Setting up for %s.%s\n", test_info->test_case_name(), test_info->name());
+        setupScheduler();
+        setupComposer(0);
+    }
+
+    ~TransactionFrameTracerTest() {
+        const ::testing::TestInfo* const test_info =
+                ::testing::UnitTest::GetInstance()->current_test_info();
+        ALOGD("**** Tearing down after %s.%s\n", test_info->test_case_name(), test_info->name());
+    }
+
+    sp<BufferStateLayer> createBufferStateLayer() {
+        sp<Client> client;
+        LayerCreationArgs args(mFlinger.flinger(), client, "buffer-state-layer", 100, 100, 0,
+                               LayerMetadata());
+        return new BufferStateLayer(args);
+    }
+
+    void commitTransaction(Layer* layer) {
+        layer->pushPendingState();
+        auto c = layer->getCurrentState();
+        if (layer->applyPendingStates(&c)) {
+            layer->commitTransaction(c);
+        }
+    }
+
+    void setupScheduler() {
+        auto eventThread = std::make_unique<mock::EventThread>();
+        auto sfEventThread = std::make_unique<mock::EventThread>();
+
+        EXPECT_CALL(*eventThread, registerDisplayEventConnection(_));
+        EXPECT_CALL(*eventThread, createEventConnection(_, _))
+                .WillOnce(Return(new EventThreadConnection(eventThread.get(), /*callingUid=*/0,
+                                                           ResyncCallback())));
+
+        EXPECT_CALL(*sfEventThread, registerDisplayEventConnection(_));
+        EXPECT_CALL(*sfEventThread, createEventConnection(_, _))
+                .WillOnce(Return(new EventThreadConnection(sfEventThread.get(), /*callingUid=*/0,
+                                                           ResyncCallback())));
+
+        auto vsyncController = std::make_unique<mock::VsyncController>();
+        auto vsyncTracker = std::make_unique<mock::VSyncTracker>();
+
+        EXPECT_CALL(*vsyncTracker, nextAnticipatedVSyncTimeFrom(_)).WillRepeatedly(Return(0));
+        EXPECT_CALL(*vsyncTracker, currentPeriod())
+                .WillRepeatedly(Return(FakeHwcDisplayInjector::DEFAULT_VSYNC_PERIOD));
+        EXPECT_CALL(*vsyncTracker, nextAnticipatedVSyncTimeFrom(_)).WillRepeatedly(Return(0));
+        mFlinger.setupScheduler(std::move(vsyncController), std::move(vsyncTracker),
+                                std::move(eventThread), std::move(sfEventThread));
+    }
+
+    void setupComposer(uint32_t virtualDisplayCount) {
+        mComposer = new Hwc2::mock::Composer();
+        EXPECT_CALL(*mComposer, getMaxVirtualDisplayCount()).WillOnce(Return(virtualDisplayCount));
+        mFlinger.setupComposer(std::unique_ptr<Hwc2::Composer>(mComposer));
+
+        Mock::VerifyAndClear(mComposer);
+    }
+
+    TestableSurfaceFlinger mFlinger;
+    Hwc2::mock::Composer* mComposer = nullptr;
+    FenceToFenceTimeMap fenceFactory;
+    client_cache_t mClientCache;
+
+    void BLASTTransactionSendsFrameTracerEvents() {
+        sp<BufferStateLayer> layer = createBufferStateLayer();
+
+        sp<Fence> fence(new Fence());
+        sp<GraphicBuffer> buffer{new GraphicBuffer(1, 1, HAL_PIXEL_FORMAT_RGBA_8888, 1, 0)};
+        int32_t layerId = layer->getSequence();
+        uint64_t bufferId = buffer->getId();
+        uint64_t frameNumber = 5;
+        nsecs_t dequeueTime = 10;
+        nsecs_t postTime = 20;
+        EXPECT_CALL(*mFlinger.getFrameTracer(), traceNewLayer(layerId, "buffer-state-layer"));
+        EXPECT_CALL(*mFlinger.getFrameTracer(),
+                    traceTimestamp(layerId, bufferId, frameNumber, dequeueTime,
+                                   FrameTracer::FrameEvent::DEQUEUE, /*duration*/ 0));
+        EXPECT_CALL(*mFlinger.getFrameTracer(),
+                    traceTimestamp(layerId, bufferId, frameNumber, postTime,
+                                   FrameTracer::FrameEvent::QUEUE, /*duration*/ 0));
+        layer->setBuffer(buffer, fence, postTime, /*desiredPresentTime*/ 30, false, mClientCache,
+                         frameNumber, dequeueTime, FrameTimelineInfo{});
+
+        commitTransaction(layer.get());
+        bool computeVisisbleRegions;
+        nsecs_t latchTime = 25;
+        EXPECT_CALL(*mFlinger.getFrameTracer(),
+                    traceFence(layerId, bufferId, frameNumber, _,
+                               FrameTracer::FrameEvent::ACQUIRE_FENCE, /*startTime*/ 0));
+        EXPECT_CALL(*mFlinger.getFrameTracer(),
+                    traceTimestamp(layerId, bufferId, frameNumber, latchTime,
+                                   FrameTracer::FrameEvent::LATCH, /*duration*/ 0));
+        layer->updateTexImage(computeVisisbleRegions, latchTime, /*expectedPresentTime*/ 0);
+
+        auto glDoneFence = fenceFactory.createFenceTimeForTest(fence);
+        auto presentFence = fenceFactory.createFenceTimeForTest(fence);
+        CompositorTiming compositorTiming;
+        EXPECT_CALL(*mFlinger.getFrameTracer(),
+                    traceFence(layerId, bufferId, frameNumber, presentFence,
+                               FrameTracer::FrameEvent::PRESENT_FENCE, /*startTime*/ 0));
+        layer->onPostComposition(nullptr, glDoneFence, presentFence, compositorTiming);
+    }
+};
+
+TEST_F(TransactionFrameTracerTest, BLASTTransactionSendsFrameTracerEvents) {
+    BLASTTransactionSendsFrameTracerEvents();
+}
+
+} // namespace android
\ No newline at end of file