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