diff --git a/dCommon/Permissions.cpp b/dCommon/Permissions.cpp index 09804606a..e306ee019 100644 --- a/dCommon/Permissions.cpp +++ b/dCommon/Permissions.cpp @@ -90,6 +90,7 @@ namespace { { "logs_audit", "Logs", "Audit log", "What staff did on the dashboard", 8 }, { "logs_system", "Logs", "Server logs", "Server log files, log search and crash dumps", 8 }, { "health_view", "Logs", "Server health", "Player counts, running worlds, uptime and memory over time", 8 }, + { "profiling_run", "Logs", "Run profiling", "Start a profiling session of a server's main loop on the Performance page (up to a minute; costs the server a little time while it runs)", 8 }, { "network_ips", "Logs", "Network addresses", "See the IP addresses of game and web clients on the Network page (without it they are shown as tokens)", 9 }, { "metrics_view", "Logs", "Prometheus metrics", "Read /metrics (and /api/metrics) with an API token, when metrics_enabled is on", 8 }, diff --git a/dDashboardServer/DashboardServer.cpp b/dDashboardServer/DashboardServer.cpp index f29931ab8..cbd5c70e7 100644 --- a/dDashboardServer/DashboardServer.cpp +++ b/dDashboardServer/DashboardServer.cpp @@ -6,6 +6,8 @@ #include #include +#include "Profiler.h" +#include #include "CDClientDatabase.h" #include "ConfigSync.h" #include "CDClientManager.h" @@ -91,6 +93,8 @@ #include "PrometheusMetrics.h" #include "Traffic.h" #include "master/ServerTraffic.h" +#include "master/Profiling.h" +#include "Performance.h" #include "Background.h" #include "master/DashboardMessages.h" #include "master/DataChanged.h" @@ -342,6 +346,7 @@ namespace { handlers.On(Master::PLAYER_ACTION_RESULT, [](const PlayerActionResult& result, const SystemAddress&) { PlayerActions::HandleResult(result); }); handlers.On(Master::SHUTDOWN_RESPONSE, OnWorldShutDown); handlers.On(Master::SERVER_TRAFFIC, [](const ServerTraffic& report, const SystemAddress&) { Traffic::Ingest(report); }); + handlers.On(Master::PROFILE_RESULT, [](const ProfileResult& result, const SystemAddress&) { Performance::IngestProfile(result); }); handlers.On(Master::LIVE_UPDATE_STATUS, [](const LiveUpdateStatus& status, const SystemAddress&) { LiveUpdateRoutes::HandleStatus(status); }); return handlers; }(); @@ -562,6 +567,7 @@ int main(int argc, char** argv) { Scenery::RegisterRoutes(); PrometheusMetrics::RegisterRoutes(); Traffic::RegisterRoutes(); + Performance::RegisterRoutes(); RegisterPublicRoutes(); RegisterShowcaseRoutes(); FeaturedProperties::RegisterRoutes(); @@ -594,12 +600,19 @@ int main(int argc, char** argv) { const auto elapsedSinceBroadcast = std::chrono::duration_cast(currentTime - lastBroadcast).count(); if (elapsed >= 1000.0f / 60.0f) { + Profiler::FrameScope frame; + std::optional masterScope; + masterScope.emplace("Master packets", Profiler::Phase::PACKETS); Packet* packet = g_Server->ReceiveFromMaster(); while (packet) { - HandleMasterPacket(packet); + { + Profiler::PacketScope scope(packet->data, packet->length); + HandleMasterPacket(packet); + } g_Server->DeallocateMasterPacket(packet); packet = g_Server->ReceiveFromMaster(); } + masterScope.reset(); // Only once the master link is up; sent earlier, the request is dropped and auth/chat look offline if (g_Server->GetIsConnectedToMaster() && std::chrono::steady_clock::now() >= g_NextServerListRequest) { @@ -607,23 +620,24 @@ int main(int argc, char** argv) { g_NextServerListRequest = std::chrono::steady_clock::now() + SERVER_LIST_INTERVAL; } - PlayerActions::Update(); - EmailService::Update(); - Alerts::Update(); - Background::Update(); - ModeratorHelper::Update(); - Scheduler::Update(); - ServerRoutes::Update(); - LiveWorld::Update(); - LiveUpdateRoutes::Update(); - Inspector::Update(); - Announcements::Update(); - EventsCalendar::Update(); - LiveEventRoutes::Update(); - ChallengeRoutes::Update(); - InstanceLoad::Update(); - Traffic::Update(); - ApiKeyService::Update(); + { Profiler::Scope scope("PlayerActions::Update"); PlayerActions::Update(); } + { Profiler::Scope scope("EmailService::Update"); EmailService::Update(); } + { Profiler::Scope scope("Alerts::Update"); Alerts::Update(); } + { Profiler::Scope scope("Background::Update"); Background::Update(); } + { Profiler::Scope scope("ModeratorHelper::Update"); ModeratorHelper::Update(); } + { Profiler::Scope scope("Scheduler::Update"); Scheduler::Update(); } + { Profiler::Scope scope("ServerRoutes::Update"); ServerRoutes::Update(); } + { Profiler::Scope scope("LiveWorld::Update"); LiveWorld::Update(); } + { Profiler::Scope scope("LiveUpdateRoutes::Update"); LiveUpdateRoutes::Update(); } + { Profiler::Scope scope("Inspector::Update"); Inspector::Update(); } + { Profiler::Scope scope("Announcements::Update"); Announcements::Update(); } + { Profiler::Scope scope("EventsCalendar::Update"); EventsCalendar::Update(); } + { Profiler::Scope scope("LiveEventRoutes::Update"); LiveEventRoutes::Update(); } + { Profiler::Scope scope("ChallengeRoutes::Update"); ChallengeRoutes::Update(); } + { Profiler::Scope scope("InstanceLoad::Update"); InstanceLoad::Update(); } + { Profiler::Scope scope("Traffic::Update"); Traffic::Update(); } + { Profiler::Scope scope("Performance::Update"); Performance::Update(); } + { Profiler::Scope scope("ApiKeyService::Update"); ApiKeyService::Update(); } // Broadcast dashboard updates periodically if (elapsedSinceBroadcast >= broadcastInterval) { diff --git a/dDashboardServer/routes/CMakeLists.txt b/dDashboardServer/routes/CMakeLists.txt index e4680f3db..71fae6f53 100644 --- a/dDashboardServer/routes/CMakeLists.txt +++ b/dDashboardServer/routes/CMakeLists.txt @@ -36,6 +36,8 @@ set(DASHBOARDROUTES_SOURCES "Traffic.cpp" "TrafficHistory.cpp" "NetworkView.cpp" + "PerfHistory.cpp" + "Performance.cpp" "LeaderboardRoutes.cpp" "VanityRoutes.cpp" "ChatRoutes.cpp" diff --git a/dDashboardServer/routes/DashboardRoutes.cpp b/dDashboardServer/routes/DashboardRoutes.cpp index b27e7c973..5b3e91f9f 100644 --- a/dDashboardServer/routes/DashboardRoutes.cpp +++ b/dDashboardServer/routes/DashboardRoutes.cpp @@ -447,6 +447,7 @@ void RegisterDashboardRoutes() { SimplePage("/health", Perm("health_view"), "health.jinja2", "health", "Player counts, worlds, uptime and memory over time; crash dumps"); SimplePage("/diagnostics", Perm("health_view"), "diagnostics.jinja2", "diagnostics", "Packets, bytes and HTTP requests per second of every server"); SimplePage("/network", Perm("health_view"), "network.jinja2", "network", "Live diagram of the traffic between players, the servers and web clients, and the traffic of each connection"); + SimplePage("/performance", Perm("health_view"), "performance.jinja2", "performance", "Main loop frame times and phases of every server, slow frames with their scopes, and profiling sessions with a flame graph"); SimplePage("/players", Perm("players_view"), "players.jinja2", "players", "Who is online, with kick, rescue and teleport"); SimplePage("/backups", Perm("backups"), "backups.jinja2", "backups", "Database backups"); // The GM level tabs need permissions_manage, the grants tab grants_manage diff --git a/dDashboardServer/routes/PerfHistory.cpp b/dDashboardServer/routes/PerfHistory.cpp new file mode 100644 index 000000000..2e7f0b3b9 --- /dev/null +++ b/dDashboardServer/routes/PerfHistory.cpp @@ -0,0 +1,258 @@ +#include "PerfHistory.h" + +#include +#include +#include +#include + +#include "ServiceType.h" +#include "TrafficStats.h" + +namespace { + double Ms(uint64_t microseconds) { + return std::round(static_cast(microseconds) / 10.0) / 100.0; + } + + double Round2(double value) { + return std::round(value * 100.0) / 100.0; + } + + std::string LabelOf(const Profiler::Node& node, const PerfHistory::Label& label) { + return label ? label(node) : Profiler::DefaultLabel(node); + } + + // The seconds of a server from `from` (inclusive) to `to` (exclusive) + template + void ForSeconds(const PerfHistory::Server& server, int64_t from, int64_t to, Fn&& fn) { + auto it = std::lower_bound(server.seconds.begin(), server.seconds.end(), from, [](const Profiler::Second& s, int64_t t) { return s.time < t; }); + for (; it != server.seconds.end() && it->time < to; ++it) fn(*it); + } +} + +bool PerfHistory::ParseKey(const std::string& key, uint16_t& serviceType, uint32_t& zoneId, uint32_t& instanceId) { + zoneId = 0; + instanceId = 0; + if (key == "master") serviceType = static_cast(ServiceType::MASTER); + else if (key == "auth") serviceType = static_cast(ServiceType::AUTH); + else if (key == "chat") serviceType = static_cast(ServiceType::CHAT); + else if (key == "dashboard") serviceType = static_cast(ServiceType::DASHBOARD); + else if (key == "ugc") serviceType = static_cast(ServiceType::UGC); + else if (key.starts_with("world:")) { + const auto colon = key.find(':', 6); + if (colon == std::string::npos) return false; + const auto zone = key.substr(6, colon - 6), instance = key.substr(colon + 1); + const auto digits = [](const std::string& s) { return !s.empty() && s.size() <= 9 && std::all_of(s.begin(), s.end(), [](char c) { return c >= '0' && c <= '9'; }); }; + if (!digits(zone) || !digits(instance)) return false; + serviceType = static_cast(ServiceType::WORLD); + zoneId = static_cast(std::stoul(zone)); + instanceId = static_cast(std::stoul(instance)); + } else { + return false; + } + return true; +} + +void PerfHistory::Ingest(const std::string& key, const Profiler::Report& report, int64_t now) { + if (!report.present) return; + auto [it, added] = m_Servers.try_emplace(key); + auto& server = it->second; + if (added) server.key = key; + server.lastSeen = now; + server.slowThresholdMs = report.slowThresholdMs; + + for (const auto& second : report.seconds) { + if (server.seconds.empty() || server.seconds.back().time < second.time) { + server.seconds.push_back(second); + continue; + } + // Late or repeated: added to the one it belongs to + auto at = std::lower_bound(server.seconds.begin(), server.seconds.end(), second.time, [](const Profiler::Second& s, int64_t t) { return s.time < t; }); + if (at != server.seconds.end() && at->time == second.time) at->Merge(second); + else server.seconds.insert(at, second); + } + if (!report.messages.empty()) server.messages.emplace_back(now, report.messages); + for (const auto& frame : report.worst) { + server.worst.push_back(frame); + if (server.worst.size() > WORST_KEPT) { + // The shortest one goes + const auto shortest = std::min_element(server.worst.begin(), server.worst.end(), [](const Profiler::Frame& a, const Profiler::Frame& b) { return a.durationUs < b.durationUs; }); + server.worst.erase(shortest); + } + } + for (const auto& frame : report.slow) { + m_Slow.push_back({ key, frame }); + if (m_Slow.size() > SLOW_KEPT) m_Slow.pop_front(); + } +} + +void PerfHistory::Forget(int64_t now) { + for (auto it = m_Servers.begin(); it != m_Servers.end();) { + auto& server = it->second; + if (now - server.lastSeen > FORGET_AFTER) { + it = m_Servers.erase(it); + continue; + } + while (!server.seconds.empty() && server.seconds.front().time < now - SECONDS_KEPT) server.seconds.pop_front(); + while (!server.messages.empty() && server.messages.front().first < now - RECENT_SECONDS) server.messages.pop_front(); + std::erase_if(server.worst, [now](const Profiler::Frame& frame) { return frame.timeMs / 1000 < now - RECENT_SECONDS; }); + ++it; + } +} + +nlohmann::json PerfHistory::ServersJson(int64_t now, int64_t span, int64_t onlineSeconds, const ServerLabel& label) const { + nlohmann::json out = nlohmann::json::array(); + for (const auto& [key, server] : m_Servers) { + uint64_t ticks = 0, totalUs = 0; + uint32_t maxUs = 0; + int64_t covered = 0; + TrafficStats::Histogram frames; + ForSeconds(server, now - span, now, [&](const Profiler::Second& s) { + covered++; + ticks += s.ticks; + totalUs += s.totalUs; + maxUs = std::max(maxUs, s.maxUs); + frames.Merge(s.frames); + }); + size_t slow = 0; + for (const auto& entry : m_Slow) if (entry.server == key && entry.frame.timeMs / 1000 >= now - span) slow++; + nlohmann::json row = { + {"key", key}, {"label", label ? label(key) : key}, {"online", now - server.lastSeen <= onlineSeconds}, {"last_seen", server.lastSeen}, + {"slow_threshold_ms", server.slowThresholdMs}, {"slow", slow}, {"seconds", covered}, + {"ticks_per_second", covered ? Round2(static_cast(ticks) / static_cast(covered)) : 0.0}, + {"avg_ms", ticks ? nlohmann::json(Ms(totalUs / ticks)) : nlohmann::json(nullptr)}, + {"p95_ms", ticks ? nlohmann::json(Ms(frames.Percentile(0.95))) : nlohmann::json(nullptr)}, + {"max_ms", ticks ? nlohmann::json(Ms(maxUs)) : nlohmann::json(nullptr)}, + {"busy_percent", covered ? Round2(static_cast(totalUs) / (static_cast(covered) * 1e4)) : 0.0}, + }; + out.push_back(std::move(row)); + } + std::stable_sort(out.begin(), out.end(), [](const nlohmann::json& a, const nlohmann::json& b) { return a["busy_percent"].get() > b["busy_percent"].get(); }); + return out; +} + +nlohmann::json PerfHistory::Series(const std::string& key, int64_t from, int64_t to, int64_t step) const { + step = std::max(step, 1); + const auto count = static_cast(std::max((to - from) / step, 0)); + nlohmann::json times = nlohmann::json::array(), ticks = nlohmann::json::array(), avg = nlohmann::json::array(), p95 = nlohmann::json::array(), + max = nlohmann::json::array(); + std::vector phases(Profiler::PHASES, nlohmann::json::array()); + const auto it = m_Servers.find(key); + for (size_t i = 0; i < count; i++) { + const int64_t start = from + static_cast(i) * step; + times.push_back(start); + Profiler::Second sum; + int64_t covered = 0; + if (it != m_Servers.end()) { + ForSeconds(it->second, start, start + step, [&](const Profiler::Second& s) { + covered++; + sum.Merge(s); + }); + } + // Not reported: gaps. Reported without frames (a stuck loop): no frames. + if (!covered) { + ticks.push_back(nullptr); + avg.push_back(nullptr); + p95.push_back(nullptr); + max.push_back(nullptr); + for (auto& phase : phases) phase.push_back(nullptr); + continue; + } + ticks.push_back(Round2(static_cast(sum.ticks) / static_cast(covered))); + avg.push_back(sum.ticks ? nlohmann::json(Ms(sum.totalUs / sum.ticks)) : nlohmann::json(nullptr)); + p95.push_back(sum.ticks ? nlohmann::json(Ms(sum.frames.Percentile(0.95))) : nlohmann::json(nullptr)); + max.push_back(sum.ticks ? nlohmann::json(Ms(sum.maxUs)) : nlohmann::json(nullptr)); + for (size_t p = 0; p < Profiler::PHASES; p++) phases[p].push_back(Ms(sum.phaseUs[p] / static_cast(covered))); + } + nlohmann::json phaseJson = nlohmann::json::object(); + for (size_t p = 0; p < Profiler::PHASES; p++) phaseJson[Profiler::PhaseName(p)] = std::move(phases[p]); + return { {"key", key}, {"from", from}, {"to", to}, {"step", step}, {"times", times}, {"ticks_per_second", ticks}, {"avg_ms", avg}, {"p95_ms", p95}, + {"max_ms", max}, {"phases_ms_per_second", phaseJson}, {"slow_threshold_ms", it != m_Servers.end() ? it->second.slowThresholdMs : 0} }; +} + +nlohmann::json PerfHistory::FrameJson(const Profiler::Frame& frame, const Label& label) { + nlohmann::json phases = nlohmann::json::object(); + for (size_t p = 0; p < Profiler::PHASES; p++) { + if (frame.phaseUs[p]) phases[Profiler::PhaseName(p)] = Ms(frame.phaseUs[p]); + } + nlohmann::json scopes = nlohmann::json::array(); + for (size_t i = 0; i < frame.scopes.size(); i++) { + const auto& node = frame.scopes[i]; + uint64_t children = 0; + for (size_t j = i + 1; j < frame.scopes.size() && frame.scopes[j].depth > node.depth; j++) { + if (frame.scopes[j].depth == node.depth + 1) children += frame.scopes[j].totalUs; + } + scopes.push_back({ {"label", LabelOf(node, label)}, {"name", node.name}, {"arg", node.arg}, {"depth", node.depth}, {"count", node.count}, + {"total_ms", Ms(node.totalUs)}, {"self_ms", Ms(node.totalUs > children ? node.totalUs - children : 0)}, {"start_ms", Ms(node.startUs)} }); + } + return { {"time_ms", frame.timeMs}, {"duration_ms", Ms(frame.durationUs)}, {"implicit", frame.implicit}, {"phases", phases}, + {"path", frame.Path([&label](const Profiler::Node& node) { return LabelOf(node, label); })}, {"scopes", scopes} }; +} + +nlohmann::json PerfHistory::Worst(const std::string& key, int64_t since, size_t limit, const Label& label) const { + nlohmann::json out = nlohmann::json::array(); + const auto it = m_Servers.find(key); + if (it == m_Servers.end()) return out; + std::vector frames; + for (const auto& frame : it->second.worst) if (frame.timeMs / 1000 >= since) frames.push_back(&frame); + std::stable_sort(frames.begin(), frames.end(), [](const Profiler::Frame* a, const Profiler::Frame* b) { return a->durationUs > b->durationUs; }); + if (frames.size() > limit) frames.resize(limit); + for (const auto* frame : frames) out.push_back(FrameJson(*frame, label)); + return out; +} + +nlohmann::json PerfHistory::Messages(const std::string& key, int64_t since, size_t limit, const MessageNames& names) const { + nlohmann::json out = nlohmann::json::array(); + const auto it = m_Servers.find(key); + if (it == m_Servers.end()) return out; + std::unordered_map merged; + for (const auto& [time, messages] : it->second.messages) { + if (time < since) continue; + for (const auto& m : messages) { + auto& sum = merged[m.key]; + sum.key = m.key; + sum.count += m.count; + sum.totalUs += m.totalUs; + sum.maxUs = std::max(sum.maxUs, m.maxUs); + } + } + std::vector list; + for (const auto& [_, m] : merged) list.push_back(m); + std::sort(list.begin(), list.end(), [](const Profiler::MessageTime& a, const Profiler::MessageTime& b) { return a.totalUs != b.totalUs ? a.totalUs > b.totalUs : a.key < b.key; }); + if (list.size() > limit) list.resize(limit); + for (const auto& m : list) { + nlohmann::json row = names ? names(m.key) : nlohmann::json::object(); + row["count"] = m.count; + row["total_ms"] = Ms(m.totalUs); + row["avg_ms"] = m.count ? Ms(m.totalUs / m.count) : 0.0; + row["max_ms"] = Ms(m.maxUs); + out.push_back(std::move(row)); + } + return out; +} + +nlohmann::json PerfHistory::SlowJson(const std::string& key, const Label& label, const ServerLabel& serverLabel) const { + nlohmann::json out = nlohmann::json::array(); + for (auto it = m_Slow.rbegin(); it != m_Slow.rend(); ++it) { + if (!key.empty() && it->server != key) continue; + auto frame = FrameJson(it->frame, label); + frame["server"] = it->server; + frame["server_label"] = serverLabel ? serverLabel(it->server) : it->server; + out.push_back(std::move(frame)); + } + return out; +} + +nlohmann::json PerfHistory::ProfileJson(const Profiler::Profile& profile, const Label& label) { + nlohmann::json nodes = nlohmann::json::array(); + for (size_t i = 0; i < profile.nodes.size(); i++) { + const auto& node = profile.nodes[i]; + uint64_t children = 0; + for (size_t j = i + 1; j < profile.nodes.size() && profile.nodes[j].depth > node.depth; j++) { + if (profile.nodes[j].depth == node.depth + 1) children += profile.nodes[j].totalUs; + } + nodes.push_back({ {"label", LabelOf(node, label)}, {"depth", node.depth}, {"count", node.count}, {"total_us", node.totalUs}, + {"self_us", node.totalUs > children ? node.totalUs - children : 0} }); + } + return { {"duration_ms", profile.durationMs}, {"frames", profile.frames}, {"total_ms", Ms(profile.totalUs)}, {"truncated", profile.truncated}, + {"nodes", nodes}, {"folded", Profiler::Folded(profile.nodes, [&label](const Profiler::Node& node) { return LabelOf(node, label); })} }; +} diff --git a/dDashboardServer/routes/PerfHistory.h b/dDashboardServer/routes/PerfHistory.h new file mode 100644 index 000000000..7c4f46ecb --- /dev/null +++ b/dDashboardServer/routes/PerfHistory.h @@ -0,0 +1,81 @@ +#pragma once + +#include +#include +#include +#include +#include +#include +#include + +#include "Profiler.h" +#include "json.hpp" + +/** + * Every server's frame timing (the frames section of its traffic reports, see Profiler.h), kept by the dashboard in + * memory: the last hour at one second, the worst frames and packet handling times of the last minutes, and the last + * slow frames of all servers. Pure (no database, network or clock), so it is unit tested; Performance.cpp feeds it. + */ +class PerfHistory { +public: + static constexpr int64_t SECONDS_KEPT = 3600; + static constexpr int64_t RECENT_SECONDS = 600; // worst frames and packet times kept + static constexpr size_t WORST_KEPT = 40; // per server + static constexpr size_t SLOW_KEPT = 50; // all servers together + static constexpr int64_t FORGET_AFTER = 86400; // a server silent this long is dropped + + struct Server { + std::string key; + int64_t lastSeen{}; + uint32_t slowThresholdMs{}; + std::deque seconds; // oldest first + std::deque>> messages; // per report + std::deque worst; // oldest first + }; + + struct SlowFrame { + std::string server; + Profiler::Frame frame; + }; + + // Names a scope ("Packet GAME_MSG RequestUse", "Component INVENTORY"); DefaultLabel when not set + using Label = std::function; + // Names a packet type: {service, packet, game_message} + using MessageNames = std::function; + // The label of a server key ("World 1200 Nimbus Station #3") + using ServerLabel = std::function; + + void Ingest(const std::string& key, const Profiler::Report& report, int64_t now); + void Forget(int64_t now); + + const std::map& Servers() const { return m_Servers; } + const std::deque& Slow() const { return m_Slow; } + + // Each server over the last `span` seconds: frames per second, average, p95 and longest frame, how busy its main + // loop was, its slow frames; busiest first + nlohmann::json ServersJson(int64_t now, int64_t span, int64_t onlineSeconds, const ServerLabel& label) const; + + // One server's seconds from `from` to `to` in steps of `step`: frames per second, average / p95 / longest frame + // (ms), and each phase's milliseconds per second + nlohmann::json Series(const std::string& key, int64_t from, int64_t to, int64_t step) const; + + // One server's longest frames since `since`, longest first + nlohmann::json Worst(const std::string& key, int64_t since, size_t limit, const Label& label) const; + + // One server's packet types by handling time since `since`, longest total first + nlohmann::json Messages(const std::string& key, int64_t since, size_t limit, const MessageNames& names) const; + + // The slow frames of every server (or one), newest first + nlohmann::json SlowJson(const std::string& key, const Label& label, const ServerLabel& serverLabel) const; + + static nlohmann::json FrameJson(const Profiler::Frame& frame, const Label& label); + // A profiling session's tree for the flame graph, and its folded stacks + static nlohmann::json ProfileJson(const Profiler::Profile& profile, const Label& label); + + // "world:1200:3" -> (WORLD, 1200, 3); false for keys that aren't a server's + static bool ParseKey(const std::string& key, uint16_t& serviceType, uint32_t& zoneId, uint32_t& instanceId); + +private: + std::map m_Servers; + std::deque m_Slow; // oldest first +}; diff --git a/dDashboardServer/routes/Performance.cpp b/dDashboardServer/routes/Performance.cpp new file mode 100644 index 000000000..f98952597 --- /dev/null +++ b/dDashboardServer/routes/Performance.cpp @@ -0,0 +1,247 @@ +#include "Performance.h" + +#include +#include +#include +#include + +#include "Game.h" +#include "GeneralUtils.h" +#include "Logger.h" +#include "MasterPackets.h" +#include "PerfHistory.h" +#include "Permissions.h" +#include "RouteUtils.h" +#include "ServiceType.h" +#include "Traffic.h" +#include "TrafficHistory.h" +#include "TrafficStats.h" +#include "Web.h" +#include "dServer.h" +#include "eHTTPMethod.h" +#include "eReplicaComponentType.h" +#include "magic_enum.hpp" +#include "master/Profiling.h" + +using namespace RouteUtils; + +namespace { + constexpr const char* VIEW = "health_view"; + constexpr const char* RUN = "profiling_run"; + constexpr int64_t ONLINE_SECONDS = 20; + constexpr uint32_t MAX_SECONDS = Profiler::Recorder::MAX_SESSION_MS / 1000; + constexpr size_t SESSIONS_KEPT = 20; + constexpr auto ANSWER_SLACK = std::chrono::seconds(20); // a session that hasn't answered this long after its end failed + + PerfHistory g_History; + std::chrono::steady_clock::time_point g_NextForget{}; + + struct Session { + uint32_t id{}; + std::string server; + std::string by; + int64_t started{}; + uint32_t seconds{}; + std::string status; // requested, running, done, failed + std::string error; + std::optional profile; + std::chrono::steady_clock::time_point deadline; + }; + std::deque g_Sessions; // oldest first + uint32_t g_NextId = static_cast(TrafficStats::Now() & 0xFFFFF) << 8; + + // Scope names for people: packets and components by name + std::string NodeLabel(const Profiler::Node& node) { + if (node.name == Profiler::PACKET) { + const auto names = Traffic::MessageNames(node.arg); + const auto gameMessage = names.value("game_message", ""); + return "Packet " + (gameMessage.empty() ? names.value("service", "") + " " + names.value("packet", "") : gameMessage); + } + if (node.name == Profiler::COMPONENT) { + const auto name = magic_enum::enum_name(static_cast(node.arg)); + return "Component " + (name.empty() ? std::to_string(node.arg) : std::string(name)); + } + return Profiler::DefaultLabel(node); + } + + Session* FindSession(uint32_t id) { + for (auto& session : g_Sessions) if (session.id == id) return &session; + return nullptr; + } + + nlohmann::json SessionJson(const Session& session, bool withProfile) { + nlohmann::json out = { {"id", session.id}, {"server", session.server}, {"server_label", Traffic::Label(session.server)}, {"by", session.by}, + {"started", session.started}, {"seconds", session.seconds}, {"status", session.status}, {"error", session.error} }; + if (session.profile) { + out["frames"] = session.profile->frames; + out["duration_ms"] = session.profile->durationMs; + out["total_ms"] = static_cast(session.profile->totalUs) / 1000.0; + if (withProfile) out["profile"] = PerfHistory::ProfileJson(*session.profile, NodeLabel); + } + return out; + } + + void Send(const ProfileRequest& request) { + // The dashboard profiles itself; everything else goes through master + if (request.serverType == ServiceType::DASHBOARD) { + if (Game::server) Game::server->HandleProfileRequest(request); + return; + } + MasterPackets::SendToMaster(request); + } + + nlohmann::json Overview(const std::string& requested, const std::string& range, int64_t now) { + auto servers = g_History.ServersJson(now, 300, ONLINE_SECONDS, Traffic::Label); + std::string key = requested; + if (key.empty() || !g_History.Servers().contains(key)) { + // The busiest server online + key.clear(); + for (const auto& row : servers) { + if (row["online"].get()) { key = row["key"].get(); break; } + } + } + const int64_t span = range == "1h" ? 3600 : 300, step = range == "1h" ? 10 : 1; + const int64_t to = now - (now % step), from = to - span; + nlohmann::json out = { {"range", range == "1h" ? "1h" : "5m"}, {"servers", servers}, {"server", key} }; + if (!key.empty()) { + out["server_label"] = Traffic::Label(key); + out["series"] = g_History.Series(key, from, to, step); + out["worst"] = g_History.Worst(key, now - PerfHistory::RECENT_SECONDS, 10, NodeLabel); + out["messages"] = g_History.Messages(key, now - 300, 15, Traffic::MessageNames); + } + return out; + } +} + +namespace Performance { + void Ingest(const std::string& serverKey, const Profiler::Report& frames) { + g_History.Ingest(serverKey, frames, TrafficStats::Now()); + } + + void IngestProfile(const ProfileResult& result) { + auto* session = FindSession(result.sessionId); + if (!session) return; + switch (result.status) { + case eProfileStatus::STARTED: + if (session->status == "requested") session->status = "running"; + break; + case eProfileStatus::DONE: + session->status = "done"; + session->profile = result.profile; + LOG("Profiling session %u of %s finished: %u frames", session->id, session->server.c_str(), result.profile.frames); + break; + case eProfileStatus::FAILED: + session->status = "failed"; + session->error = result.error; + break; + } + } + + void Update() { + const auto now = std::chrono::steady_clock::now(); + if (now >= g_NextForget) { + g_NextForget = now + std::chrono::seconds(15); + g_History.Forget(TrafficStats::Now()); + } + for (auto& session : g_Sessions) { + if ((session.status == "requested" || session.status == "running") && now >= session.deadline) { + session.status = "failed"; + session.error = "The server didn't answer"; + } + } + } + + void RegisterRoutes() { + // The dashboard's own results stay here + if (Game::server) Game::server->SetProfileSink([](ProfileResult& result) { IngestProfile(result); }); + + Route(eHTTPMethod::GET, "/api/diagnostics/performance", Perm(VIEW), + "Main loop frame timing. Query: ?server=world:1200:3 (default: the busiest server online) and ?range=5m|1h. Every server's frames per second, average, p95 and longest frame and how busy its loop was over 5 minutes; for the server: frame times and each phase's milliseconds per second, its longest frames of the last 10 minutes with their scopes, and the packet types that took longest to handle", + [](HTTPReply& reply, const HTTPContext& context) { + const auto server = QueryValue(context.queryString, "server"); + if (server.size() > 64) return JsonError(reply, eHTTPStatusCode::BAD_REQUEST, "server is too long"); + auto out = Overview(server, QueryValue(context.queryString, "range"), TrafficStats::Now()); + out["can_profile"] = Can(context, RUN); + JsonSuccess(reply, out); + }); + + Route(eHTTPMethod::GET, "/api/diagnostics/performance/slow", Perm(VIEW), + "The last 50 slow frames of every server (over slow_frame_ms), newest first, with their phases and heaviest scopes. Query: ?server= for one server", + [](HTTPReply& reply, const HTTPContext& context) { + const auto server = QueryValue(context.queryString, "server"); + JsonSuccess(reply, { {"frames", g_History.SlowJson(server, NodeLabel, Traffic::Label)} }); + }); + + Route(eHTTPMethod::GET, "/api/diagnostics/performance/profiles", Perm(VIEW), + "The last profiling sessions, newest first (without their trees)", + [](HTTPReply& reply, const HTTPContext& context) { + nlohmann::json sessions = nlohmann::json::array(); + for (auto it = g_Sessions.rbegin(); it != g_Sessions.rend(); ++it) sessions.push_back(SessionJson(*it, false)); + JsonSuccess(reply, { {"sessions", sessions}, {"can_profile", Can(context, RUN)}, {"max_seconds", MAX_SECONDS} }); + }); + + Route(eHTTPMethod::GET, "/api/diagnostics/performance/profiles/:id", Perm(VIEW), + "One profiling session with its merged scope tree (nodes in pre-order with depth, total and own microseconds) and its folded stacks", + [](HTTPReply& reply, const HTTPContext& context) { + const auto id = PathId(context.path, 4); + const auto* session = id ? FindSession(*id) : nullptr; + if (!session) return JsonError(reply, eHTTPStatusCode::NOT_FOUND, "No such session"); + JsonSuccess(reply, { {"session", SessionJson(*session, true)} }); + }); + + Route(eHTTPMethod::POST, "/api/diagnostics/performance/profiles", Perm(RUN), + "Start a profiling session: {server: \"world:1200:3\", seconds: 1-60}. The server merges its main loop's scopes for that long; poll the session for the result", + [](HTTPReply& reply, const HTTPContext& context) { + const auto body = ParseBody(context); + if (!body || !body->is_object()) return JsonError(reply, eHTTPStatusCode::BAD_REQUEST, "Invalid JSON"); + const auto server = body->value("server", ""); + uint16_t type{}; + uint32_t zoneId{}, instanceId{}; + if (!PerfHistory::ParseKey(server, type, zoneId, instanceId)) return JsonError(reply, eHTTPStatusCode::BAD_REQUEST, "Unknown server"); + const auto seconds = body->contains("seconds") && (*body)["seconds"].is_number_integer() ? (*body)["seconds"].get() : 10; + if (seconds < 1 || seconds > MAX_SECONDS) return JsonError(reply, eHTTPStatusCode::BAD_REQUEST, "seconds must be 1 to " + std::to_string(MAX_SECONDS)); + for (const auto& session : g_Sessions) { + if (session.server == server && (session.status == "requested" || session.status == "running")) { + return JsonError(reply, eHTTPStatusCode::CONFLICT, "A session of that server is running"); + } + } + Session session; + session.id = ++g_NextId; + session.server = server; + session.by = context.authenticatedUser; + session.started = TrafficStats::Now(); + session.seconds = static_cast(seconds); + session.status = "requested"; + session.deadline = std::chrono::steady_clock::now() + std::chrono::seconds(seconds) + ANSWER_SLACK; + g_Sessions.push_back(session); + if (g_Sessions.size() > SESSIONS_KEPT) g_Sessions.pop_front(); + + ProfileRequest request; + request.sessionId = session.id; + request.serverType = static_cast(type); + request.zoneId = zoneId; + request.instanceId = instanceId; + request.durationMs = static_cast(seconds) * 1000; + Send(request); + Audit(context, "profile_server", "Profiled " + Traffic::Label(server) + " for " + std::to_string(seconds) + " s"); + JsonSuccess(reply, { {"session", SessionJson(session, false)} }); + }); + + Route(eHTTPMethod::POST, "/api/diagnostics/performance/profiles/:id/stop", Perm(RUN), + "End a running profiling session early; the server sends what it has", + [](HTTPReply& reply, const HTTPContext& context) { + const auto id = PathId(context.path, 4); + const auto* session = id ? FindSession(*id) : nullptr; + if (!session) return JsonError(reply, eHTTPStatusCode::NOT_FOUND, "No such session"); + if (session->status != "requested" && session->status != "running") return JsonError(reply, eHTTPStatusCode::CONFLICT, "The session isn't running"); + ProfileRequest request; + uint16_t type{}; + PerfHistory::ParseKey(session->server, type, request.zoneId, request.instanceId); + request.serverType = static_cast(type); + request.sessionId = session->id; + request.stop = true; + Send(request); + JsonSuccess(reply); + }); + } +} diff --git a/dDashboardServer/routes/Performance.h b/dDashboardServer/routes/Performance.h new file mode 100644 index 000000000..3e2e84593 --- /dev/null +++ b/dDashboardServer/routes/Performance.h @@ -0,0 +1,25 @@ +#pragma once + +#include + +#include "Profiler.h" + +struct ProfileResult; + +/** + * The Performance page (docs/Dashboard.md, "Performance"): every server's main loop frame times and phases, its worst + * and slow frames, and profiling sessions with a flame graph. Frame timing comes with the traffic reports; sessions go + * out as PROFILE_REQUEST through master and come back as PROFILE_RESULT. + */ +namespace Performance { + void RegisterRoutes(); + + // A traffic report's frames section (Traffic::Ingest passes it on) + void Ingest(const std::string& serverKey, const Profiler::Report& frames); + + // PROFILE_RESULT from a server (via master), or the dashboard's own + void IngestProfile(const ProfileResult& result); + + // Main loop: forget old seconds, give up on sessions that never answered + void Update(); +} diff --git a/dDashboardServer/routes/Traffic.cpp b/dDashboardServer/routes/Traffic.cpp index 7d3c5d608..a643bdc0d 100644 --- a/dDashboardServer/routes/Traffic.cpp +++ b/dDashboardServer/routes/Traffic.cpp @@ -1,6 +1,7 @@ #include "Traffic.h" #include +#include #include #include #include @@ -14,6 +15,7 @@ #include "MessageIdentifiers.h" #include "MetricsFormat.h" #include "NetworkView.h" +#include "Performance.h" #include "Permissions.h" #include "RouteUtils.h" #include "GameText.h" @@ -344,6 +346,21 @@ namespace Traffic { void Ingest(const ServerTraffic& report) { g_History.Ingest(static_cast(report.serverType), report.zoneId, report.instanceId, report.report, TrafficStats::Now()); g_Changed = true; + Performance::Ingest(TrafficHistory::KeyFor(static_cast(report.serverType), report.zoneId, report.instanceId), report.frames); + } + + std::string Label(const std::string& key) { + const auto& servers = g_History.Servers(); + const auto it = servers.find(key); + if (it != servers.end()) return LabelOf(it->second); + if (key.starts_with("world:")) return "World " + key.substr(6); + if (!key.empty()) return std::string(1, static_cast(std::toupper(static_cast(key[0])))) + key.substr(1); + return key; + } + + nlohmann::json MessageNames(uint64_t packedKey) { + const auto names = NamesOf(TrafficStats::MessageKey::Unpack(packedKey)); + return { {"service", names.service}, {"packet", names.packet}, {"game_message", names.gameMessage} }; } void Update() { diff --git a/dDashboardServer/routes/Traffic.h b/dDashboardServer/routes/Traffic.h index 51aed38a7..f9d0388ec 100644 --- a/dDashboardServer/routes/Traffic.h +++ b/dDashboardServer/routes/Traffic.h @@ -22,6 +22,12 @@ namespace Traffic { // Main thread: one server's last report ("ugc", "chat", ...): {key, label, online, last_seen, link, gauges} nlohmann::json Server(const std::string& key); + // "World 1200 Nimbus Station #3" for world:1200:3, "Master" for master, ... + std::string Label(const std::string& key); + + // A packet type's names (MessageKey::Packed): {service, packet, game_message} + nlohmann::json MessageNames(uint64_t packedKey); + // Counters for /metrics void AddMetrics(MetricsFormat::Writer& w); } diff --git a/dDashboardServer/static/js/perf-charts.js b/dDashboardServer/static/js/perf-charts.js new file mode 100644 index 000000000..bdc58685c --- /dev/null +++ b/dDashboardServer/static/js/perf-charts.js @@ -0,0 +1,261 @@ +/** + * The Performance page's drawing: the frame time and phase charts, the flame graph of a profiling session and the + * timeline of a slow frame. The layouts are plain functions (tested with node: tests/dWebTests/perf-charts.test.mjs); + * the draw functions put SVG into the page. + * + * Scope trees come in pre-order with a depth, as the server sends them (Profiler.h): [{label, depth, total_us|total_ms, + * ...}, ...], root first. + */ +(function (root) { + 'use strict'; + + // Phases drawn in the stacked chart, in a fixed order with a fixed colour each; the rest are drawn as "other" + var PHASES = [ + { key: 'packets', label: 'Packets', color: 'var(--tr-1)' }, + { key: 'entities', label: 'Entities', color: 'var(--tr-2)' }, + { key: 'physics', label: 'Physics', color: 'var(--tr-3)' }, + { key: 'web', label: 'Web requests', color: 'var(--tr-3)' }, // only the dashboard and UGC server, which have no physics + { key: 'replica', label: 'Replica', color: 'var(--tr-4)' }, + { key: 'database', label: 'Database', color: 'var(--tr-5)' }, + { key: 'cdclient', label: 'CDClient', color: 'var(--tr-6)' }, + ]; + var OTHER_PHASES = ['other', 'scripts', 'log_flush']; + + function num(v) { return typeof v === 'number' && isFinite(v) ? v : 0; } + + // The index of each node's parent (-1 for the root) + function parents(nodes) { + var out = [], stack = []; + for (var i = 0; i < nodes.length; i++) { + var d = nodes[i].depth; + stack.length = d; + out.push(d > 0 && stack.length ? stack[d - 1] : -1); + stack[d] = i; + } + return out; + } + + /** + * Flame graph rectangles: x and w as fractions of the focused node's width (its ancestors span the whole width), + * row = depth. Children are laid out left to right in the order they come. Nodes narrower than minWidth are left out. + */ + function flameLayout(nodes, focus, minWidth) { + focus = focus || 0; + minWidth = minWidth || 0; + if (!nodes.length) return []; + var parent = parents(nodes), total = function (i) { return num(nodes[i].total_us); }; + var rects = []; + // Ancestors of the focus, full width + var chain = []; + for (var a = parent[focus]; a >= 0; a = parent[a]) chain.unshift(a); + chain.forEach(function (i) { rects.push({ index: i, x: 0, w: 1, row: nodes[i].depth, ancestor: true }); }); + var focusTotal = total(focus) || 1; + var x = {}; + x[focus] = 0; + rects.push({ index: focus, x: 0, w: 1, row: nodes[focus].depth }); + var next = {}; // where the next child of a node starts + next[focus] = 0; + for (var i = focus + 1; i < nodes.length && nodes[i].depth > nodes[focus].depth; i++) { + var p = parent[i]; + if (!(p in next)) continue; // under a node too narrow to draw + var w = total(i) / focusTotal; + var start = next[p]; + next[p] = start + w; + if (w < minWidth) continue; + next[i] = start; + rects.push({ index: i, x: start, w: w, row: nodes[i].depth }); + } + return rects; + } + + /** + * A slow frame's timeline: each scope from its first start for its total time, row = depth, as fractions of the + * frame. A scope entered many times is drawn as one bar of all of its time (count says how many). + */ + function timelineLayout(scopes, durationMs) { + var d = num(durationMs) || 1; + return scopes.map(function (s, i) { + var x = Math.min(Math.max(num(s.start_ms) / d, 0), 1); + return { index: i, x: x, w: Math.max(Math.min(num(s.total_ms) / d, 1 - x), 0), row: s.depth }; + }); + } + + /** + * The stacked phase series: the drawn phases (those with any time) and "other" for the rest, each {key, label, + * color, values}; values are milliseconds per second (null where nothing was reported) + */ + function phaseSeries(phases) { + phases = phases || {}; + var length = 0; + Object.keys(phases).forEach(function (k) { length = Math.max(length, (phases[k] || []).length); }); + var out = []; + PHASES.forEach(function (p) { + var values = phases[p.key] || []; + if (!values.some(function (v) { return num(v) > 0; })) return; + out.push({ key: p.key, label: p.label, color: p.color, values: values.slice() }); + }); + var other = []; + for (var i = 0; i < length; i++) { + var sum = null; + OTHER_PHASES.forEach(function (k) { var v = (phases[k] || [])[i]; if (v != null) sum = (sum || 0) + num(v); }); + other.push(sum); + } + if (other.some(function (v) { return num(v) > 0; })) out.push({ key: 'other', label: 'Other', color: 'var(--tr-other)', values: other }); + return out; + } + + // ---- Drawing (browser only) ---- + + var SVG = 'http://www.w3.org/2000/svg'; + function el(name, attrs, parent) { + var e = document.createElementNS(SVG, name); + for (var k in attrs) e.setAttribute(k, attrs[k]); + if (parent) parent.appendChild(e); + return e; + } + function esc(s) { return String(s).replace(/[&<>"']/g, function (c) { return { '&': '&', '<': '<', '>': '>', '"': '"', "'": ''' }[c]; }); } + function niceMax(v) { + if (v <= 0) return 1; + var p = Math.pow(10, Math.floor(Math.log10(v))), n = v / p; + return (n <= 1 ? 1 : n <= 2 ? 2 : n <= 5 ? 5 : 10) * p; + } + function ms(v) { return v == null ? '-' : v >= 1000 ? (v / 1000).toFixed(2) + ' s' : (v >= 10 ? v.toFixed(0) : v.toFixed(2)) + ' ms'; } + + function tip(box) { + var t = box.querySelector('.pf-tip'); + if (!t) { t = document.createElement('div'); t.className = 'pf-tip d-none'; box.appendChild(t); } + return t; + } + function showTip(box, html, x, y) { + var t = tip(box); + t.innerHTML = html; + t.classList.remove('d-none'); + var left = Math.min(x + 12, box.clientWidth - t.offsetWidth - 4); + t.style.left = Math.max(left, 0) + 'px'; + t.style.top = Math.max(y - t.offsetHeight - 8, 0) + 'px'; + } + function hideTip(box) { tip(box).classList.add('d-none'); } + + /** + * A time chart: lines ([{label, color, values, dash}]) or a stack of areas (stacked: true), with a crosshair and + * every series' value in the tooltip; `threshold` draws a dashed line (the slow frame threshold) + */ + function timeChart(svg, times, series, options) { + options = options || {}; + var box = svg.parentNode; + var width = box.clientWidth || 600, height = box.clientHeight || 180, left = 52, bottom = 20, top = 8, right = 8; + svg.innerHTML = ''; + svg.setAttribute('viewBox', '0 0 ' + width + ' ' + height); + var n = times.length, max = 0; + var stacks = []; + for (var i = 0; i < n; i++) { + var sum = 0; + series.forEach(function (s) { + var v = s.values[i]; + if (options.stacked) sum += num(v); else if (v != null) max = Math.max(max, v); + }); + stacks.push(sum); + if (options.stacked) max = Math.max(max, sum); + } + if (options.threshold) max = Math.max(max, Math.min(options.threshold * 1.1, max * 4 || options.threshold * 1.1)); + max = niceMax(max); + var W = width - left - right, H = height - top - bottom; + var X = function (i) { return left + (n > 1 ? i / (n - 1) : 0) * W; }; + var Y = function (v) { return top + H - Math.min(v / max, 1) * H; }; + for (var g = 0; g <= 4; g++) { + var v = max * g / 4, y = Y(v); + el('line', { x1: left, x2: width - right, y1: y, y2: y, class: 'grid' }, svg); + el('text', { x: left - 6, y: y + 4, 'text-anchor': 'end', class: 'axis' }, svg).textContent = options.format ? options.format(v) : String(v); + } + [0, Math.floor((n - 1) / 2), n - 1].forEach(function (i) { + if (i < 0 || !times.length) return; + el('text', { x: X(i), y: height - 4, 'text-anchor': i === 0 ? 'start' : i === n - 1 ? 'end' : 'middle', class: 'axis' }, svg).textContent = + new Date(times[i] * 1000).toLocaleTimeString([], { hour: '2-digit', minute: '2-digit', second: n <= 400 ? '2-digit' : undefined }); + }); + if (options.stacked) { + var base = new Array(n).fill(0); + series.forEach(function (s) { + var upper = [], lower = []; + for (var i = 0; i < n; i++) { + if (s.values[i] == null) continue; + lower.push(X(i) + ',' + Y(base[i])); + base[i] += num(s.values[i]); + upper.push(X(i) + ',' + Y(base[i])); + } + if (!upper.length) return; + el('polygon', { points: upper.concat(lower.reverse()).join(' '), fill: s.color, class: 'area' }, svg); + }); + } else { + series.forEach(function (s) { + var d = '', pen = false; + for (var i = 0; i < n; i++) { + var v = s.values[i]; + if (v == null) { pen = false; continue; } + d += (pen ? 'L' : 'M') + X(i).toFixed(1) + ',' + Y(v).toFixed(1); + pen = true; + } + if (d) el('path', { d: d, stroke: s.color, class: 'line' + (s.dash ? ' dashed' : '') }, svg); + }); + } + if (options.threshold && options.threshold <= max) { + var ty = Y(options.threshold); + el('line', { x1: left, x2: width - right, y1: ty, y2: ty, class: 'threshold' }, svg); + el('text', { x: width - right, y: ty - 3, 'text-anchor': 'end', class: 'axis' }, svg).textContent = 'slow ' + ms(options.threshold); + } + var cross = el('line', { y1: top, y2: top + H, class: 'cross', visibility: 'hidden' }, svg); + var hit = el('rect', { x: left, y: top, width: W, height: H, fill: 'transparent' }, svg); + hit.addEventListener('mousemove', function (e) { + var r = svg.getBoundingClientRect(), px = (e.clientX - r.left) * width / r.width; + var i = Math.round((px - left) / W * (n - 1)); + if (i < 0 || i >= n) return; + cross.setAttribute('x1', X(i)); cross.setAttribute('x2', X(i)); cross.setAttribute('visibility', 'visible'); + var rows = series.map(function (s) { + return '
' + esc(s.label) + ': ' + (options.format ? options.format(s.values[i]) : esc(s.values[i])) + '
'; + }); + if (options.extra) rows = rows.concat(options.extra(i)); + showTip(box, '
' + esc(new Date(times[i] * 1000).toLocaleTimeString()) + '
' + rows.join(''), e.clientX - box.getBoundingClientRect().left, e.clientY - box.getBoundingClientRect().top); + }); + hit.addEventListener('mouseleave', function () { cross.setAttribute('visibility', 'hidden'); hideTip(box); }); + } + + /** + * Rows of named bars (a flame graph or a timeline): rects from flameLayout or timelineLayout; `describe(index)` is + * the tooltip; `onClick(index)` for zooming + */ + function bars(svg, rects, nodes, options) { + options = options || {}; + var box = svg.parentNode, row = 20, width = box.clientWidth || 800; + var rows = rects.reduce(function (m, r) { return Math.max(m, r.row + 1); }, 1); + var height = rows * row + 2; + svg.innerHTML = ''; + svg.setAttribute('viewBox', '0 0 ' + width + ' ' + height); + svg.setAttribute('height', height); + rects.forEach(function (r) { + var node = nodes[r.index], x = r.x * width, w = Math.max(r.w * width - 1, 1), y = r.row * row; + var g = el('g', { class: 'pf-bar' + (r.ancestor ? ' ancestor' : ''), 'data-index': r.index }, svg); + el('rect', { x: x, y: y, width: w, height: row - 2, rx: 2, class: 'tone-' + (hash(node.label) % 3) }, g); + if (w > 30) { + var text = el('text', { x: x + 4, y: y + 14, class: 'pf-label' }, g); + var chars = Math.floor((w - 8) / 6.5); + text.textContent = node.label.length > chars ? node.label.slice(0, Math.max(chars - 1, 1)) + '…' : node.label; + } + g.addEventListener('mousemove', function (e) { + var b = box.getBoundingClientRect(); + showTip(box, options.describe ? options.describe(r.index) : esc(node.label), e.clientX - b.left, e.clientY - b.top); + }); + g.addEventListener('mouseleave', function () { hideTip(box); }); + if (options.onClick) g.addEventListener('click', function () { options.onClick(r.index); }); + }); + } + + function hash(s) { + var h = 0; + for (var i = 0; i < s.length; i++) h = (h * 31 + s.charCodeAt(i)) | 0; + return Math.abs(h); + } + + root.PerfCharts = { + PHASES: PHASES, parents: parents, flameLayout: flameLayout, timelineLayout: timelineLayout, phaseSeries: phaseSeries, + timeChart: timeChart, bars: bars, ms: ms, esc: esc, + }; +})(typeof window !== 'undefined' ? window : this); diff --git a/dDashboardServer/templates/header.jinja2 b/dDashboardServer/templates/header.jinja2 index 9215c921e..68634bec7 100644 --- a/dDashboardServer/templates/header.jinja2 +++ b/dDashboardServer/templates/header.jinja2 @@ -105,7 +105,7 @@ {% endif %} - {% set logsPages = ["health", "instances", "diagnostics", "network", "activity_log", "command_log", "audit_log", "system_log", "client_sysinfo"] %} + {% set logsPages = ["health", "instances", "diagnostics", "network", "performance", "activity_log", "command_log", "audit_log", "system_log", "client_sysinfo"] %} {% if can.health_view or can.logs_activity or can.logs_command or can.logs_audit or can.logs_system or can.client_sysinfo %}
- {% if can.health_view %}Server HealthInstance LoadDiagnosticsNetwork{% endif %} + {% if can.health_view %}Server HealthInstance LoadDiagnosticsNetworkPerformance{% endif %} {% if can.logs_activity %}Activity Log{% endif %} {% if can.logs_command %}Command Log{% endif %} {% if can.logs_audit %}Audit Log{% endif %} diff --git a/dDashboardServer/templates/performance.jinja2 b/dDashboardServer/templates/performance.jinja2 new file mode 100644 index 000000000..e1850a52f --- /dev/null +++ b/dDashboardServer/templates/performance.jinja2 @@ -0,0 +1,288 @@ +{% extends "base.jinja2" %} + +{% block title %}Performance - DarkflameServer{% endblock %} + +{% block css %} + +{% endblock %} + +{% block content %} +
+
+

Performance

+

How long each server's main loop takes per frame and what it spends the time on. Frames over + slow_frame_ms are kept with their scopes and logged. Kept in memory: the last hour.

+
+
+ +
+ + +
+
+
+ +
+
+
Frame time
+
+
Time per phase (ms per second)
+
+
Slow frames (every server, the last 50)
+
+
+
+
Folded stacks
+
+
+
+
+
Servers (last 5 minutes; click to pick)
+
Longest frames (this server, 10 minutes)
+
Packet handling (this server, 5 minutes)
+
Profiling
+
+
+
+ Seconds + + +
+
Merges every frame's scopes for that long into a flame graph. One session per server at a time.
+
+
Running a session needs the profiling_run permission.
+
+
+
+
+
+{% endblock %} + +{% block scripts %} + + +{% endblock %} diff --git a/tests/dWebTests/CMakeLists.txt b/tests/dWebTests/CMakeLists.txt index bb948f237..2679e8123 100644 --- a/tests/dWebTests/CMakeLists.txt +++ b/tests/dWebTests/CMakeLists.txt @@ -59,6 +59,8 @@ set(DWEBTESTS_SOURCES "${PROJECT_SOURCE_DIR}/dDashboardServer/routes/TrafficHistory.cpp" "NetworkViewTests.cpp" "${PROJECT_SOURCE_DIR}/dDashboardServer/routes/NetworkView.cpp" + "PerfHistoryTests.cpp" + "${PROJECT_SOURCE_DIR}/dDashboardServer/routes/PerfHistory.cpp" "${PROJECT_SOURCE_DIR}/dDashboardServer/routes/SettingsCatalog.cpp" "AlertsAndTwoFactorTests.cpp" "${PROJECT_SOURCE_DIR}/dDashboardServer/auth/Totp.cpp" @@ -111,4 +113,7 @@ if(NODE_EXECUTABLE) # The Network page's diagram model: nodes and links from the traffic summary (static/js/network-graph.js) add_test(NAME NetworkGraphJs COMMAND ${NODE_EXECUTABLE} "${CMAKE_CURRENT_SOURCE_DIR}/network-graph.test.mjs" "${PROJECT_SOURCE_DIR}/dDashboardServer/static/js/network-graph.js") + # The Performance page's flame graph, timeline and phase layouts (static/js/perf-charts.js) + add_test(NAME PerfChartsJs COMMAND ${NODE_EXECUTABLE} "${CMAKE_CURRENT_SOURCE_DIR}/perf-charts.test.mjs" + "${PROJECT_SOURCE_DIR}/dDashboardServer/static/js/perf-charts.js") endif() diff --git a/tests/dWebTests/PerfHistoryTests.cpp b/tests/dWebTests/PerfHistoryTests.cpp new file mode 100644 index 000000000..c9b54cc87 --- /dev/null +++ b/tests/dWebTests/PerfHistoryTests.cpp @@ -0,0 +1,205 @@ +#include + +#include "PerfHistory.h" +#include "Permissions.h" +#include "ServiceType.h" + +namespace { + constexpr int64_t NOW = 1700000100; + + size_t P(Profiler::Phase phase) { return static_cast(phase); } + + // Five seconds of a world at 30 frames a second, 3 ms each (2 of them packets); one 400 ms frame in the last + Profiler::Report WorldReport(int64_t end = NOW) { + Profiler::Report report; + report.present = true; + report.slowThresholdMs = 250; + for (int64_t t = end - 5; t < end; t++) { + Profiler::Second s{ .time = t, .ticks = 30, .totalUs = 90000, .maxUs = 3000 }; + s.frames.Add(3000, 30); + s.phaseUs[P(Profiler::Phase::PACKETS)] = 60000; + s.phaseUs[P(Profiler::Phase::ENTITIES)] = 30000; + report.seconds.push_back(s); + } + auto& last = report.seconds.back(); + last.ticks++; + last.totalUs += 400000; + last.maxUs = 400000; + last.frames.Add(400000); + last.phaseUs[P(Profiler::Phase::CDCLIENT)] += 400000; + + Profiler::Frame slow{ .timeMs = (end - 1) * 1000, .durationUs = 400000 }; + slow.phaseUs[P(Profiler::Phase::CDCLIENT)] = 390000; + slow.scopes = { + { .name = Profiler::FRAME, .depth = 0, .count = 1, .totalUs = 400000 }, + { .name = Profiler::PACKET, .arg = 77, .depth = 1, .count = 1, .totalUs = 399000, .startUs = 50 }, + { .name = "CDClient Objects", .depth = 2, .count = 9800, .totalUs = 390000, .startUs = 60 }, + }; + report.worst = { slow }; + report.slow = { slow }; + report.messages = { { .key = 77, .count = 10, .totalUs = 399500, .maxUs = 399000 }, { .key = 5, .count = 100, .totalUs = 1000, .maxUs = 50 } }; + return report; + } + + std::string Label(const Profiler::Node& node) { + return node.name == Profiler::PACKET ? "Packet named " + std::to_string(node.arg) : Profiler::DefaultLabel(node); + } + std::string ServerLabel(const std::string& key) { return "label of " + key; } +} + +TEST(PerfHistoryTest, KeysParse) { + uint16_t type{}; + uint32_t zone{}, instance{}; + ASSERT_TRUE(PerfHistory::ParseKey("world:1200:3", type, zone, instance)); + EXPECT_EQ(type, static_cast(ServiceType::WORLD)); + EXPECT_EQ(zone, 1200u); + EXPECT_EQ(instance, 3u); + ASSERT_TRUE(PerfHistory::ParseKey("dashboard", type, zone, instance)); + EXPECT_EQ(type, static_cast(ServiceType::DASHBOARD)); + EXPECT_EQ(zone, 0u); + EXPECT_FALSE(PerfHistory::ParseKey("world:12a:3", type, zone, instance)); + EXPECT_FALSE(PerfHistory::ParseKey("world:1200", type, zone, instance)); + EXPECT_FALSE(PerfHistory::ParseKey("service:9:0:0", type, zone, instance)); + EXPECT_FALSE(PerfHistory::ParseKey("", type, zone, instance)); +} + +TEST(PerfHistoryTest, ReportsWithoutFramesAreIgnored) { + PerfHistory history; + history.Ingest("auth", Profiler::Report{}, NOW); + EXPECT_TRUE(history.Servers().empty()); +} + +TEST(PerfHistoryTest, ServersSummariseTheirLoops) { + PerfHistory history; + history.Ingest("world:1200:3", WorldReport(), NOW); + const auto servers = history.ServersJson(NOW, 300, 20, ServerLabel); + ASSERT_EQ(servers.size(), 1u); + const auto& world = servers[0]; + EXPECT_EQ(world["key"], "world:1200:3"); + EXPECT_EQ(world["label"], "label of world:1200:3"); + EXPECT_TRUE(world["online"].get()); + EXPECT_EQ(world["seconds"], 5); + EXPECT_DOUBLE_EQ(world["ticks_per_second"].get(), 30.2); + EXPECT_DOUBLE_EQ(world["max_ms"].get(), 400.0); + // 850 ms of frames in 5 seconds + EXPECT_DOUBLE_EQ(world["busy_percent"].get(), 17.0); + EXPECT_EQ(world["slow"], 1); + EXPECT_EQ(world["slow_threshold_ms"], 250); + EXPECT_FALSE(history.ServersJson(NOW + 100, 300, 20, ServerLabel)[0]["online"].get()); +} + +TEST(PerfHistoryTest, SeriesHasFrameTimesAndPhasesPerStep) { + PerfHistory history; + history.Ingest("world:1200:3", WorldReport(), NOW); + const auto series = history.Series("world:1200:3", NOW - 6, NOW, 1); + ASSERT_EQ(series["times"].size(), 6u); + // The first second wasn't reported: gaps + EXPECT_TRUE(series["ticks_per_second"][0].is_null()); + EXPECT_TRUE(series["avg_ms"][0].is_null()); + EXPECT_TRUE(series["phases_ms_per_second"]["packets"][0].is_null()); + EXPECT_DOUBLE_EQ(series["ticks_per_second"][1].get(), 30.0); + EXPECT_DOUBLE_EQ(series["avg_ms"][1].get(), 3.0); + EXPECT_DOUBLE_EQ(series["max_ms"][5].get(), 400.0); + EXPECT_DOUBLE_EQ(series["phases_ms_per_second"]["packets"][1].get(), 60.0); + EXPECT_DOUBLE_EQ(series["phases_ms_per_second"]["cdclient"][5].get(), 400.0); + EXPECT_EQ(series["slow_threshold_ms"], 250); + + // Steps of 5 seconds: per-second averages, the longest frame, p95 from the merged histograms + const auto coarse = history.Series("world:1200:3", NOW - 5, NOW, 5); + ASSERT_EQ(coarse["times"].size(), 1u); + EXPECT_DOUBLE_EQ(coarse["ticks_per_second"][0].get(), 30.2); + EXPECT_DOUBLE_EQ(coarse["max_ms"][0].get(), 400.0); + EXPECT_LT(coarse["p95_ms"][0].get(), 5.0); + EXPECT_DOUBLE_EQ(coarse["phases_ms_per_second"]["cdclient"][0].get(), 80.0); +} + +TEST(PerfHistoryTest, SecondsFromLateReportsMerge) { + PerfHistory history; + history.Ingest("chat", WorldReport(), NOW); + history.Ingest("chat", WorldReport(), NOW + 1); // the same seconds again + const auto series = history.Series("chat", NOW - 5, NOW, 1); + EXPECT_DOUBLE_EQ(series["ticks_per_second"][0].get(), 60.0); + EXPECT_EQ(history.Servers().at("chat").seconds.size(), 5u); +} + +TEST(PerfHistoryTest, WorstSlowAndMessagesAreLabelled) { + PerfHistory history; + history.Ingest("world:1200:3", WorldReport(), NOW); + const auto worst = history.Worst("world:1200:3", NOW - 600, 10, Label); + ASSERT_EQ(worst.size(), 1u); + EXPECT_DOUBLE_EQ(worst[0]["duration_ms"].get(), 400.0); + EXPECT_DOUBLE_EQ(worst[0]["phases"]["cdclient"].get(), 390.0); + ASSERT_EQ(worst[0]["scopes"].size(), 3u); + EXPECT_EQ(worst[0]["scopes"][1]["label"], "Packet named 77"); + EXPECT_EQ(worst[0]["scopes"][2]["count"], 9800); + EXPECT_DOUBLE_EQ(worst[0]["scopes"][1]["self_ms"].get(), 9.0); + EXPECT_NE(worst[0]["path"].get().find("Packet named 77"), std::string::npos); + + const auto slow = history.SlowJson("", Label, ServerLabel); + ASSERT_EQ(slow.size(), 1u); + EXPECT_EQ(slow[0]["server"], "world:1200:3"); + EXPECT_EQ(slow[0]["server_label"], "label of world:1200:3"); + EXPECT_TRUE(history.SlowJson("auth", Label, ServerLabel).empty()); + + const auto messages = history.Messages("world:1200:3", NOW - 300, 10, [](uint64_t key) { return nlohmann::json{ {"packet", std::to_string(key)} }; }); + ASSERT_EQ(messages.size(), 2u); + EXPECT_EQ(messages[0]["packet"], "77"); + EXPECT_EQ(messages[0]["count"], 10); + EXPECT_DOUBLE_EQ(messages[0]["max_ms"].get(), 399.0); + EXPECT_DOUBLE_EQ(messages[1]["avg_ms"].get(), 0.01); +} + +TEST(PerfHistoryTest, SlowFramesKeepTheLastFifty) { + PerfHistory history; + for (int i = 0; i < 60; i++) history.Ingest("world:1200:" + std::to_string(i % 3), WorldReport(NOW + i * 5), NOW + i * 5); + EXPECT_EQ(history.Slow().size(), PerfHistory::SLOW_KEPT); + // Newest first + const auto slow = history.SlowJson("", Label, ServerLabel); + EXPECT_GT(slow[0]["time_ms"].get(), slow[1]["time_ms"].get()); +} + +TEST(PerfHistoryTest, OldDataIsForgotten) { + PerfHistory history; + history.Ingest("world:1200:3", WorldReport(), NOW); + history.Forget(NOW + PerfHistory::RECENT_SECONDS + 10); + const auto& server = history.Servers().at("world:1200:3"); + EXPECT_EQ(server.seconds.size(), 5u); + EXPECT_TRUE(server.worst.empty()); + EXPECT_TRUE(server.messages.empty()); + history.Forget(NOW + PerfHistory::SECONDS_KEPT + 10); + EXPECT_TRUE(history.Servers().at("world:1200:3").seconds.empty()); + history.Forget(NOW + PerfHistory::FORGET_AFTER + 10); + EXPECT_TRUE(history.Servers().empty()); +} + +TEST(PerfHistoryTest, ProfilesBecomeAFlameGraphAndFoldedStacks) { + Profiler::Profile profile; + profile.frames = 300; + profile.durationMs = 10000; + profile.totalUs = 900000; + profile.nodes = { + { .name = "All frames", .depth = 0, .count = 300, .totalUs = 900000 }, + { .name = Profiler::PACKET, .arg = 77, .depth = 1, .count = 20, .totalUs = 500000 }, + { .name = "Database query", .depth = 2, .count = 40, .totalUs = 300000 }, + { .name = "Entities", .depth = 1, .count = 300, .totalUs = 400000 }, + }; + const auto json = PerfHistory::ProfileJson(profile, Label); + ASSERT_EQ(json["nodes"].size(), 4u); + EXPECT_EQ(json["nodes"][1]["label"], "Packet named 77"); + EXPECT_EQ(json["nodes"][1]["self_us"], 200000); + EXPECT_EQ(json["nodes"][0]["self_us"], 0); + EXPECT_DOUBLE_EQ(json["total_ms"].get(), 900.0); + EXPECT_EQ(json["folded"], + "All frames;Packet named 77 200000\n" + "All frames;Packet named 77;Database query 300000\n" + "All frames;Entities 400000\n"); +} + +TEST(PerfHistoryTest, ProfilingIsItsOwnPermission) { + // Viewing needs health_view; starting a session profiling_run, GM 8 by default and grantable + const auto* run = Permissions::Find("profiling_run"); + ASSERT_NE(run, nullptr); + EXPECT_EQ(run->defaultLevel, 8); + EXPECT_FALSE(run->locked); + EXPECT_EQ(Permissions::Level("health_view"), 8); +} diff --git a/tests/dWebTests/perf-charts.test.mjs b/tests/dWebTests/perf-charts.test.mjs new file mode 100644 index 000000000..bf70005f2 --- /dev/null +++ b/tests/dWebTests/perf-charts.test.mjs @@ -0,0 +1,58 @@ +// The Performance page's layouts (static/js/perf-charts.js): flame graph, slow frame timeline, stacked phases. +// Run by ctest: node perf-charts.test.mjs +import { readFileSync } from 'node:fs'; +import vm from 'node:vm'; + +const [scriptPath] = process.argv.slice(2); +const context = { window: {} }; +vm.createContext(context); +vm.runInContext(readFileSync(scriptPath, 'utf8'), context); +const C = context.window.PerfCharts; +let failures = 0; +const same = (actual, expected, what) => { + if (JSON.stringify(actual) !== JSON.stringify(expected)) { + failures++; + console.error(`${what}: ${JSON.stringify(actual)} is not ${JSON.stringify(expected)}`); + } +}; + +// A session's tree as PerfHistory::ProfileJson sends it +const nodes = [ + { label: 'All frames', depth: 0, total_us: 1000 }, + { label: 'Entities', depth: 1, total_us: 600 }, + { label: 'Script timer', depth: 2, total_us: 200 }, + { label: 'Physics step', depth: 1, total_us: 300 }, + { label: 'Tiny', depth: 1, total_us: 0.5 }, + { label: 'Under tiny', depth: 2, total_us: 0.5 }, +]; +same(Array.from(C.parents(nodes)), [-1, 0, 1, 0, 0, 4], 'parents'); + +const whole = C.flameLayout(nodes, 0, 0.001).map((r) => [r.index, +r.x.toFixed(3), +r.w.toFixed(3), r.row]); +same(whole, [[0, 0, 1, 0], [1, 0, 0.6, 1], [2, 0, 0.2, 2], [3, 0.6, 0.3, 1]], 'flame graph of the whole tree, too narrow ones left out'); + +// Zoomed into Entities: its ancestors span the width, it and its children are scaled to it +const zoomed = C.flameLayout(nodes, 1, 0).map((r) => [r.index, +r.x.toFixed(3), +r.w.toFixed(3), r.row, !!r.ancestor]); +same(zoomed, [[0, 0, 1, 0, true], [1, 0, 1, 1, false], [2, 0, 0.333, 2, false]], 'flame graph zoomed in'); + +// A slow frame: bars from their first start +const scopes = [ + { label: 'Frame', depth: 0, start_ms: 0, total_ms: 100 }, + { label: 'LoadPlayer', depth: 1, start_ms: 10, total_ms: 80 }, + { label: 'Late', depth: 1, start_ms: 95, total_ms: 20 }, +]; +same(C.timelineLayout(scopes, 100).map((r) => [r.index, +r.x.toFixed(2), +r.w.toFixed(2), r.row]), [[0, 0, 1, 0], [1, 0.1, 0.8, 1], [2, 0.95, 0.05, 1]], 'timeline'); + +// Phases: the ones with time in their fixed colours, scripts and log flushes folded into other +const series = C.phaseSeries({ packets: [1, 2], entities: [0, 0], physics: [3, null], scripts: [1, null], log_flush: [0.5, null], other: [1, null], cdclient: [0, 9] }); +same(series.map((s) => [s.key, s.color, Array.from(s.values)]), [ + ['packets', 'var(--tr-1)', [1, 2]], + ['physics', 'var(--tr-3)', [3, null]], + ['cdclient', 'var(--tr-6)', [0, 9]], + ['other', 'var(--tr-other)', [2.5, null]], +], 'phase series'); + +if (failures) { + console.error(`${failures} failure(s)`); + process.exit(1); +} +console.log('perf-charts: all passed');