diff --git a/dCommon/dEnums/MessageType/Master.h b/dCommon/dEnums/MessageType/Master.h index 6ef2b1c17..36e69cdaa 100644 --- a/dCommon/dEnums/MessageType/Master.h +++ b/dCommon/dEnums/MessageType/Master.h @@ -84,5 +84,10 @@ namespace MessageType { CHAT_HANDOFF, // Master -> worlds during a live update: a new chat server is up; connect and send it who is online CHAT_SERVER_READY, + + // Dashboard -> master -> one server: start or stop a profiling session of its main loop (see Profiling.h) + PROFILE_REQUEST, + // Any server -> master -> dashboard: a profiling session started, failed or finished with its scope tree + PROFILE_RESULT, }; } diff --git a/dNet/master/Profiling.h b/dNet/master/Profiling.h new file mode 100644 index 000000000..ffdeb9a99 --- /dev/null +++ b/dNet/master/Profiling.h @@ -0,0 +1,95 @@ +#ifndef __PROFILING__H__ +#define __PROFILING__H__ + +#include +#include +#include + +#include "BitStream.h" +#include "BitStreamUtils.h" +#include "MessageType/Master.h" +#include "Profiler.h" +#include "ServiceType.h" +#include "master/ServerTraffic.h" + +/** + * Profiling sessions from the dashboard (docs/Dashboard.md, "Performance"). PROFILE_REQUEST (dashboard -> master -> the + * server named by type, zone and instance) starts or stops a session; the server merges its main loop's scope trees + * (Profiler.h) for the time asked, at most a minute, and answers with PROFILE_RESULT (server -> master -> dashboard): + * STARTED at once, then DONE with the merged tree, or FAILED with the reason. Master answers FAILED itself when the + * server isn't running. A server runs one session at a time. + */ +enum class eProfileStatus : uint8_t { + STARTED, + DONE, + FAILED, +}; + +struct ProfileRequest : public LUBitStream { + ProfileRequest() : LUBitStream(ServiceType::MASTER, MessageType::Master::PROFILE_REQUEST) {} + + uint32_t sessionId{}; + ServiceType serverType{}; + uint32_t zoneId{}; + uint32_t instanceId{}; + uint32_t durationMs{}; + bool stop{}; // end the session early + + void Serialize(RakNet::BitStream& stream) const override { + stream.Write(sessionId); + stream.Write(serverType); + stream.Write(zoneId); + stream.Write(instanceId); + stream.Write(durationMs); + stream.Write(static_cast(stop ? 1 : 0)); + } + + bool Deserialize(RakNet::BitStream& stream) override { + uint8_t flags{}; + if (!stream.Read(sessionId) || !stream.Read(serverType) || !stream.Read(zoneId) || !stream.Read(instanceId) || !stream.Read(durationMs) || + !stream.Read(flags)) return false; + stop = (flags & 1) != 0; + return true; + } +}; + +struct ProfileResult : public LUBitStream { + ProfileResult() : LUBitStream(ServiceType::MASTER, MessageType::Master::PROFILE_RESULT) {} + + static constexpr uint32_t MAX_NODES = 20000; + + uint32_t sessionId{}; + ServiceType serverType{}; + uint32_t zoneId{}; + uint32_t instanceId{}; + eProfileStatus status{}; + std::string error; // FAILED only + Profiler::Profile profile; // DONE only + + void Serialize(RakNet::BitStream& stream) const override { + stream.Write(sessionId); + stream.Write(serverType); + stream.Write(zoneId); + stream.Write(instanceId); + stream.Write(status); + ServerTraffic::WriteText(stream, error); + stream.Write(profile.durationMs); + stream.Write(profile.frames); + stream.Write(profile.totalUs); + stream.Write(static_cast(profile.truncated ? 1 : 0)); + ServerTraffic::WriteScopes(stream, profile.nodes, MAX_NODES); + } + + bool Deserialize(RakNet::BitStream& stream) override { + uint8_t truncated{}; + if (!stream.Read(sessionId) || !stream.Read(serverType) || !stream.Read(zoneId) || !stream.Read(instanceId) || !stream.Read(status) || + !ServerTraffic::ReadText(stream, error) || !stream.Read(profile.durationMs) || !stream.Read(profile.frames) || !stream.Read(profile.totalUs) || + !stream.Read(truncated)) return false; + if (status > eProfileStatus::FAILED) return false; + profile.id = sessionId; + profile.truncated = truncated != 0; + return ServerTraffic::ReadScopes(stream, profile.nodes, MAX_NODES); + } +}; + +#endif //!__PROFILING__H__ diff --git a/dNet/master/ServerTraffic.h b/dNet/master/ServerTraffic.h index 7294ad1ab..480284434 100644 --- a/dNet/master/ServerTraffic.h +++ b/dNet/master/ServerTraffic.h @@ -10,6 +10,7 @@ #include "BitStreamUtils.h" #include "MessageType/Master.h" #include "ServiceType.h" +#include "Profiler.h" #include "TrafficStats.h" /** @@ -20,7 +21,9 @@ * Newer servers append optional sections at the end, each after a marker byte, so readers that don't know them stop * before them and reports without them still read: PEER_SPLIT_MARKER, each second's packets by peer (clients, master, * other servers) and its HTTP requests from and to other servers (peerSplit); CONNECTIONS_MARKER, the busiest remote - * ends with the rest summed (hasConnections). + * ends with the rest summed (hasConnections); FRAMES_MARKER, the main loop's frame timing (see Profiler.h): per second + * frames, frame times and time per phase, the packet types that took longest to handle, the worst frames and the slow + * frames with their scopes (frames.present). */ struct ServerTraffic : public LUBitStream { ServerTraffic() : LUBitStream(ServiceType::MASTER, MessageType::Master::SERVER_TRAFFIC) {} @@ -35,11 +38,16 @@ struct ServerTraffic : public LUBitStream { static constexpr uint8_t HTTP_SPLIT_BIT = 0x80; // in a second's mask: the HTTP split follows the peers static constexpr uint8_t CONNECTIONS_MARKER = 2; static constexpr uint8_t MAX_CONNECTIONS = 64; + static constexpr uint8_t FRAMES_MARKER = 3; + static constexpr uint8_t MAX_FRAME_MESSAGES = 32; + static constexpr uint8_t MAX_FRAMES = 16; // worst or slow frames per report + static constexpr uint16_t MAX_SCOPES = 256; // per frame ServiceType serverType{}; uint32_t zoneId{}; uint32_t instanceId{}; TrafficStats::Report report; + Profiler::Report frames; static void WriteHistogram(RakNet::BitStream& stream, const TrafficStats::Histogram& histogram) { const auto sparse = histogram.Sparse(); @@ -137,6 +145,122 @@ struct ServerTraffic : public LUBitStream { if (report.peerSplit) WritePeerSplit(stream, report.seconds.size() - seconds); if (report.hasConnections) WriteConnections(stream); + if (frames.present) WriteFrames(stream, frames); + } + + // Scopes in pre-order: name, argument, depth, count, total and first start + static void WriteScopes(RakNet::BitStream& stream, const std::vector& nodes, size_t max) { + const auto count = std::min(nodes.size(), max); + stream.Write(static_cast(count)); + for (size_t i = 0; i < count; i++) { + const auto& n = nodes[i]; + WriteText(stream, n.name); + stream.Write(n.arg); + stream.Write(n.depth); + stream.Write(n.count); + stream.Write(n.totalUs); + stream.Write(n.startUs); + } + } + + static bool ReadScopes(RakNet::BitStream& stream, std::vector& nodes, size_t max) { + uint32_t count{}; + if (!stream.Read(count) || count > max) return false; + nodes.resize(count); + for (auto& n : nodes) { + if (!ReadText(stream, n.name) || !stream.Read(n.arg) || !stream.Read(n.depth) || !stream.Read(n.count) || !stream.Read(n.totalUs) || + !stream.Read(n.startUs)) return false; + } + return true; + } + + // Phase times with their count first, so a reader that knows fewer phases skips the rest and one that knows more + // leaves them 0 + template + static void WritePhases(RakNet::BitStream& stream, const std::array& phases) { + stream.Write(static_cast(Profiler::PHASES)); + for (const auto value : phases) stream.Write(Clamp(value)); + } + + template + static bool ReadPhases(RakNet::BitStream& stream, std::array& phases) { + uint8_t count{}; + if (!stream.Read(count)) return false; + phases.fill(0); + for (uint8_t i = 0; i < count; i++) { + uint32_t value{}; + if (!stream.Read(value)) return false; + if (i < Profiler::PHASES) phases[i] = value; + } + return true; + } + + static void WriteFrame(RakNet::BitStream& stream, const Profiler::Frame& frame) { + stream.Write(frame.timeMs); + stream.Write(frame.durationUs); + stream.Write(static_cast(frame.implicit ? 1 : 0)); + WritePhases(stream, frame.phaseUs); + WriteScopes(stream, frame.scopes, MAX_SCOPES); + } + + static bool ReadFrame(RakNet::BitStream& stream, Profiler::Frame& frame) { + uint8_t flags{}; + if (!stream.Read(frame.timeMs) || !stream.Read(frame.durationUs) || !stream.Read(flags) || !ReadPhases(stream, frame.phaseUs)) return false; + frame.implicit = (flags & 1) != 0; + return ReadScopes(stream, frame.scopes, MAX_SCOPES); + } + + static void WriteFrames(RakNet::BitStream& stream, const Profiler::Report& frames) { + stream.Write(FRAMES_MARKER); + stream.Write(frames.slowThresholdMs); + const auto seconds = std::min(frames.seconds.size(), MAX_SECONDS); + stream.Write(static_cast(seconds)); + for (size_t i = frames.seconds.size() - seconds; i < frames.seconds.size(); i++) { + const auto& s = frames.seconds[i]; + stream.Write(s.time); + stream.Write(s.ticks); + stream.Write(s.totalUs); + stream.Write(s.maxUs); + WriteHistogram(stream, s.frames); + WritePhases(stream, s.phaseUs); + } + const auto messages = std::min(frames.messages.size(), MAX_FRAME_MESSAGES); + stream.Write(static_cast(messages)); + for (size_t i = 0; i < messages; i++) { + const auto& m = frames.messages[i]; + stream.Write(m.key); + stream.Write(m.count); + stream.Write(m.totalUs); + stream.Write(m.maxUs); + } + for (const auto* list : { &frames.worst, &frames.slow }) { + const auto count = std::min(list->size(), MAX_FRAMES); + stream.Write(static_cast(count)); + for (size_t i = 0; i < count; i++) WriteFrame(stream, (*list)[i]); + } + } + + static bool ReadFrames(RakNet::BitStream& stream, Profiler::Report& frames) { + uint16_t seconds{}; + if (!stream.Read(frames.slowThresholdMs) || !stream.Read(seconds) || seconds > MAX_SECONDS) return false; + frames.seconds.resize(seconds); + for (auto& s : frames.seconds) { + if (!stream.Read(s.time) || !stream.Read(s.ticks) || !stream.Read(s.totalUs) || !stream.Read(s.maxUs) || !ReadHistogram(stream, s.frames) || + !ReadPhases(stream, s.phaseUs)) return false; + } + uint8_t count{}; + if (!stream.Read(count) || count > MAX_FRAME_MESSAGES) return false; + frames.messages.resize(count); + for (auto& m : frames.messages) { + if (!stream.Read(m.key) || !stream.Read(m.count) || !stream.Read(m.totalUs) || !stream.Read(m.maxUs)) return false; + } + for (auto* list : { &frames.worst, &frames.slow }) { + if (!stream.Read(count) || count > MAX_FRAMES) return false; + list->resize(count); + for (auto& frame : *list) if (!ReadFrame(stream, frame)) return false; + } + frames.present = true; + return true; } static uint32_t Clamp(uint64_t value) { return static_cast(std::min(value, UINT32_MAX)); } @@ -289,12 +413,15 @@ struct ServerTraffic : public LUBitStream { // Older servers stop here; newer ones add sections, each after its marker (a reader stops at one it doesn't know) report.peerSplit = false; report.hasConnections = false; + frames = Profiler::Report{}; uint8_t marker{}; while (stream.GetNumberOfUnreadBits() >= 8 && stream.Read(marker)) { if (marker == PEER_SPLIT_MARKER && !report.peerSplit) { if (!ReadPeerSplit(stream)) return false; } else if (marker == CONNECTIONS_MARKER && !report.hasConnections) { if (!ReadConnections(stream)) return false; + } else if (marker == FRAMES_MARKER && !frames.present) { + if (!ReadFrames(stream, frames)) return false; } else { break; } diff --git a/tests/dCommonTests/MessageIdPinTests.cpp b/tests/dCommonTests/MessageIdPinTests.cpp index 3b6cfdf61..0c77429ac 100644 --- a/tests/dCommonTests/MessageIdPinTests.cpp +++ b/tests/dCommonTests/MessageIdPinTests.cpp @@ -1807,6 +1807,8 @@ static_assert(static_cast(MessageType::Master::LIVE_UPDATE_STATUS) == 4 static_assert(static_cast(MessageType::Master::LIVE_UPDATE_RETIRE) == 41); static_assert(static_cast(MessageType::Master::CHAT_HANDOFF) == 42); static_assert(static_cast(MessageType::Master::CHAT_SERVER_READY) == 43); +static_assert(static_cast(MessageType::Master::PROFILE_REQUEST) == 44); +static_assert(static_cast(MessageType::Master::PROFILE_RESULT) == 45); // MessageType::Server: 3 enumerators static_assert(static_cast(MessageType::Server::VERSION_CONFIRM) == 0); diff --git a/tests/dGameTests/dNetTests/ServerTrafficTests.cpp b/tests/dGameTests/dNetTests/ServerTrafficTests.cpp index 6da8cc72b..f1545325d 100644 --- a/tests/dGameTests/dNetTests/ServerTrafficTests.cpp +++ b/tests/dGameTests/dNetTests/ServerTrafficTests.cpp @@ -2,6 +2,8 @@ #include #include "master/ServerTraffic.h" +#include "master/Profiling.h" +#include using namespace TrafficStats; @@ -117,3 +119,146 @@ TEST(ServerTrafficTest, ReportsWithoutTheSplitStillRead) { EXPECT_TRUE(got.report.seconds[0].peers[0].Empty()); EXPECT_EQ(got.report.gauges.size(), 1u); } + +namespace { + Profiler::Report SampleFrames() { + Profiler::Report frames; + frames.present = true; + frames.slowThresholdMs = 250; + Profiler::Second second{ .time = 1700000000, .ticks = 30, .totalUs = 90000, .maxUs = 12000 }; + second.frames.Add(3000, 29); + second.frames.Add(12000); + second.phaseUs[static_cast(Profiler::Phase::PACKETS)] = 40000; + second.phaseUs[static_cast(Profiler::Phase::ENTITIES)] = 30000; + frames.seconds = { second, Profiler::Second{ .time = 1700000001 } }; + frames.messages = { Profiler::MessageTime{ .key = TrafficStats::MessageKey{ false, 4, 5, 1234 }.Packed(), .count = 3, .totalUs = 700, .maxUs = 400 } }; + Profiler::Frame slow{ .timeMs = 1700000000500, .durationUs = 600000 }; + slow.phaseUs[static_cast(Profiler::Phase::CDCLIENT)] = 550000; + slow.scopes = { + { .name = "Frame", .depth = 0, .count = 1, .totalUs = 600000 }, + { .name = "LoadPlayer", .depth = 1, .count = 1, .totalUs = 590000, .startUs = 100 }, + { .name = "CDClient Objects", .depth = 2, .count = 9800, .totalUs = 550000, .startUs = 200 }, + }; + frames.slow = { slow }; + frames.worst = { slow }; + return frames; + } +} + +TEST(ServerTrafficTest, FramesRoundTrip) { + auto sent = Sample(true); + sent.frames = SampleFrames(); + RakNet::BitStream stream; + sent.WritePacket(stream); + ServerTraffic got; + ASSERT_TRUE(ReadBack(stream, stream.GetNumberOfBytesUsed(), got)); + EXPECT_TRUE(got.report.peerSplit); + ASSERT_TRUE(got.frames.present); + EXPECT_EQ(got.frames.slowThresholdMs, 250u); + ASSERT_EQ(got.frames.seconds.size(), 2u); + const auto& s = got.frames.seconds[0]; + EXPECT_EQ(s.time, 1700000000); + EXPECT_EQ(s.ticks, 30u); + EXPECT_EQ(s.totalUs, 90000u); + EXPECT_EQ(s.maxUs, 12000u); + EXPECT_EQ(s.frames.Count(), 30u); + EXPECT_EQ(s.frames.Sum(), 3000u * 29 + 12000u); + EXPECT_EQ(s.phaseUs[static_cast(Profiler::Phase::PACKETS)], 40000u); + EXPECT_EQ(s.phaseUs[static_cast(Profiler::Phase::ENTITIES)], 30000u); + EXPECT_EQ(got.frames.seconds[1].ticks, 0u); + ASSERT_EQ(got.frames.messages.size(), 1u); + EXPECT_EQ(got.frames.messages[0].count, 3u); + EXPECT_EQ(got.frames.messages[0].maxUs, 400u); + ASSERT_EQ(got.frames.slow.size(), 1u); + ASSERT_EQ(got.frames.worst.size(), 1u); + const auto& frame = got.frames.slow[0]; + EXPECT_EQ(frame.timeMs, 1700000000500); + EXPECT_EQ(frame.durationUs, 600000u); + EXPECT_EQ(frame.phaseUs[static_cast(Profiler::Phase::CDCLIENT)], 550000u); + EXPECT_EQ(frame.scopes, sent.frames.slow[0].scopes); + + // A cut-off section is refused + ServerTraffic broken; + EXPECT_FALSE(ReadBack(stream, stream.GetNumberOfBytesUsed() - 2, broken)); +} + +TEST(ServerTrafficTest, ReportsWithoutFramesStillRead) { + // An older server's report stops before the frames section: it reads, without frames + auto withFrames = Sample(true); + withFrames.frames = SampleFrames(); + RakNet::BitStream old, now; + Sample(true).WritePacket(old); + withFrames.WritePacket(now); + ASSERT_LT(old.GetNumberOfBytesUsed(), now.GetNumberOfBytesUsed()); + EXPECT_EQ(0, std::memcmp(old.GetData(), now.GetData(), old.GetNumberOfBytesUsed())); + ServerTraffic got; + ASSERT_TRUE(ReadBack(old, old.GetNumberOfBytesUsed(), got)); + EXPECT_FALSE(got.frames.present); + EXPECT_TRUE(got.report.peerSplit); +} + +TEST(ServerTrafficTest, ReadersStopAtSectionsTheyDontKnow) { + // A newer server's section after the frames: this reader keeps what it knows and stops there + auto sent = Sample(true); + sent.frames = SampleFrames(); + RakNet::BitStream stream; + sent.WritePacket(stream); + stream.Write(static_cast(200)); + stream.Write(static_cast(0xDEADBEEF)); + ServerTraffic got; + ASSERT_TRUE(ReadBack(stream, stream.GetNumberOfBytesUsed(), got)); + EXPECT_TRUE(got.frames.present); + EXPECT_EQ(got.frames.seconds.size(), 2u); +} + +TEST(ServerTrafficTest, PhasesOfANewerServerRead) { + // Phases go with their count: more phases than this reader knows still read, the extra ones skipped + RakNet::BitStream stream; + stream.Write(static_cast(Profiler::PHASES + 2)); + for (uint32_t i = 0; i < Profiler::PHASES + 2; i++) stream.Write(i + 1); + std::array phases{}; + ASSERT_TRUE(ServerTraffic::ReadPhases(stream, phases)); + EXPECT_EQ(phases[0], 1u); + EXPECT_EQ(phases[Profiler::PHASES - 1], Profiler::PHASES); + EXPECT_EQ(stream.GetNumberOfUnreadBits(), 0u); +} + +TEST(ServerTrafficTest, ProfileMessagesRoundTrip) { + ProfileRequest request; + request.sessionId = 7; + request.serverType = ServiceType::WORLD; + request.zoneId = 1200; + request.instanceId = 2; + request.durationMs = 10000; + RakNet::BitStream requestStream; + request.WritePacket(requestStream); + LUBitStream header; + ASSERT_TRUE(header.ReadHeader(requestStream)); + EXPECT_EQ(header.internalPacketID, static_cast(MessageType::Master::PROFILE_REQUEST)); + ProfileRequest gotRequest; + ASSERT_TRUE(gotRequest.Deserialize(requestStream)); + EXPECT_EQ(gotRequest.sessionId, 7u); + EXPECT_EQ(gotRequest.zoneId, 1200u); + EXPECT_EQ(gotRequest.durationMs, 10000u); + EXPECT_FALSE(gotRequest.stop); + + ProfileResult result; + result.sessionId = 7; + result.serverType = ServiceType::WORLD; + result.status = eProfileStatus::DONE; + result.profile.durationMs = 10002; + result.profile.frames = 300; + result.profile.totalUs = 450000; + result.profile.nodes = { { .name = "All frames", .count = 300, .totalUs = 450000 }, { .name = "Entities", .depth = 1, .count = 300, .totalUs = 200000 } }; + RakNet::BitStream resultStream; + result.WritePacket(resultStream); + LUBitStream resultHeader; + ASSERT_TRUE(resultHeader.ReadHeader(resultStream)); + EXPECT_EQ(resultHeader.internalPacketID, static_cast(MessageType::Master::PROFILE_RESULT)); + ProfileResult got; + ASSERT_TRUE(got.Deserialize(resultStream)); + EXPECT_EQ(got.status, eProfileStatus::DONE); + EXPECT_EQ(got.profile.id, 7u); + EXPECT_EQ(got.profile.frames, 300u); + EXPECT_EQ(got.profile.nodes, result.profile.nodes); +}