#include #include "Profiler.h" #include using namespace Profiler; namespace { constexpr int64_t MS = 1000000; // nanoseconds constexpr int64_t UNIX_MS = 1700000000000; size_t PhaseIndex(Phase phase) { return static_cast(phase); } const Node* Find(const std::vector& nodes, const std::string& name) { for (const auto& node : nodes) if (node.name == name) return &node; return nullptr; } } TEST(ProfilerTest, FramesAddUpPerSecond) { Recorder recorder; int64_t now = 1000 * MS; for (int i = 0; i < 3; i++) { recorder.FrameBegin(now, UNIX_MS + i * 100); recorder.Enter("Entities", 0, now); recorder.SetPhase(Phase::ENTITIES, now); now += 4 * MS; recorder.SetPhase(Phase::OTHER, now); recorder.Exit(now); now += 1 * MS; recorder.FrameEnd(now); now += 30 * MS; // asleep } const auto report = recorder.Take(UNIX_MS / 1000 + 1); ASSERT_TRUE(report.present); ASSERT_EQ(report.seconds.size(), 1u); const auto& second = report.seconds[0]; EXPECT_EQ(second.time, UNIX_MS / 1000); EXPECT_EQ(second.ticks, 3u); EXPECT_EQ(second.totalUs, 15000u); EXPECT_EQ(second.maxUs, 5000u); EXPECT_EQ(second.frames.Count(), 3u); EXPECT_EQ(second.phaseUs[PhaseIndex(Phase::ENTITIES)], 12000u); EXPECT_EQ(second.phaseUs[PhaseIndex(Phase::OTHER)], 3000u); // The longest frames, with their scopes ASSERT_EQ(report.worst.size(), Recorder::WORST_FRAMES); EXPECT_EQ(report.worst[0].durationUs, 5000u); EXPECT_TRUE(report.slow.empty()); } TEST(ProfilerTest, SecondsMerge) { Second a{ .time = 10, .ticks = 2, .totalUs = 3000, .maxUs = 2000 }; a.frames.Add(1000); a.frames.Add(2000); a.phaseUs[1] = 500; Second b{ .time = 11, .ticks = 1, .totalUs = 9000, .maxUs = 9000 }; b.frames.Add(9000); b.phaseUs[1] = 250; a.Merge(b); EXPECT_EQ(a.time, 10); EXPECT_EQ(a.ticks, 3u); EXPECT_EQ(a.totalUs, 12000u); EXPECT_EQ(a.maxUs, 9000u); EXPECT_EQ(a.frames.Count(), 3u); EXPECT_EQ(a.frames.Sum(), 12000u); EXPECT_EQ(a.phaseUs[1], 750u); // Merged histograms give the percentiles of all their frames EXPECT_GE(a.frames.Percentile(1.0), 9000u * 9 / 10); } TEST(ProfilerTest, SilentSecondsAreFilledIn) { Recorder recorder; const int64_t t = UNIX_MS / 1000; recorder.FrameBegin(0, UNIX_MS); recorder.FrameEnd(1 * MS); auto report = recorder.Take(t + 1); ASSERT_EQ(report.seconds.size(), 1u); // A main loop stuck for 3 seconds: those seconds come as no frames report = recorder.Take(t + 4); ASSERT_EQ(report.seconds.size(), 3u); EXPECT_EQ(report.seconds[0].time, t + 1); EXPECT_EQ(report.seconds[2].ticks, 0u); } TEST(ProfilerTest, SlowFrameCaptureHasItsScopes) { Recorder recorder; recorder.SetSlowThreshold(250); std::vector logged; recorder.SetSlowSink([&logged](const Frame& frame) { logged.push_back(frame); }); int64_t now = 0; recorder.FrameBegin(now, UNIX_MS); recorder.Enter(PACKET, 42, now); recorder.SetPhase(Phase::PACKETS, now); now += 1 * MS; recorder.Enter("LoadPlayer", 0, now); recorder.Enter("CreateEntity", 0, now); for (int i = 0; i < 9800; i++) { now += MS / 20; // 50 microseconds each recorder.Record("CDClient Objects", 0, MS / 20, Phase::CDCLIENT, now); } recorder.Enter(COMPONENT, 17, now); now += 60 * MS; recorder.Exit(now); recorder.Exit(now); // CreateEntity recorder.Exit(now); // LoadPlayer recorder.SetPhase(Phase::OTHER, now); recorder.Exit(now); // packet now += 2 * MS; recorder.FrameEnd(now); ASSERT_EQ(logged.size(), 1u); const auto report = recorder.Take(UNIX_MS / 1000 + 1); ASSERT_EQ(report.slow.size(), 1u); const auto& frame = report.slow[0]; EXPECT_EQ(frame.timeMs, UNIX_MS); EXPECT_EQ(frame.durationUs, 1000u + 490000u + 60000u + 2000u); EXPECT_FALSE(frame.implicit); EXPECT_EQ(frame.phaseUs[PhaseIndex(Phase::CDCLIENT)], 490000u); EXPECT_EQ(frame.phaseUs[PhaseIndex(Phase::PACKETS)], 61000u); EXPECT_EQ(frame.phaseUs[PhaseIndex(Phase::OTHER)], 2000u); // The tree, in pre-order with depths, children by when they started ASSERT_EQ(frame.scopes.size(), 6u); EXPECT_EQ(frame.scopes[0].name, FRAME); EXPECT_EQ(frame.scopes[0].depth, 0); EXPECT_EQ(frame.scopes[1].name, PACKET); EXPECT_EQ(frame.scopes[1].arg, 42u); EXPECT_EQ(frame.scopes[2].name, "LoadPlayer"); EXPECT_EQ(frame.scopes[3].name, "CreateEntity"); EXPECT_EQ(frame.scopes[3].depth, 3); EXPECT_EQ(frame.scopes[4].name, "CDClient Objects"); EXPECT_EQ(frame.scopes[4].count, 9800u); EXPECT_EQ(frame.scopes[4].totalUs, 490000u); EXPECT_EQ(frame.scopes[4].depth, 4); EXPECT_EQ(frame.scopes[5].name, COMPONENT); EXPECT_EQ(frame.scopes[5].totalUs, 60000u); EXPECT_EQ(frame.scopes[2].totalUs, 550000u); const auto path = frame.Path(); EXPECT_NE(path.find("LoadPlayer 550.0 ms > CreateEntity 550.0 ms > CDClient Objects 490.0 ms x9800"), std::string::npos) << path; // Also in the report's worst frames, cut to fewer scopes ASSERT_FALSE(report.worst.empty()); EXPECT_EQ(report.worst[0].durationUs, frame.durationUs); } TEST(ProfilerTest, SlowFramesKeepTheHeaviestScopesWithTheirParents) { Recorder recorder; recorder.SetSlowThreshold(1); int64_t now = 0; recorder.FrameBegin(now, UNIX_MS); // Many light scopes and one heavy one deep down for (int i = 0; i < 60; i++) { recorder.Enter(Intern("light " + std::to_string(i)), 0, now); now += MS / 100; recorder.Exit(now); } recorder.Enter("a", 0, now); recorder.Enter("b", 0, now); recorder.Enter("heavy", 0, now); now += 10 * MS; recorder.Exit(now); recorder.Exit(now); recorder.Exit(now); recorder.FrameEnd(now); const auto report = recorder.Take(UNIX_MS / 1000 + 1); ASSERT_EQ(report.slow.size(), 1u); const auto& scopes = report.slow[0].scopes; EXPECT_LE(scopes.size(), Recorder::SLOW_SCOPES + 1); const auto* heavy = Find(scopes, "heavy"); ASSERT_NE(heavy, nullptr); EXPECT_EQ(heavy->depth, 3); EXPECT_NE(Find(scopes, "a"), nullptr); EXPECT_NE(Find(scopes, "b"), nullptr); } TEST(ProfilerTest, TooManyDifferentChildrenShareOne) { Recorder recorder; int64_t now = 0; recorder.SetSlowThreshold(1); recorder.FrameBegin(now, UNIX_MS); for (size_t i = 0; i < Recorder::MAX_CHILDREN + 10; i++) { recorder.Enter("child", i + 1, now); now += MS / 10; recorder.Exit(now); } now += MS; recorder.FrameEnd(now); const auto report = recorder.Take(UNIX_MS / 1000 + 1); ASSERT_EQ(report.slow.size(), 1u); bool more = false; for (const auto& node : report.slow[0].scopes) { if (node.name == "(more)") { more = true; EXPECT_EQ(node.count, 10u); } } EXPECT_TRUE(more); } TEST(ProfilerTest, WorkOutsideFramesIsItsOwnFrame) { Recorder recorder; recorder.SetSlowThreshold(100); std::vector logged; recorder.SetSlowSink([&logged](const Frame& frame) { logged.push_back(frame); }); // A scope with no frame open (a zone load at startup) is timed as one, but not counted as a tick recorder.Enter("Zone load", 0, 0); EXPECT_TRUE(recorder.InFrame()); recorder.Exit(400 * MS); EXPECT_FALSE(recorder.InFrame()); ASSERT_EQ(logged.size(), 1u); EXPECT_TRUE(logged[0].implicit); EXPECT_EQ(logged[0].durationUs, 400000u); ASSERT_EQ(logged[0].scopes.size(), 2u); EXPECT_EQ(logged[0].scopes[0].name, OUTSIDE); EXPECT_EQ(logged[0].scopes[1].name, "Zone load"); const auto report = recorder.Take(Profiler::UnixMs() / 1000 + 1); for (const auto& second : report.seconds) EXPECT_EQ(second.ticks, 0u); ASSERT_EQ(report.slow.size(), 1u); } TEST(ProfilerTest, SessionsMergeFramesIntoFoldedStacks) { Recorder recorder; std::optional result; int64_t now = 0; ASSERT_TRUE(recorder.StartSession(5, 1000, now, [&result](Profile&& profile) { result = std::move(profile); })); EXPECT_FALSE(recorder.StartSession(6, 1000, now, [](Profile&&) {})); for (int i = 0; i < 10; i++) { recorder.FrameBegin(now, UNIX_MS); recorder.Enter("Entities", 0, now); now += 2 * MS; recorder.Enter("Script timer", 0, now); now += 1 * MS; recorder.Exit(now); recorder.Exit(now); recorder.Enter("Physics step", 0, now); now += 1 * MS; recorder.Exit(now); recorder.FrameEnd(now); now += 30 * MS; } // Not yet: 340 ms of 1000 EXPECT_FALSE(result.has_value()); recorder.CheckSession(now + 1000 * MS); ASSERT_TRUE(result.has_value()); EXPECT_FALSE(recorder.SessionActive()); EXPECT_EQ(result->id, 5u); EXPECT_EQ(result->frames, 10u); EXPECT_EQ(result->totalUs, 40000u); EXPECT_FALSE(result->truncated); ASSERT_EQ(result->nodes.size(), 4u); EXPECT_EQ(result->nodes[0].name, "All frames"); EXPECT_EQ(result->nodes[0].count, 10u); // Heaviest child first EXPECT_EQ(result->nodes[1].name, "Entities"); EXPECT_EQ(result->nodes[1].count, 10u); EXPECT_EQ(result->nodes[1].totalUs, 30000u); EXPECT_EQ(result->nodes[2].name, "Script timer"); EXPECT_EQ(result->nodes[2].depth, 2); EXPECT_EQ(result->nodes[3].name, "Physics step"); // Folded stacks: each stack's own time EXPECT_EQ(Folded(result->nodes), "All frames;Entities 20000\n" "All frames;Entities;Script timer 10000\n" "All frames;Physics step 10000\n"); // With labels (the dashboard names packets); ';' can't appear in a frame name EXPECT_EQ(Folded({ { .name = "a;b", .count = 1, .totalUs = 5 } }, [](const Node& node) { return "x" + node.name; }), "xa,b 5\n"); } TEST(ProfilerTest, SessionsStopEarly) { Recorder recorder; bool done = false; ASSERT_TRUE(recorder.StartSession(1, 60000, 0, [&done](Profile&& profile) { done = true; EXPECT_EQ(profile.frames, 1u); })); recorder.FrameBegin(0, UNIX_MS); recorder.FrameEnd(MS); EXPECT_FALSE(recorder.StopSession(2, MS)); EXPECT_TRUE(recorder.StopSession(1, MS)); EXPECT_TRUE(done); } TEST(ProfilerTest, MessageTimesAreReportedLongestFirst) { Recorder recorder; recorder.AddMessageTime(1, 5 * MS); recorder.AddMessageTime(2, 1 * MS); recorder.AddMessageTime(1, 3 * MS); const auto report = recorder.Take(10); ASSERT_EQ(report.messages.size(), 2u); EXPECT_EQ(report.messages[0].key, 1u); EXPECT_EQ(report.messages[0].count, 2u); EXPECT_EQ(report.messages[0].totalUs, 8000u); EXPECT_EQ(report.messages[0].maxUs, 5000u); EXPECT_TRUE(recorder.Take(11).messages.empty()); } TEST(ProfilerTest, ScopesOffTheMainThreadDoNothing) { // This test's thread isn't marked as a main thread: nothing is recorded in the process's recorder { Scope scope("Worker", Phase::DATABASE); } EXPECT_FALSE(Local().InFrame()); }