Frame Timeline Perfetto producer
This change adds a Perfetto Producer inside FrameTimeline that emits
DisplayFrame and SurfaceFrame as TracePackets as per the proto defined
in frame_timeline_event.proto
This change also adds a MockFrameTimeline to be used in unittests as a
part of TestableSurfaceFlinger. Due to perfetto capability, running
production FrameTimeline in TestableSurfaceFlinger has caused issues and
its best to isolate them.
Bug: 170914689
Test: libsurfaceflinger_unittest (whole test suite without filter)
Change-Id: Iabd5521629d16ded6ba3f165229caa74b1cb8eb7
diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
index 03c6f70..cb617d6 100644
--- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
+++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
@@ -22,10 +22,16 @@
#include <FrameTimeline/FrameTimeline.h>
#include <gtest/gtest.h>
#include <log/log.h>
+#include <perfetto/trace/trace.pb.h>
#include <cinttypes>
using namespace std::chrono_literals;
using testing::Contains;
+using FrameTimelineEvent = perfetto::protos::FrameTimelineEvent;
+using ProtoDisplayFrame = perfetto::protos::FrameTimelineEvent_DisplayFrame;
+using ProtoSurfaceFrame = perfetto::protos::FrameTimelineEvent_SurfaceFrame;
+using ProtoPresentType = perfetto::protos::FrameTimelineEvent_PresentType;
+using ProtoJankType = perfetto::protos::FrameTimelineEvent_JankType;
MATCHER_P(HasBit, bit, "") {
return (arg & bit) != 0;
@@ -47,14 +53,56 @@
ALOGD("**** Tearing down after %s.%s\n", test_info->test_case_name(), test_info->name());
}
+ static void SetUpTestSuite() {
+ // Need to initialize tracing in process for testing, and only once per test suite.
+ perfetto::TracingInitArgs args;
+ args.backends = perfetto::kInProcessBackend;
+ perfetto::Tracing::Initialize(args);
+ }
+
void SetUp() override {
mTimeStats = std::make_shared<mock::TimeStats>();
mFrameTimeline = std::make_unique<impl::FrameTimeline>(mTimeStats);
+ mFrameTimeline->registerDataSource();
mTokenManager = &mFrameTimeline->mTokenManager;
maxDisplayFrames = &mFrameTimeline->mMaxDisplayFrames;
maxTokenRetentionTime = mTokenManager->kMaxRetentionTime;
}
+ // Each tracing session can be used for a single block of Start -> Stop.
+ static std::unique_ptr<perfetto::TracingSession> getTracingSessionForTest() {
+ perfetto::TraceConfig cfg;
+ cfg.set_duration_ms(500);
+ cfg.add_buffers()->set_size_kb(1024);
+ auto* ds_cfg = cfg.add_data_sources()->mutable_config();
+ ds_cfg->set_name(impl::FrameTimeline::kFrameTimelineDataSource);
+
+ auto tracingSession = perfetto::Tracing::NewTrace(perfetto::kInProcessBackend);
+ tracingSession->Setup(cfg);
+ return tracingSession;
+ }
+
+ std::vector<perfetto::protos::TracePacket> readFrameTimelinePacketsBlocking(
+ perfetto::TracingSession* tracingSession) {
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ perfetto::protos::Trace trace;
+ EXPECT_TRUE(trace.ParseFromArray(raw_trace.data(), int(raw_trace.size())));
+
+ std::vector<perfetto::protos::TracePacket> packets;
+ for (const auto& packet : trace.packet()) {
+ if (!packet.has_frame_timeline_event()) {
+ continue;
+ }
+ packets.emplace_back(packet);
+ }
+ return packets;
+ }
+
+ void addEmptyDisplayFrame() {
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ mFrameTimeline->setSfPresent(2500, presentFence1);
+ }
+
void flushTokens(nsecs_t flushTime) {
std::lock_guard<std::mutex> lock(mTokenManager->mMutex);
mTokenManager->flushTokens(flushTime);
@@ -413,4 +461,308 @@
presentFence1);
}
+/*
+ * Tracing Tests
+ *
+ * Trace packets are flushed all the way only when the next packet is traced.
+ * For example: trace<Display/Surface>Frame() will create a TracePacket but not flush it. Only when
+ * another TracePacket is created, the previous one is guaranteed to be flushed. The following tests
+ * will have additional empty frames created for this reason.
+ */
+TEST_F(FrameTimelineTest, tracing_noPacketsSentWithoutTraceStart) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
+ int64_t token2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
+ auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken(sPidOne, sUidOne, sLayerNameOne,
+ sLayerNameOne, token1);
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(token1, 20);
+ mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1), SurfaceFrame::PresentState::Dropped);
+ mFrameTimeline->setSfPresent(25, presentFence1);
+ presentFence1->signalForTest(30);
+
+ // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
+ // next frame
+ mFrameTimeline->setSfWakeUp(token2, 50);
+ mFrameTimeline->setSfPresent(55, presentFence2);
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ EXPECT_EQ(packets.size(), 0);
+}
+
+TEST_F(FrameTimelineTest, tracing_sanityTest) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
+ int64_t token2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
+ auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken(sPidOne, sUidOne, sLayerNameOne,
+ sLayerNameOne, token1);
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(token2, 20);
+ mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1),
+ SurfaceFrame::PresentState::Presented);
+ mFrameTimeline->setSfPresent(25, presentFence1);
+ presentFence1->signalForTest(30);
+
+ // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
+ // next frame
+ mFrameTimeline->setSfWakeUp(token2, 50);
+ mFrameTimeline->setSfPresent(55, presentFence2);
+ presentFence2->signalForTest(55);
+
+ // The SurfaceFrame packet from the first frame is emitted, but not flushed yet. Emitting a new
+ // packet will flush it. To emit a new packet, we'll need to call flushPendingPresentFences()
+ // again, which is done by setSfPresent().
+ addEmptyDisplayFrame();
+ tracingSession->StopBlocking();
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ // Display Frame 1 has two packets - DisplayFrame and a SurfaceFrame.
+ // Display Frame 2 has one packet - DisplayFrame. However, this packet has been emitted but not
+ // flushed through traced, so this is not counted.
+ EXPECT_EQ(packets.size(), 2);
+}
+
+TEST_F(FrameTimelineTest, traceDisplayFrame_invalidTokenDoesNotEmitTracePacket) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(-1, 20);
+ mFrameTimeline->setSfPresent(25, presentFence1);
+ presentFence1->signalForTest(30);
+
+ // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
+ // next frame
+ mFrameTimeline->setSfWakeUp(token1, 50);
+ mFrameTimeline->setSfPresent(55, presentFence2);
+ presentFence2->signalForTest(60);
+
+ addEmptyDisplayFrame();
+ tracingSession->StopBlocking();
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ // Display Frame 1 has no packets.
+ // Display Frame 2 has one packet - DisplayFrame. However, this packet has
+ // been emitted but not flushed through traced, so this is not counted.
+ EXPECT_EQ(packets.size(), 0);
+}
+
+TEST_F(FrameTimelineTest, traceSurfaceFrame_invalidTokenDoesNotEmitTracePacket) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
+ int64_t token2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
+ auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken(sPidOne, sUidOne, sLayerNameOne,
+ sLayerNameOne, std::nullopt);
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(token1, 20);
+ mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1), SurfaceFrame::PresentState::Dropped);
+ mFrameTimeline->setSfPresent(25, presentFence1);
+ presentFence1->signalForTest(30);
+
+ // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
+ // next frame
+ mFrameTimeline->setSfWakeUp(token2, 50);
+ mFrameTimeline->setSfPresent(55, presentFence2);
+ presentFence2->signalForTest(60);
+
+ addEmptyDisplayFrame();
+ tracingSession->StopBlocking();
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ // Display Frame 1 has one packet - DisplayFrame (SurfaceFrame shouldn't be traced since it has
+ // an invalid token).
+ // Display Frame 2 has one packet - DisplayFrame. However, this packet has
+ // been emitted but not flushed through traced, so this is not counted.
+ EXPECT_EQ(packets.size(), 1);
+}
+
+void validateDisplayFrameEvent(const ProtoDisplayFrame& received, const ProtoDisplayFrame& source) {
+ ASSERT_TRUE(received.has_token());
+ EXPECT_EQ(received.token(), source.token());
+
+ ASSERT_TRUE(received.has_present_type());
+ EXPECT_EQ(received.present_type(), source.present_type());
+ ASSERT_TRUE(received.has_on_time_finish());
+ EXPECT_EQ(received.on_time_finish(), source.on_time_finish());
+ ASSERT_TRUE(received.has_gpu_composition());
+ EXPECT_EQ(received.gpu_composition(), source.gpu_composition());
+ ASSERT_TRUE(received.has_jank_type());
+ EXPECT_EQ(received.jank_type(), source.jank_type());
+
+ ASSERT_TRUE(received.has_expected_start_ns());
+ EXPECT_EQ(received.expected_start_ns(), source.expected_start_ns());
+ ASSERT_TRUE(received.has_expected_end_ns());
+ EXPECT_EQ(received.expected_end_ns(), source.expected_end_ns());
+
+ ASSERT_TRUE(received.has_actual_start_ns());
+ EXPECT_EQ(received.actual_start_ns(), source.actual_start_ns());
+ ASSERT_TRUE(received.has_actual_end_ns());
+ EXPECT_EQ(received.actual_end_ns(), source.actual_end_ns());
+}
+
+void validateSurfaceFrameEvent(const ProtoSurfaceFrame& received, const ProtoSurfaceFrame& source) {
+ ASSERT_TRUE(received.has_token());
+ EXPECT_EQ(received.token(), source.token());
+
+ ASSERT_TRUE(received.has_display_frame_token());
+ EXPECT_EQ(received.display_frame_token(), source.display_frame_token());
+
+ ASSERT_TRUE(received.has_present_type());
+ EXPECT_EQ(received.present_type(), source.present_type());
+ ASSERT_TRUE(received.has_on_time_finish());
+ EXPECT_EQ(received.on_time_finish(), source.on_time_finish());
+ ASSERT_TRUE(received.has_gpu_composition());
+ EXPECT_EQ(received.gpu_composition(), source.gpu_composition());
+ ASSERT_TRUE(received.has_jank_type());
+ EXPECT_EQ(received.jank_type(), source.jank_type());
+
+ ASSERT_TRUE(received.has_expected_start_ns());
+ EXPECT_EQ(received.expected_start_ns(), source.expected_start_ns());
+ ASSERT_TRUE(received.has_expected_end_ns());
+ EXPECT_EQ(received.expected_end_ns(), source.expected_end_ns());
+
+ ASSERT_TRUE(received.has_actual_start_ns());
+ EXPECT_EQ(received.actual_start_ns(), source.actual_start_ns());
+ ASSERT_TRUE(received.has_actual_end_ns());
+ EXPECT_EQ(received.actual_end_ns(), source.actual_end_ns());
+
+ ASSERT_TRUE(received.has_layer_name());
+ EXPECT_EQ(received.layer_name(), source.layer_name());
+ ASSERT_TRUE(received.has_pid());
+ EXPECT_EQ(received.pid(), source.pid());
+}
+
+TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ int64_t displayFrameToken1 = mTokenManager->generateTokenForPredictions({10, 25, 30});
+ int64_t displayFrameToken2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(displayFrameToken1, 20);
+ mFrameTimeline->setSfPresent(26, presentFence1);
+ presentFence1->signalForTest(31);
+
+ ProtoDisplayFrame protoDisplayFrame;
+ protoDisplayFrame.set_token(displayFrameToken1);
+ protoDisplayFrame.set_present_type(ProtoPresentType(FrameTimelineEvent::PRESENT_ON_TIME));
+ protoDisplayFrame.set_on_time_finish(true);
+ protoDisplayFrame.set_gpu_composition(false);
+ protoDisplayFrame.set_jank_type(ProtoJankType(FrameTimelineEvent::JANK_NONE));
+ protoDisplayFrame.set_expected_start_ns(10);
+ protoDisplayFrame.set_expected_end_ns(25);
+ protoDisplayFrame.set_actual_start_ns(20);
+ protoDisplayFrame.set_actual_end_ns(26);
+
+ // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
+ // next frame
+ mFrameTimeline->setSfWakeUp(displayFrameToken2, 50);
+ mFrameTimeline->setSfPresent(55, presentFence2);
+ presentFence2->signalForTest(55);
+
+ addEmptyDisplayFrame();
+ tracingSession->StopBlocking();
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ // Display Frame 1 has one packet - DisplayFrame.
+ // Display Frame 2 has one packet - DisplayFrame. However, this packet has been emitted but not
+ // flushed through traced, so this is not counted.
+ EXPECT_EQ(packets.size(), 1);
+
+ const auto& packet = packets[0];
+ ASSERT_TRUE(packet.has_timestamp());
+ ASSERT_TRUE(packet.has_frame_timeline_event());
+
+ const auto& event = packet.frame_timeline_event();
+ ASSERT_TRUE(event.has_display_frame());
+ ASSERT_FALSE(event.has_surface_frame());
+ const auto& displayFrameEvent = event.display_frame();
+ validateDisplayFrameEvent(displayFrameEvent, protoDisplayFrame);
+}
+
+TEST_F(FrameTimelineTest, traceSurfaceFrame_emitsValidTracePacket) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ int64_t surfaceFrameToken = mTokenManager->generateTokenForPredictions({10, 25, 40});
+ int64_t displayFrameToken1 = mTokenManager->generateTokenForPredictions({30, 35, 40});
+ int64_t displayFrameToken2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
+
+ auto surfaceFrame1 =
+ mFrameTimeline->createSurfaceFrameForToken(sPidOne, sUidOne, sLayerNameOne,
+ sLayerNameOne, surfaceFrameToken);
+ surfaceFrame1->setActualStartTime(0);
+ surfaceFrame1->setActualQueueTime(15);
+ surfaceFrame1->setAcquireFenceTime(20);
+
+ ProtoSurfaceFrame protoSurfaceFrame;
+ protoSurfaceFrame.set_token(surfaceFrameToken);
+ protoSurfaceFrame.set_display_frame_token(displayFrameToken1);
+ protoSurfaceFrame.set_present_type(ProtoPresentType(FrameTimelineEvent::PRESENT_ON_TIME));
+ protoSurfaceFrame.set_on_time_finish(true);
+ protoSurfaceFrame.set_gpu_composition(false);
+ protoSurfaceFrame.set_jank_type(ProtoJankType(FrameTimelineEvent::JANK_NONE));
+ protoSurfaceFrame.set_expected_start_ns(10);
+ protoSurfaceFrame.set_expected_end_ns(25);
+ protoSurfaceFrame.set_actual_start_ns(0);
+ protoSurfaceFrame.set_actual_end_ns(20);
+ protoSurfaceFrame.set_layer_name(sLayerNameOne);
+ protoSurfaceFrame.set_pid(sPidOne);
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(displayFrameToken1, 20);
+ mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1),
+ SurfaceFrame::PresentState::Presented);
+ mFrameTimeline->setSfPresent(26, presentFence1);
+ presentFence1->signalForTest(31);
+
+ // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
+ // next frame
+ mFrameTimeline->setSfWakeUp(displayFrameToken2, 50);
+ mFrameTimeline->setSfPresent(55, presentFence2);
+ presentFence2->signalForTest(55);
+
+ addEmptyDisplayFrame();
+ tracingSession->StopBlocking();
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ // Display Frame 1 has one packet - DisplayFrame and a SurfaceFrame.
+ // Display Frame 2 has one packet - DisplayFrame. However, this packet has been emitted but not
+ // flushed through traced, so this is not counted.
+ EXPECT_EQ(packets.size(), 2);
+
+ const auto& packet = packets[1];
+ ASSERT_TRUE(packet.has_timestamp());
+ ASSERT_TRUE(packet.has_frame_timeline_event());
+
+ const auto& event = packet.frame_timeline_event();
+ ASSERT_TRUE(!event.has_display_frame());
+ ASSERT_TRUE(event.has_surface_frame());
+ const auto& surfaceFrameEvent = event.surface_frame();
+ validateSurfaceFrameEvent(surfaceFrameEvent, protoSurfaceFrame);
+}
+
} // namespace android::frametimeline