Add per-buffer perfetto trace points for SurfaceFlinger frame events
In order to track how buffers move through the system, we add per-buffer perfetto trace points for SurfaceFlinger.
The majority of these were already tracked through TimeStats, so the new tracing was built on top of TimeStats.
Test: atest libsurfaceflinger_unittest
Run trace with:
{ adb shell perfetto -c - --txt -o /data/misc/perfetto-traces/trace <<EOF
buffers: {
size_kb: 1280
}
data_sources: {
config {
name: "android.surfaceflinger.timestats"
}
}
duration_ms: 3000
EOF
} && adb pull /data/misc/perfetto-traces/trace ~/Desktop/trace
Change-Id: Ifb38c64a9966fece735f0ad72438c7c9c5e07baa
diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
index f35758d..f01e603 100644
--- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
+++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
@@ -17,18 +17,17 @@
#undef LOG_TAG
#define LOG_TAG "LibSurfaceFlingerUnittests"
+#include <TimeStats/TimeStats.h>
#include <gmock/gmock.h>
#include <gtest/gtest.h>
-
#include <log/log.h>
+#include <perfetto/trace/trace.pb.h>
#include <utils/String16.h>
#include <utils/Vector.h>
#include <random>
#include <unordered_set>
-#include "TimeStats/TimeStats.h"
-
#include "libsurfaceflinger_unittest_main.h"
using namespace android::surfaceflinger;
@@ -110,6 +109,15 @@
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());
+
+ // Need to initialize tracing in process for testing, and only once per test suite.
+ static bool wasInitialized = false;
+ if (!wasInitialized) {
+ perfetto::TracingInitArgs args;
+ args.backends = perfetto::kInProcessBackend;
+ perfetto::Tracing::Initialize(args);
+ wasInitialized = true;
+ }
}
~TimeStatsTest() {
@@ -118,6 +126,13 @@
ALOGD("**** Tearing down after %s.%s\n", test_info->test_case_name(), test_info->name());
}
+ void SetUp() override {
+ mTimeStats = std::make_unique<impl::TimeStats>();
+ mTimeStats->registerTracingDataSource();
+ }
+
+ void TearDown() override { mTimeStats.reset(); }
+
std::string inputCommand(InputCommand cmd, bool useProto);
void setTimeStamp(TimeStamp type, int32_t id, uint64_t frameNumber, nsecs_t ts);
@@ -132,8 +147,22 @@
}
}
+ // 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(TimeStats::kTimeStatsDataSource);
+
+ auto tracingSession = perfetto::Tracing::NewTrace(perfetto::kInProcessBackend);
+ tracingSession->Setup(cfg);
+ return tracingSession;
+ }
+
std::mt19937 mRandomEngine = std::mt19937(std::random_device()());
- std::unique_ptr<TimeStats> mTimeStats = std::make_unique<impl::TimeStats>();
+ std::unique_ptr<TimeStats> mTimeStats;
+ FenceToFenceTimeMap fenceFactory;
};
std::string TimeStatsTest::inputCommand(InputCommand cmd, bool useProto) {
@@ -210,6 +239,330 @@
return distr(mRandomEngine);
}
+TEST_F(TimeStatsTest, traceNewLayerStartsTrackingLayerWhenTracing) {
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 0\n");
+
+ const std::string layerName = "co.layername#0";
+ const int32_t layerID = 5;
+ mTimeStats->traceNewLayer(layerID, layerName);
+
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 0\n");
+
+ auto tracingSession = getTracingSessionForTest();
+ tracingSession->StartBlocking();
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 0\n");
+ mTimeStats->traceNewLayer(layerID, layerName);
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 1\n");
+ tracingSession->StopBlocking();
+}
+
+TEST_F(TimeStatsTest, onDestroyRemovesTheTrackedLayer) {
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 0\n");
+
+ const std::string layerName = "co.layername#0";
+ const int32_t layerID = 5;
+ const int32_t secondLayerID = 6;
+
+ auto tracingSession = getTracingSessionForTest();
+ tracingSession->StartBlocking();
+ mTimeStats->traceNewLayer(layerID, layerName);
+ mTimeStats->traceNewLayer(secondLayerID, layerName);
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 2\n");
+ tracingSession->StopBlocking();
+
+ mTimeStats->onDestroy(layerID);
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 1\n");
+ mTimeStats->onDestroy(layerID);
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 1\n");
+ mTimeStats->onDestroy(secondLayerID);
+ EXPECT_EQ(mTimeStats->miniDump(),
+ "TimeStats miniDump:\nNumber of layers currently being tracked is 0\nNumber of "
+ "layers in the stats pool is 0\nNumber of layers currently being traced is 0\n");
+}
+
+TEST_F(TimeStatsTest, canTraceAfterAddingLayer) {
+ const std::string layerName = "co.layername#0";
+ const int32_t layerID = 1;
+ const uint32_t bufferID = 2;
+ const uint64_t frameNumber = 3;
+ const nsecs_t timestamp = 4;
+ const nsecs_t duration = 5;
+ const auto type = TimeStats::FrameEvent::POST;
+
+ {
+ auto tracingSession = getTracingSessionForTest();
+
+ tracingSession->StartBlocking();
+ // Clean up irrelevant traces.
+ tracingSession->ReadTraceBlocking();
+
+ mTimeStats->traceTimestamp(layerID, bufferID, frameNumber, timestamp, type, duration);
+ // Create second trace packet to finalize the previous one.
+ mTimeStats->traceTimestamp(layerID, 0, 0, 0, TimeStats::FrameEvent::UNSPECIFIED);
+ tracingSession->StopBlocking();
+
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ EXPECT_EQ(raw_trace.size(), 0);
+ }
+
+ {
+ auto tracingSession = getTracingSessionForTest();
+
+ tracingSession->StartBlocking();
+ // Clean up irrelevant traces.
+ tracingSession->ReadTraceBlocking();
+
+ mTimeStats->traceNewLayer(layerID, layerName);
+ mTimeStats->traceTimestamp(layerID, bufferID, frameNumber, timestamp, type, duration);
+ // Create second trace packet to finalize the previous one.
+ mTimeStats->traceTimestamp(layerID, 0, 0, 0, TimeStats::FrameEvent::UNSPECIFIED);
+ tracingSession->StopBlocking();
+
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ ASSERT_GT(raw_trace.size(), 0);
+
+ perfetto::protos::Trace trace;
+ ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), int(raw_trace.size())));
+ ASSERT_FALSE(trace.packet().empty());
+ EXPECT_EQ(trace.packet().size(), 1);
+
+ const auto& packet = trace.packet().Get(0);
+ ASSERT_TRUE(packet.has_timestamp());
+ EXPECT_EQ(packet.timestamp(), timestamp);
+ ASSERT_TRUE(packet.has_graphics_frame_event());
+ const auto& frame_event = packet.graphics_frame_event();
+ ASSERT_TRUE(frame_event.has_buffer_event());
+ const auto& buffer_event = frame_event.buffer_event();
+ ASSERT_TRUE(buffer_event.has_buffer_id());
+ EXPECT_EQ(buffer_event.buffer_id(), bufferID);
+ ASSERT_TRUE(buffer_event.has_frame_number());
+ EXPECT_EQ(buffer_event.frame_number(), frameNumber);
+ ASSERT_TRUE(buffer_event.has_type());
+ EXPECT_EQ(buffer_event.type(), perfetto::protos::GraphicsFrameEvent_BufferEventType(type));
+ ASSERT_TRUE(buffer_event.has_duration_ns());
+ EXPECT_EQ(buffer_event.duration_ns(), duration);
+ }
+}
+
+TEST_F(TimeStatsTest, traceFenceTriggersOnNextTraceAfterFenceFired) {
+ const std::string layerName = "co.layername#0";
+ const int32_t layerID = 5;
+ const uint32_t bufferID = 4;
+ const uint64_t frameNumber = 3;
+ const auto type = TimeStats::FrameEvent::ACQUIRE_FENCE;
+
+ {
+ auto fenceTime = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ fenceFactory.signalAllForTest(Fence::NO_FENCE, Fence::SIGNAL_TIME_PENDING);
+ auto tracingSession = getTracingSessionForTest();
+ tracingSession->StartBlocking();
+ // Clean up irrelevant traces.
+ tracingSession->ReadTraceBlocking();
+ // Trace.
+ mTimeStats->traceNewLayer(layerID, layerName);
+ mTimeStats->traceFence(layerID, bufferID, frameNumber, fenceTime, type);
+ // Create extra trace packet to (hopefully not) trigger and finalize the fence packet.
+ mTimeStats->traceTimestamp(layerID, bufferID, 0, 0, TimeStats::FrameEvent::UNSPECIFIED);
+ tracingSession->StopBlocking();
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ EXPECT_EQ(raw_trace.size(), 0);
+ }
+
+ {
+ auto fenceTime = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ auto tracingSession = getTracingSessionForTest();
+ tracingSession->StartBlocking();
+ // Clean up irrelevant traces.
+ tracingSession->ReadTraceBlocking();
+ mTimeStats->traceNewLayer(layerID, layerName);
+ mTimeStats->traceFence(layerID, bufferID, frameNumber, fenceTime, type);
+ const nsecs_t timestamp = systemTime();
+ fenceFactory.signalAllForTest(Fence::NO_FENCE, timestamp);
+ // Create extra trace packet to trigger and finalize fence trace packets.
+ mTimeStats->traceTimestamp(layerID, bufferID, 0, 0, TimeStats::FrameEvent::UNSPECIFIED);
+ tracingSession->StopBlocking();
+
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ ASSERT_GT(raw_trace.size(), 0);
+
+ perfetto::protos::Trace trace;
+ ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), int(raw_trace.size())));
+ ASSERT_FALSE(trace.packet().empty());
+ EXPECT_EQ(trace.packet().size(), 2); // Two packets because of the extra trace made above.
+
+ const auto& packet = trace.packet().Get(1);
+ ASSERT_TRUE(packet.has_timestamp());
+ EXPECT_EQ(packet.timestamp(), timestamp);
+ ASSERT_TRUE(packet.has_graphics_frame_event());
+ const auto& frame_event = packet.graphics_frame_event();
+ ASSERT_TRUE(frame_event.has_buffer_event());
+ const auto& buffer_event = frame_event.buffer_event();
+ ASSERT_TRUE(buffer_event.has_buffer_id());
+ EXPECT_EQ(buffer_event.buffer_id(), bufferID);
+ ASSERT_TRUE(buffer_event.has_frame_number());
+ EXPECT_EQ(buffer_event.frame_number(), frameNumber);
+ ASSERT_TRUE(buffer_event.has_type());
+ EXPECT_EQ(buffer_event.type(), perfetto::protos::GraphicsFrameEvent_BufferEventType(type));
+ EXPECT_FALSE(buffer_event.has_duration_ns());
+ }
+}
+
+TEST_F(TimeStatsTest, traceFenceWithStartTimeAfterSignalTime_ShouldHaveNoDuration) {
+ const std::string layerName = "co.layername#0";
+ const int32_t layerID = 5;
+ const uint32_t bufferID = 4;
+ const uint64_t frameNumber = 3;
+ const auto type = TimeStats::FrameEvent::ACQUIRE_FENCE;
+
+ auto tracingSession = getTracingSessionForTest();
+
+ tracingSession->StartBlocking();
+ // Clean up irrelevant traces.
+ tracingSession->ReadTraceBlocking();
+ mTimeStats->traceNewLayer(layerID, layerName);
+
+ // traceFence called after fence signalled.
+ const nsecs_t signalTime1 = systemTime();
+ const nsecs_t startTime1 = signalTime1 + 100000;
+ auto fence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ fenceFactory.signalAllForTest(Fence::NO_FENCE, signalTime1);
+ mTimeStats->traceFence(layerID, bufferID, frameNumber, fence1, type, startTime1);
+
+ // traceFence called before fence signalled.
+ const nsecs_t signalTime2 = systemTime();
+ const nsecs_t startTime2 = signalTime2 + 100000;
+ auto fence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ mTimeStats->traceFence(layerID, bufferID, frameNumber, fence2, type, startTime2);
+ fenceFactory.signalAllForTest(Fence::NO_FENCE, signalTime2);
+
+ // Create extra trace packet to trigger and finalize fence trace packets.
+ mTimeStats->traceTimestamp(layerID, bufferID, 0, 0, TimeStats::FrameEvent::UNSPECIFIED);
+ tracingSession->StopBlocking();
+
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ ASSERT_GT(raw_trace.size(), 0);
+
+ perfetto::protos::Trace trace;
+ ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), int(raw_trace.size())));
+ ASSERT_FALSE(trace.packet().empty());
+ EXPECT_EQ(trace.packet().size(), 2);
+
+ const auto& packet1 = trace.packet().Get(0);
+ ASSERT_TRUE(packet1.has_timestamp());
+ EXPECT_EQ(packet1.timestamp(), signalTime1);
+ ASSERT_TRUE(packet1.has_graphics_frame_event());
+ ASSERT_TRUE(packet1.graphics_frame_event().has_buffer_event());
+ ASSERT_FALSE(packet1.graphics_frame_event().buffer_event().has_duration_ns());
+
+ const auto& packet2 = trace.packet().Get(1);
+ ASSERT_TRUE(packet2.has_timestamp());
+ EXPECT_EQ(packet2.timestamp(), signalTime2);
+ ASSERT_TRUE(packet2.has_graphics_frame_event());
+ ASSERT_TRUE(packet2.graphics_frame_event().has_buffer_event());
+ ASSERT_FALSE(packet2.graphics_frame_event().buffer_event().has_duration_ns());
+}
+
+TEST_F(TimeStatsTest, traceFenceOlderThanDeadline_ShouldBeIgnored) {
+ const std::string layerName = "co.layername#0";
+ const int32_t layerID = 5;
+ const uint32_t bufferID = 4;
+ const uint64_t frameNumber = 3;
+ const auto type = TimeStats::FrameEvent::ACQUIRE_FENCE;
+ const nsecs_t signalTime = systemTime() - TimeStats::kFenceSignallingDeadline;
+
+ auto tracingSession = getTracingSessionForTest();
+ auto fence = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ // Clean up irrelevant traces.
+ tracingSession->ReadTraceBlocking();
+ mTimeStats->traceNewLayer(layerID, layerName);
+ mTimeStats->traceFence(layerID, bufferID, frameNumber, fence, type);
+ fenceFactory.signalAllForTest(Fence::NO_FENCE, signalTime);
+ // Create extra trace packet to trigger and finalize any previous fence packets.
+ mTimeStats->traceTimestamp(layerID, bufferID, 0, 0, TimeStats::FrameEvent::UNSPECIFIED);
+ tracingSession->StopBlocking();
+
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ EXPECT_EQ(raw_trace.size(), 0);
+}
+
+TEST_F(TimeStatsTest, traceFenceWithValidStartTime_ShouldHaveCorrectDuration) {
+ const std::string layerName = "co.layername#0";
+ const int32_t layerID = 5;
+ const uint32_t bufferID = 4;
+ const uint64_t frameNumber = 3;
+ const auto type = TimeStats::FrameEvent::ACQUIRE_FENCE;
+ const nsecs_t duration = 1234;
+
+ auto tracingSession = getTracingSessionForTest();
+
+ tracingSession->StartBlocking();
+ // Clean up irrelevant traces.
+ tracingSession->ReadTraceBlocking();
+ mTimeStats->traceNewLayer(layerID, layerName);
+
+ // traceFence called after fence signalled.
+ const nsecs_t signalTime1 = systemTime();
+ const nsecs_t startTime1 = signalTime1 - duration;
+ auto fence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ fenceFactory.signalAllForTest(Fence::NO_FENCE, signalTime1);
+ mTimeStats->traceFence(layerID, bufferID, frameNumber, fence1, type, startTime1);
+
+ // traceFence called before fence signalled.
+ const nsecs_t signalTime2 = systemTime();
+ const nsecs_t startTime2 = signalTime2 - duration;
+ auto fence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ mTimeStats->traceFence(layerID, bufferID, frameNumber, fence2, type, startTime2);
+ fenceFactory.signalAllForTest(Fence::NO_FENCE, signalTime2);
+
+ // Create extra trace packet to trigger and finalize fence trace packets.
+ mTimeStats->traceTimestamp(layerID, bufferID, 0, 0, TimeStats::FrameEvent::UNSPECIFIED);
+ tracingSession->StopBlocking();
+
+ std::vector<char> raw_trace = tracingSession->ReadTraceBlocking();
+ ASSERT_GT(raw_trace.size(), 0);
+
+ perfetto::protos::Trace trace;
+ ASSERT_TRUE(trace.ParseFromArray(raw_trace.data(), int(raw_trace.size())));
+ ASSERT_FALSE(trace.packet().empty());
+ EXPECT_EQ(trace.packet().size(), 2);
+
+ const auto& packet1 = trace.packet().Get(0);
+ ASSERT_TRUE(packet1.has_timestamp());
+ EXPECT_EQ(packet1.timestamp(), startTime1);
+ ASSERT_TRUE(packet1.has_graphics_frame_event());
+ ASSERT_TRUE(packet1.graphics_frame_event().has_buffer_event());
+ ASSERT_TRUE(packet1.graphics_frame_event().buffer_event().has_duration_ns());
+ const auto& buffer_event1 = packet1.graphics_frame_event().buffer_event();
+ EXPECT_EQ(buffer_event1.duration_ns(), duration);
+
+ const auto& packet2 = trace.packet().Get(1);
+ ASSERT_TRUE(packet2.has_timestamp());
+ EXPECT_EQ(packet2.timestamp(), startTime2);
+ ASSERT_TRUE(packet2.has_graphics_frame_event());
+ ASSERT_TRUE(packet2.graphics_frame_event().has_buffer_event());
+ ASSERT_TRUE(packet2.graphics_frame_event().buffer_event().has_duration_ns());
+ const auto& buffer_event2 = packet2.graphics_frame_event().buffer_event();
+ EXPECT_EQ(buffer_event2.duration_ns(), duration);
+}
+
TEST_F(TimeStatsTest, canEnableAndDisableTimeStats) {
EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
ASSERT_TRUE(mTimeStats->isEnabled());