From 63666c3c6be2f00d884d02c00d0b44183d81549f Mon Sep 17 00:00:00 2001 From: Aaron Kimbrell Date: Tue, 29 Sep 2026 22:06:30 -0500 Subject: [PATCH] feat(servers): report frame timing, log slow frames, answer profiling requests dServer sends the frames with each traffic report, logs a frame over slow_frame_ms (default 250, reread on a settings reload) as one line with its heaviest path, and runs profiling sessions master forwards. Master routes the dashboard's requests to the named server, profiles itself and passes results on. Task 96. Co-Authored-By: Claude Opus 5.5 --- dDashboardServer/routes/SettingsCatalog.cpp | 1 + dMasterServer/MasterServer.cpp | 53 ++++++++++++++ dNet/dServer.cpp | 79 +++++++++++++++++++++ dNet/dServer.h | 13 ++++ resources/sharedconfig.ini | 4 ++ 5 files changed, 150 insertions(+) diff --git a/dDashboardServer/routes/SettingsCatalog.cpp b/dDashboardServer/routes/SettingsCatalog.cpp index 44ac6e74b..bf47b4009 100644 --- a/dDashboardServer/routes/SettingsCatalog.cpp +++ b/dDashboardServer/routes/SettingsCatalog.cpp @@ -158,6 +158,7 @@ namespace { c.AddSection("Logging and crashes"); c.Add(Bool(SHARED, "log_to_console", "Log to the console", "Also print log lines to the terminal.", true, true)); c.Add(Bool(SHARED, "log_debug_statements", "Debug logging", "Extra log lines for developers.", false, true)); + c.Add(Unit(Int(SHARED, "slow_frame_ms", "Slow frame", "A server's main loop frame that takes this long is logged with what took the time, and shown on the Performance page. 0 turns it off.", "250", 0, 600000), "ms")); c.Add(Format(Text(SHARED, "dump_folder", "Crash dump folder", "Where crash logs go. Empty turns them off.", "", true), eFormat::PATH)); c.Add(Bool(WORLD, "generate_dump", "Crash dumps from world servers", "Write a dump when a world server crashes (needs the crash dump folder).", false, true)); c.Add(Bool(WORLD, "save_lxfmls", "Save model files", "Save players' models (LXFML) to disk before they are split, for debugging.", false)); diff --git a/dMasterServer/MasterServer.cpp b/dMasterServer/MasterServer.cpp index a6ccd2d22..e2827079f 100644 --- a/dMasterServer/MasterServer.cpp +++ b/dMasterServer/MasterServer.cpp @@ -1,3 +1,4 @@ +#include "Profiler.h" #include "master/PlayerAction.h" #include "master/DashboardMessages.h" #include @@ -55,6 +56,7 @@ #include "master/InstanceMigration.h" #include "master/LiveUpdate.h" #include "master/ServerTraffic.h" +#include "master/Profiling.h" #include "master/UgcModelsMade.h" #include "BuildInfo.h" @@ -475,6 +477,10 @@ int main(int argc, char** argv) { Game::server->SetTrafficSink([](ServerTraffic& report) { if (dashboardServerMasterPeerSysAddr != UNASSIGNED_SYSTEM_ADDRESS) MasterPackets::SendTo(dashboardServerMasterPeerSysAddr, report); }); + // Its profiling results too + Game::server->SetProfileSink([](ProfileResult& result) { + if (dashboardServerMasterPeerSysAddr != UNASSIGNED_SYSTEM_ADDRESS) MasterPackets::SendTo(dashboardServerMasterPeerSysAddr, result); + }); std::string master_server_ip = "localhost"; const auto masterServerIPString = Game::config->GetValue("master_ip"); @@ -555,11 +561,13 @@ int main(int argc, char** argv) { Game::logger->Flush(); while (!Game::ShouldShutdown()) { + Profiler::BeginFrame(); //In world we'd update our other systems here. //Check for packets here: packet = Game::server->Receive(); if (packet) { + Profiler::PacketScope scope(packet->data, packet->length); HandlePacket(packet); Game::server->DeallocatePacket(packet); packet = nullptr; @@ -584,6 +592,7 @@ int main(int argc, char** argv) { //Push our log every 15s: if (framesSinceLastFlush >= logFlushTime) { + Profiler::Scope scope("Log flush", Profiler::Phase::LOG_FLUSH); Game::logger->Flush(); framesSinceLastFlush = 0; } else @@ -656,6 +665,7 @@ int main(int argc, char** argv) { waitpid(static_cast(-1), &status, WNOHANG); #endif + Profiler::EndFrame(); t += std::chrono::milliseconds(masterFrameDelta); std::this_thread::sleep_until(t); } @@ -1005,6 +1015,47 @@ namespace { MasterPackets::SendTo(dashboardServerMasterPeerSysAddr, report); } + // Profiling sessions (Profiling.h): the dashboard's request goes to the server it names; master profiles itself + void OnProfileRequest(const ProfileRequest& request, const SystemAddress& sysAddr) { + if (sysAddr != dashboardServerMasterPeerSysAddr) { + LOG("Ignoring a profiling request from a server that is not the dashboard"); + return; + } + SystemAddress target = UNASSIGNED_SYSTEM_ADDRESS; + switch (request.serverType) { + case ServiceType::MASTER: + Game::server->HandleProfileRequest(request); + return; + case ServiceType::AUTH: target = authServerMasterPeerSysAddr; break; + case ServiceType::CHAT: target = chatServerMasterPeerSysAddr; break; + case ServiceType::UGC: target = ugcServerMasterPeerSysAddr; break; + case ServiceType::WORLD: { + const auto& instance = Game::im->FindInstanceWithPrivate(static_cast(request.zoneId), static_cast(request.instanceId)); + if (instance) target = instance->GetSysAddr(); + break; + } + default: break; + } + if (target != UNASSIGNED_SYSTEM_ADDRESS) { + MasterPackets::SendTo(target, request); + return; + } + if (request.stop) return; + ProfileResult failed; + failed.sessionId = request.sessionId; + failed.serverType = request.serverType; + failed.zoneId = request.zoneId; + failed.instanceId = request.instanceId; + failed.status = eProfileStatus::FAILED; + failed.error = "That server isn't running"; + MasterPackets::SendTo(dashboardServerMasterPeerSysAddr, failed); + } + + void OnProfileResult(const ProfileResult& result, const SystemAddress& sysAddr) { + if (dashboardServerMasterPeerSysAddr == UNASSIGNED_SYSTEM_ADDRESS || sysAddr == dashboardServerMasterPeerSysAddr) return; + MasterPackets::SendTo(dashboardServerMasterPeerSysAddr, result); + } + void OnAnnounce(const Announcement& announcement, const SystemAddress& sysAddr) { if (sysAddr != dashboardServerMasterPeerSysAddr) { LOG("Ignoring announcement from a server that is not the dashboard"); @@ -1120,6 +1171,8 @@ namespace { handlers.On(Master::MESSAGE_CAPTURE_DATA, ForwardWorldToDashboard); handlers.On(Master::REQUEST_SERVER_LIST, OnRequestServerList); handlers.On(Master::SERVER_TRAFFIC, OnServerTraffic); + handlers.On(Master::PROFILE_REQUEST, OnProfileRequest); + handlers.On(Master::PROFILE_RESULT, OnProfileResult); handlers.On(Master::UGC_MODELS_MADE, OnUgcModelsMade); handlers.On(Master::LIVE_UPDATE_REQUEST, OnLiveUpdateRequest); handlers.On(Master::CHAT_HANDOFF, OnChatHandoff); diff --git a/dNet/dServer.cpp b/dNet/dServer.cpp index d43ce3d1d..0eb0db44f 100644 --- a/dNet/dServer.cpp +++ b/dNet/dServer.cpp @@ -20,6 +20,11 @@ #include "TrafficStats.h" #include "RakNetStatistics.h" #include "master/ServerTraffic.h" +#include "master/Profiling.h" +#include "Profiler.h" + +#include +#include //! Replica Constructor class class ReplicaConstructor : public ReceiveConstructionInterface { @@ -77,6 +82,9 @@ dServer::dServer( mConfig = config; mMasterPassword = masterPassword; mShouldShutdown = lastSignal; + // Frame timing (Profiler.h) counts the scopes of the thread that runs the server: this one + Profiler::SetMainThread(); + ConfigureProfiler(); //Attempt to start our server here: mIsOkay = Startup(); @@ -183,8 +191,16 @@ Packet* dServer::ReceiveFromMaster() { case MessageType::Master::CONFIG_RELOAD: LOG("Reloading settings (changed on the dashboard)"); if (mConfig) mConfig->ReloadConfig(); + ConfigureProfiler(); break; + case MessageType::Master::PROFILE_REQUEST: { + ProfileRequest request; + if (request.Deserialize(inStream)) HandleProfileRequest(request); + else LOG("Dropped a profiling request from master that failed to read"); + break; + } + // When we handle these packets in World instead dServer, we just return the packet's pointer. default: return packet; @@ -394,6 +410,8 @@ void dServer::ReportTraffic() { report.zoneId = mZoneID; report.instanceId = static_cast(mInstanceID); report.report = TrafficStats::Local().Take(TrafficStats::Now()); + report.frames = Profiler::Local().Take(TrafficStats::Now()); + Profiler::Local().CheckSession(Profiler::NowNs()); uint64_t pingSum = 0; std::map seen; @@ -406,3 +424,64 @@ void dServer::ReportTraffic() { if (mTrafficSink) mTrafficSink(report); else if (mMasterPeer && mMasterConnectionActive) MasterPackets::SendToMaster(report, this); } + +void dServer::ConfigureProfiler() { + auto& recorder = Profiler::Local(); + const auto threshold = mConfig ? GeneralUtils::TryParse(mConfig->GetValue("slow_frame_ms")).value_or(250) : 250; + recorder.SetSlowThreshold(threshold); + recorder.SetSlowSink([](const Profiler::Frame& frame) { + // The two phases that took longest + std::array order{}; + for (size_t i = 0; i < order.size(); i++) order[i] = i; + std::sort(order.begin(), order.end(), [&frame](size_t a, size_t b) { return frame.phaseUs[a] > frame.phaseUs[b]; }); + std::string phases; + for (size_t i = 0; i < 2; i++) { + if (frame.phaseUs[order[i]] < 1000) break; + phases += std::string(phases.empty() ? "" : ", ") + Profiler::PhaseName(order[i]) + " " + std::to_string(frame.phaseUs[order[i]] / 1000) + " ms"; + } + LOG("Slow %s: %u ms (%s): %s", frame.implicit ? "work outside the main loop" : "frame", frame.durationUs / 1000, phases.c_str(), frame.Path().c_str()); + }); +} + +void dServer::SendProfileResult(ProfileResult& result) { + if (mProfileSink) mProfileSink(result); + else if (mMasterPeer && mMasterConnectionActive) MasterPackets::SendToMaster(result, this); +} + +void dServer::HandleProfileRequest(const ProfileRequest& request) { + auto& recorder = Profiler::Local(); + const auto now = Profiler::NowNs(); + if (request.stop) { + recorder.StopSession(request.sessionId, now); + return; + } + ProfileResult reply; + reply.sessionId = request.sessionId; + reply.serverType = mServerType; + reply.zoneId = mZoneID; + reply.instanceId = static_cast(mInstanceID); + if (!Profiler::IsMainThread()) { + reply.status = eProfileStatus::FAILED; + reply.error = "Not on the server's main thread"; + } else if (recorder.SessionActive()) { + reply.status = eProfileStatus::FAILED; + reply.error = "Another profiling session is running on this server"; + } else { + const auto serverType = mServerType; + const auto zoneId = mZoneID; + const auto instanceId = static_cast(mInstanceID); + recorder.StartSession(request.sessionId, request.durationMs, now, [this, serverType, zoneId, instanceId](Profiler::Profile&& profile) { + ProfileResult done; + done.sessionId = profile.id; + done.serverType = serverType; + done.zoneId = zoneId; + done.instanceId = instanceId; + done.status = eProfileStatus::DONE; + done.profile = std::move(profile); + SendProfileResult(done); + }); + LOG("Profiling the main loop for %u ms (session %u, from the dashboard)", std::min(request.durationMs, Profiler::Recorder::MAX_SESSION_MS), request.sessionId); + reply.status = eProfileStatus::STARTED; + } + SendProfileResult(reply); +} diff --git a/dNet/dServer.h b/dNet/dServer.h index a1005d895..590a8185d 100644 --- a/dNet/dServer.h +++ b/dNet/dServer.h @@ -12,6 +12,8 @@ class Logger; class dConfig; struct ServerTraffic; +struct ProfileRequest; +struct ProfileResult; enum class eServerDisconnectIdentifiers : uint32_t; enum class ServiceType : uint16_t; @@ -59,6 +61,13 @@ public: using TrafficSink = std::function; void SetTrafficSink(TrafficSink sink) { mTrafficSink = std::move(sink); } + // Where this server's profiling results go (see Profiling.h). By default they are sent to master; master sends its + // own to the dashboard, the dashboard keeps its own. + using ProfileSink = std::function; + void SetProfileSink(ProfileSink sink) { mProfileSink = std::move(sink); } + // Starts or stops a profiling session of this server's main loop (master forwards the dashboard's request) + void HandleProfileRequest(const ProfileRequest& request); + // Names who is on a connection in the traffic report (a world fills in the player's account and character) using ConnectionIdentity = std::function; void SetConnectionIdentity(ConnectionIdentity identity) { mConnectionIdentity = std::move(identity); } @@ -102,6 +111,9 @@ private: // Who mPeer's connections are: other servers on master and chat (the worlds connect to chat), players elsewhere TrafficStats::Peer PeerOfConnections() const; void ReportTraffic(); + void SendProfileResult(ProfileResult& result); + // Main thread, frame timing: the slow frame threshold (slow_frame_ms) and the log line of a slow frame + void ConfigureProfiler(); // Adds the peer's connections to the report's link statistics (changes since the last report) void AddLinkStats(RakPeerInterface* peer, uint64_t peerIndex, ServerTraffic& report, uint64_t& pingSum, std::map& seen); void Shutdown(); @@ -143,6 +155,7 @@ protected: SendObserver mSendObserver; TrafficSink mTrafficSink; + ProfileSink mProfileSink; ConnectionIdentity mConnectionIdentity; // RakNet's per-connection statistics are totals since the connection opened; the last ones seen, for deltas std::map mLinkCounters; diff --git a/resources/sharedconfig.ini b/resources/sharedconfig.ini index 53b5b9b5d..f71072ddd 100644 --- a/resources/sharedconfig.ini +++ b/resources/sharedconfig.ini @@ -10,6 +10,10 @@ log_to_console=1 # 0 or 1, should log debug (developer only) statements to console for debugging, not needed for normal operation log_debug_statements=0 +# A main loop frame (one pass of a server's loop) that takes at least this many milliseconds is logged as one line with +# what took the time, and shown on the dashboard's Performance page. 0 turns it off. See docs/Dashboard.md, Performance. +slow_frame_ms=250 + # The public facing IP address. Can be 'localhost' for locally hosted servers external_ip=localhost