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 <noreply@anthropic.com>

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));

dMasterServer/MasterServer.cpp

@@ -1,3 +1,4 @@
+#include "Profiler.h"
 #include "master/PlayerAction.h"
 #include "master/DashboardMessages.h"
 #include <chrono>
@@ -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<pid_t>(-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<LWOMAPID>(request.zoneId), static_cast<LWOINSTANCEID>(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<MessageCaptureData>(Master::MESSAGE_CAPTURE_DATA, ForwardWorldToDashboard<MessageCaptureData>);
 			handlers.On<RequestServerList>(Master::REQUEST_SERVER_LIST, OnRequestServerList);
 			handlers.On<ServerTraffic>(Master::SERVER_TRAFFIC, OnServerTraffic);
+			handlers.On<ProfileRequest>(Master::PROFILE_REQUEST, OnProfileRequest);
+			handlers.On<ProfileResult>(Master::PROFILE_RESULT, OnProfileResult);
 			handlers.On<UgcModelsMade>(Master::UGC_MODELS_MADE, OnUgcModelsMade);
 			handlers.On<LiveUpdateRequest>(Master::LIVE_UPDATE_REQUEST, OnLiveUpdateRequest);
 			handlers.On<ChatHandoff>(Master::CHAT_HANDOFF, OnChatHandoff);

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 <algorithm>
+#include <array>
 
 //! 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<uint32_t>(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<uint64_t, LinkCounters> 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<uint32_t>(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<size_t, Profiler::PHASES> 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<uint32_t>(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<uint32_t>(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);
+}

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(ServerTraffic& report)>;
 	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(ProfileResult& result)>;
+	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(const SystemAddress& sysAddr, TrafficStats::Connection& connection)>;
 	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<uint64_t, LinkCounters>& 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<uint64_t, LinkCounters> mLinkCounters;

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