Refactor: Pull tracing out of TimeStats.
The tracing in TimeStats ended up having no actual overlap with current
TimeStats functionality. This CL pulls all tracing related code out
into its own class.
Test: atest libsurfaceflinger_unittest and manually inspected traces.
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.frame"
}
}
duration_ms: 3000
EOF
} && adb pull /data/misc/perfetto-traces/trace ~/Desktop/trace
Fixes: 140298240
Change-Id: I52d80d46eb8dee8979b02416ab7a758b7e58dfd1
diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
index f01e603..ffacbfe 100644
--- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
+++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
@@ -20,8 +20,8 @@
#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>
@@ -109,15 +109,6 @@
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() {
@@ -126,13 +117,6 @@
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);
@@ -147,22 +131,8 @@
}
}
- // 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;
- FenceToFenceTimeMap fenceFactory;
+ std::unique_ptr<TimeStats> mTimeStats = std::make_unique<impl::TimeStats>();
};
std::string TimeStatsTest::inputCommand(InputCommand cmd, bool useProto) {
@@ -239,330 +209,6 @@
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());