feat(net): frame timing section in SERVER_TRAFFIC, profiling messages

An optional section after marker 3 carries the report's frame timing; older readers stop before it and reports without it still read. Phase times go with their count so readers with fewer or more phases read them. PROFILE_REQUEST and PROFILE_RESULT are appended to the master messages (44, 45). Task 96.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Aaron Kimbrell
2026-09-29 22:06:29 -05:00
parent 06af6c3aaa
commit d0c7b089ff
5 changed files with 375 additions and 1 deletions

View File

@@ -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,
};
}

95
dNet/master/Profiling.h Normal file
View File

@@ -0,0 +1,95 @@
#ifndef __PROFILING__H__
#define __PROFILING__H__
#include <algorithm>
#include <cstdint>
#include <string>
#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<uint8_t>(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<uint8_t>(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__

View File

@@ -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<Profiler::Node>& nodes, size_t max) {
const auto count = std::min(nodes.size(), max);
stream.Write(static_cast<uint32_t>(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<Profiler::Node>& 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<typename T>
static void WritePhases(RakNet::BitStream& stream, const std::array<T, Profiler::PHASES>& phases) {
stream.Write(static_cast<uint8_t>(Profiler::PHASES));
for (const auto value : phases) stream.Write(Clamp(value));
}
template<typename T>
static bool ReadPhases(RakNet::BitStream& stream, std::array<T, Profiler::PHASES>& 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<uint8_t>(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<size_t>(frames.seconds.size(), MAX_SECONDS);
stream.Write(static_cast<uint16_t>(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<size_t>(frames.messages.size(), MAX_FRAME_MESSAGES);
stream.Write(static_cast<uint8_t>(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<size_t>(list->size(), MAX_FRAMES);
stream.Write(static_cast<uint8_t>(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<uint32_t>(std::min<uint64_t>(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;
}

View File

@@ -1807,6 +1807,8 @@ static_assert(static_cast<int64_t>(MessageType::Master::LIVE_UPDATE_STATUS) == 4
static_assert(static_cast<int64_t>(MessageType::Master::LIVE_UPDATE_RETIRE) == 41);
static_assert(static_cast<int64_t>(MessageType::Master::CHAT_HANDOFF) == 42);
static_assert(static_cast<int64_t>(MessageType::Master::CHAT_SERVER_READY) == 43);
static_assert(static_cast<int64_t>(MessageType::Master::PROFILE_REQUEST) == 44);
static_assert(static_cast<int64_t>(MessageType::Master::PROFILE_RESULT) == 45);
// MessageType::Server: 3 enumerators
static_assert(static_cast<int64_t>(MessageType::Server::VERSION_CONFIRM) == 0);

View File

@@ -2,6 +2,8 @@
#include <cstring>
#include "master/ServerTraffic.h"
#include "master/Profiling.h"
#include <array>
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<size_t>(Profiler::Phase::PACKETS)] = 40000;
second.phaseUs[static_cast<size_t>(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<size_t>(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<size_t>(Profiler::Phase::PACKETS)], 40000u);
EXPECT_EQ(s.phaseUs[static_cast<size_t>(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<size_t>(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<uint8_t>(200));
stream.Write(static_cast<uint32_t>(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<uint8_t>(Profiler::PHASES + 2));
for (uint32_t i = 0; i < Profiler::PHASES + 2; i++) stream.Write(i + 1);
std::array<uint64_t, Profiler::PHASES> 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<uint32_t>(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<uint32_t>(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);
}