diff --git a/dCommon/CMakeLists.txt b/dCommon/CMakeLists.txt index f1f10270c..6987a9ad3 100644 --- a/dCommon/CMakeLists.txt +++ b/dCommon/CMakeLists.txt @@ -6,6 +6,7 @@ set(DCOMMON_SOURCES "dConfig.cpp" "Diagnostics.cpp" "TrafficStats.cpp" + "Profiler.cpp" "Locale.cpp" "Logger.cpp" "Game.cpp" @@ -115,3 +116,9 @@ target_link_libraries(dCommon PUBLIC glm::glm dBuildInfo PRIVATE ZLIB::ZLIB bcrypt tinyxml2 INTERFACE dDatabase) + +# Profiler.h's frames and scopes also go to Tracy (thirdparty/CMakeLists.txt, DLU_TRACY) +if(DLU_TRACY) + target_link_libraries(dCommon PUBLIC Tracy::TracyClient) + target_compile_definitions(dCommon PRIVATE DLU_TRACY) +endif() diff --git a/dCommon/Profiler.cpp b/dCommon/Profiler.cpp new file mode 100644 index 000000000..c5899bcf5 --- /dev/null +++ b/dCommon/Profiler.cpp @@ -0,0 +1,561 @@ +#include "Profiler.h" + +#include +#include +#include +#include +#include +#include + +#ifdef DLU_TRACY +#include "tracy/TracyC.h" +#endif + +namespace Profiler { + namespace { + thread_local bool t_Main = false; + +#ifdef DLU_TRACY + // Tracy zones for the scopes (its C interface: zones with names made at run time) + uint64_t TracyBegin(const char* name, uint64_t arg) { + const auto location = ___tracy_alloc_srcloc_name(0, "", 0, "", 0, name, std::strlen(name), 0); + const auto zone = ___tracy_emit_zone_begin_alloc(location, 1); + if (arg) ___tracy_emit_zone_value(zone, arg); + return (static_cast(zone.id) << 32) | static_cast(zone.active); + } + + void TracyEnd(uint64_t packed) { + TracyCZoneCtx zone{}; + zone.id = static_cast(packed >> 32); + zone.active = static_cast(static_cast(packed)); + ___tracy_emit_zone_end(zone); + } +#endif + + constexpr const char* MORE = "(more)"; + constexpr const char* ALL_FRAMES = "All frames"; + + uint32_t ClampU32(int64_t value) { + return static_cast(std::clamp(value, 0, UINT32_MAX)); + } + + uint64_t Micros(int64_t ns) { + return ns > 0 ? static_cast(ns / 1000) : 0; + } + + std::string Duration(uint64_t us) { + char buffer[32]; + if (us >= 1000000) std::snprintf(buffer, sizeof(buffer), "%.1f s", static_cast(us) / 1e6); + else std::snprintf(buffer, sizeof(buffer), "%.1f ms", static_cast(us) / 1e3); + return buffer; + } + + bool SameName(const char* a, const char* b) { + return a == b || std::strcmp(a, b) == 0; + } + + // The children of nodes[i] in a pre-order list: the following nodes one deeper, until one as shallow as it + template + void ForEachChild(const std::vector& nodes, size_t i, Fn&& fn) { + for (size_t j = i + 1; j < nodes.size() && nodes[j].depth > nodes[i].depth; j++) { + if (nodes[j].depth == nodes[i].depth + 1) fn(j); + } + } + } + + const char* PhaseName(size_t phase) { + static constexpr const char* NAMES[PHASES] = { "other", "packets", "entities", "physics", "replica", "scripts", "database", "cdclient", "log_flush", "web" }; + return phase < PHASES ? NAMES[phase] : ""; + } + + void Second::Merge(const Second& other) { + ticks += other.ticks; + totalUs += other.totalUs; + maxUs = std::max(maxUs, other.maxUs); + frames.Merge(other.frames); + for (size_t i = 0; i < PHASES; i++) phaseUs[i] += other.phaseUs[i]; + } + + std::string DefaultLabel(const Node& node) { + if (node.name == PACKET) { + const auto key = TrafficStats::MessageKey::Unpack(node.arg); + std::string label = "Packet " + std::to_string(key.service) + ":" + std::to_string(key.packet); + if (key.gameMessage) label += ":" + std::to_string(key.gameMessage); + return label; + } + return node.arg ? node.name + " " + std::to_string(node.arg) : node.name; + } + + std::string Frame::Path(const std::function& label) const { + if (scopes.empty()) return ""; + const auto name = [&label](const Node& node) { return label ? label(node) : DefaultLabel(node); }; + std::string path; + size_t current = 0; + while (true) { + size_t heaviest = SIZE_MAX; + ForEachChild(scopes, current, [&](size_t j) { + if (heaviest == SIZE_MAX || scopes[j].totalUs > scopes[heaviest].totalUs) heaviest = j; + }); + // Stop where the scope's own time is most of it + if (heaviest == SIZE_MAX || scopes[heaviest].totalUs * 5 < scopes[current].totalUs) break; + current = heaviest; + const auto& node = scopes[current]; + if (!path.empty()) path += " > "; + path += name(node) + " " + Duration(node.totalUs); + if (node.count > 1) path += " x" + std::to_string(node.count); + } + // The busiest repeated scope below where the path stopped (e.g. many small lookups) + size_t repeated = SIZE_MAX; + for (size_t j = current + 1; j < scopes.size() && scopes[j].depth > scopes[current].depth; j++) { + if (scopes[j].count > 1 && (repeated == SIZE_MAX || scopes[j].totalUs > scopes[repeated].totalUs)) repeated = j; + } + if (repeated != SIZE_MAX) { + path += (path.empty() ? "" : ", ") + name(scopes[repeated]) + " " + Duration(scopes[repeated].totalUs) + " x" + std::to_string(scopes[repeated].count); + } + return path; + } + + std::string Folded(const std::vector& nodes, const std::function& label) { + std::string out; + std::vector stack; + for (size_t i = 0; i < nodes.size(); i++) { + const auto& node = nodes[i]; + std::string name = label ? label(node) : DefaultLabel(node); + std::replace(name.begin(), name.end(), ';', ','); + std::replace(name.begin(), name.end(), '\n', ' '); + stack.resize(node.depth); + stack.push_back(std::move(name)); + uint64_t children = 0; + ForEachChild(nodes, i, [&](size_t j) { children += nodes[j].totalUs; }); + const uint64_t self = node.totalUs > children ? node.totalUs - children : 0; + if (self == 0) continue; + for (size_t d = 0; d < stack.size(); d++) { + if (d) out += ';'; + out += stack[d]; + } + out += ' '; + out += std::to_string(self); + out += '\n'; + } + return out; + } + + uint32_t Recorder::Child(std::vector& nodes, uint32_t parent, const char* name, uint64_t arg, size_t maxNodes, bool& full) { + full = false; + for (uint32_t c = nodes[parent].firstChild; c; c = nodes[c].nextSibling) { + if (nodes[c].arg == arg && SameName(nodes[c].name, name)) return c; + } + // Too many different children: the rest share one + if (nodes[parent].children >= MAX_CHILDREN && !(arg == 0 && SameName(name, MORE))) { + return Child(nodes, parent, MORE, 0, maxNodes, full); + } + if (nodes.size() >= maxNodes) { + full = true; + return parent; + } + const auto index = static_cast(nodes.size()); + LiveNode node; + node.name = name; + node.arg = arg; + node.parent = parent; + node.nextSibling = nodes[parent].firstChild; + nodes.push_back(node); + nodes[parent].firstChild = index; + nodes[parent].children++; + return index; + } + + std::vector Recorder::Flatten(const std::vector& nodes, size_t limit, bool byStart, bool& truncated) { + std::vector out; + if (nodes.empty()) return out; + std::vector keep(nodes.size(), 1); + truncated = nodes.size() > limit; + if (truncated) { + std::vector order(nodes.size()); + for (uint32_t i = 0; i < order.size(); i++) order[i] = i; + std::stable_sort(order.begin(), order.end(), [&nodes](uint32_t a, uint32_t b) { return nodes[a].totalNs > nodes[b].totalNs; }); + std::fill(keep.begin(), keep.end(), 0); + keep[0] = 1; + for (size_t i = 0; i < limit && i < order.size(); i++) { + // With its parents, so the tree stays whole + for (uint32_t n = order[i]; !keep[n]; n = nodes[n].parent) keep[n] = 1; + } + } + out.reserve(std::min(limit + 8, nodes.size())); + // Pre-order, without recursion + std::vector> pending{ { 0u, uint8_t{ 0 } } }; + std::vector children; + while (!pending.empty()) { + const auto [index, depth] = pending.back(); + pending.pop_back(); + const auto& live = nodes[index]; + Node node; + node.name = live.name ? live.name : ""; + node.arg = live.arg; + node.depth = depth; + node.count = live.count; + node.totalUs = Micros(live.totalNs); + node.startUs = ClampU32(live.startNs / 1000); + out.push_back(std::move(node)); + + children.clear(); + for (uint32_t c = live.firstChild; c; c = nodes[c].nextSibling) if (keep[c]) children.push_back(c); + if (byStart) std::sort(children.begin(), children.end(), [&nodes](uint32_t a, uint32_t b) { return nodes[a].startNs != nodes[b].startNs ? nodes[a].startNs < nodes[b].startNs : a < b; }); + else std::sort(children.begin(), children.end(), [&nodes](uint32_t a, uint32_t b) { return nodes[a].totalNs != nodes[b].totalNs ? nodes[a].totalNs > nodes[b].totalNs : a < b; }); + const auto childDepth = static_cast(std::min(depth + 1, 255)); + // Pushed in reverse so the first comes out first + for (auto it = children.rbegin(); it != children.rend(); ++it) pending.emplace_back(*it, childDepth); + } + return out; + } + + void Recorder::FrameBegin(int64_t nowNs, int64_t unixMs, bool implicit) { + if (m_InFrame) return; + m_InFrame = true; + m_Implicit = implicit; + m_FrameStartNs = nowNs; + m_FrameUnixMs = unixMs; + m_Nodes.clear(); + LiveNode root; + root.name = implicit ? OUTSIDE : FRAME; + m_Nodes.push_back(root); + m_Stack.clear(); + m_Phase = Phase::OTHER; + m_PhaseStartNs = nowNs; + m_PhaseNs.fill(0); + } + + Frame Recorder::MakeFrame(int64_t durationNs, size_t scopes) const { + Frame frame; + frame.timeMs = m_FrameUnixMs; + frame.durationUs = ClampU32(durationNs / 1000); + frame.implicit = m_Implicit; + for (size_t i = 0; i < PHASES; i++) frame.phaseUs[i] = ClampU32(m_PhaseNs[i] / 1000); + bool truncated = false; + frame.scopes = Flatten(m_Nodes, scopes, true, truncated); + return frame; + } + + void Recorder::FrameEnd(int64_t nowNs) { + if (!m_InFrame) return; + // Scopes still open (a frame ended inside one) end with it + while (!m_Stack.empty()) { + const auto open = m_Stack.back(); + m_Stack.pop_back(); + if (open.counted) m_Nodes[open.node].totalNs += nowNs - open.startNs; + } + m_PhaseNs[static_cast(m_Phase)] += nowNs - m_PhaseStartNs; + const int64_t duration = std::max(nowNs - m_FrameStartNs, 0); + m_Nodes[0].count = 1; + m_Nodes[0].totalNs = duration; + const uint32_t us = ClampU32(duration / 1000); + const uint32_t threshold = SlowThreshold(); + const bool slow = threshold > 0 && us >= static_cast(threshold) * 1000; + + std::optional slowFrame; + if (slow) slowFrame = MakeFrame(duration, SLOW_SCOPES); + { + std::lock_guard lock(m_Mutex); + if (!m_Implicit) { + auto& second = m_Seconds[m_FrameUnixMs / 1000]; + second.time = m_FrameUnixMs / 1000; + second.ticks++; + second.totalUs += us; + second.maxUs = std::max(second.maxUs, us); + second.frames.Add(us); + for (size_t i = 0; i < PHASES; i++) second.phaseUs[i] += Micros(m_PhaseNs[i]); + } + if (m_Worst.size() < WORST_FRAMES || us > m_Worst.back().durationUs) { + auto frame = MakeFrame(duration, WORST_SCOPES); + const auto at = std::find_if(m_Worst.begin(), m_Worst.end(), [us](const Frame& f) { return f.durationUs < us; }); + m_Worst.insert(at, std::move(frame)); + if (m_Worst.size() > WORST_FRAMES) m_Worst.pop_back(); + } + if (slowFrame && m_Slow.size() < MAX_SLOW_FRAMES) m_Slow.push_back(*slowFrame); + } + m_InFrame = false; + if (slowFrame && m_SlowSink) m_SlowSink(*slowFrame); + + if (m_Session.active) { + MergeIntoSession(); + m_Session.frames++; + m_Session.totalNs += duration; + if (nowNs >= m_Session.endNs) FinishSession(nowNs); + } + } + + void Recorder::Enter(const char* name, uint64_t arg, int64_t nowNs) { + if (!m_InFrame) FrameBegin(nowNs, UnixMs(), true); + const uint32_t parent = m_Stack.empty() ? 0 : m_Stack.back().node; + bool full = false; + const uint32_t index = Child(m_Nodes, parent, name, arg, MAX_NODES, full); + if (full) { + m_Stack.push_back({ parent, nowNs, false }); + return; + } + auto& node = m_Nodes[index]; + if (node.count == 0) node.startNs = nowNs - m_FrameStartNs; + node.count++; + m_Stack.push_back({ index, nowNs, true }); + } + + void Recorder::Exit(int64_t nowNs) { + if (m_Stack.empty()) return; + const auto open = m_Stack.back(); + m_Stack.pop_back(); + if (open.counted) m_Nodes[open.node].totalNs += nowNs - open.startNs; + if (m_Stack.empty() && m_Implicit && m_InFrame) FrameEnd(nowNs); + } + + Phase Recorder::SetPhase(Phase phase, int64_t nowNs) { + const auto previous = m_Phase; + if (!m_InFrame) return previous; + m_PhaseNs[static_cast(previous)] += nowNs - m_PhaseStartNs; + m_PhaseStartNs = nowNs; + m_Phase = phase; + return previous; + } + + void Recorder::Record(const char* name, uint64_t arg, int64_t durationNs, Phase phase, int64_t nowNs) { + if (!m_InFrame || durationNs < 0) return; + const uint32_t parent = m_Stack.empty() ? 0 : m_Stack.back().node; + bool full = false; + const uint32_t index = Child(m_Nodes, parent, name, arg, MAX_NODES, full); + if (!full) { + auto& node = m_Nodes[index]; + if (node.count == 0) node.startNs = std::max(nowNs - durationNs - m_FrameStartNs, 0); + node.count++; + node.totalNs += durationNs; + } + // The time moves from the current phase to its own + if (phase != m_Phase) { + const int64_t moved = std::min(durationNs, std::max(nowNs - m_PhaseStartNs, 0)); + m_PhaseNs[static_cast(phase)] += moved; + m_PhaseStartNs += moved; + } + } + + void Recorder::AddMessageTime(uint64_t key, int64_t durationNs) { + const auto us = Micros(durationNs); + std::lock_guard lock(m_Mutex); + auto& message = m_Messages[key]; + message.key = key; + message.count++; + message.totalUs += us; + message.maxUs = std::max(message.maxUs, ClampU32(static_cast(us))); + } + + void Recorder::SetSlowThreshold(uint32_t milliseconds) { + std::lock_guard lock(m_Mutex); + m_SlowThresholdMs = milliseconds; + } + + uint32_t Recorder::SlowThreshold() const { + std::lock_guard lock(m_Mutex); + return m_SlowThresholdMs; + } + + bool Recorder::StartSession(uint32_t id, uint32_t durationMs, int64_t nowNs, std::function done) { + if (m_Session.active) return false; + m_Session = Session{}; + m_Session.active = true; + m_Session.id = id; + m_Session.startNs = nowNs; + m_Session.endNs = nowNs + static_cast(std::clamp(durationMs, 1, MAX_SESSION_MS)) * 1000000; + LiveNode root; + root.name = ALL_FRAMES; + m_Session.nodes.push_back(root); + m_Session.done = std::move(done); + return true; + } + + bool Recorder::StopSession(uint32_t id, int64_t nowNs) { + if (!m_Session.active || m_Session.id != id) return false; + FinishSession(nowNs); + return true; + } + + void Recorder::CheckSession(int64_t nowNs) { + if (m_Session.active && !m_InFrame && nowNs >= m_Session.endNs) FinishSession(nowNs); + } + + void Recorder::MergeIntoSession() { + auto& session = m_Session; + // Parents come before their children in m_Nodes, so each parent is mapped before its children + std::vector mapped(m_Nodes.size(), 0); + for (uint32_t i = 1; i < m_Nodes.size(); i++) { + const auto& node = m_Nodes[i]; + const uint32_t parent = mapped[node.parent]; + bool full = false; + const uint32_t index = Child(session.nodes, parent, node.name, node.arg, MAX_SESSION_NODES, full); + mapped[i] = index; + if (full) { + // Its time stays in the parent's (the parent's total includes it) + session.truncated = true; + continue; + } + session.nodes[index].count += m_Nodes[i].count; + session.nodes[index].totalNs += m_Nodes[i].totalNs; + } + session.nodes[0].count++; + session.nodes[0].totalNs += m_Nodes[0].totalNs; + } + + void Recorder::FinishSession(int64_t nowNs) { + Profile profile; + profile.id = m_Session.id; + profile.durationMs = ClampU32((nowNs - m_Session.startNs) / 1000000); + profile.frames = m_Session.frames; + profile.totalUs = Micros(m_Session.totalNs); + bool truncated = false; + profile.nodes = Flatten(m_Session.nodes, PROFILE_NODES, false, truncated); + profile.truncated = truncated || m_Session.truncated; + auto done = std::move(m_Session.done); + m_Session = Session{}; + if (done) done(std::move(profile)); + } + + Report Recorder::Take(int64_t now) { + Report report; + report.present = true; + std::lock_guard lock(m_Mutex); + report.slowThresholdMs = m_SlowThresholdMs; + int64_t from = m_LastReported ? m_LastReported + 1 : (m_Seconds.empty() ? now : std::min(m_Seconds.begin()->first, now - 1)); + from = std::max(from, now - MAX_GAP); + for (int64_t t = from; t < now; t++) { + const auto it = m_Seconds.find(t); + if (it != m_Seconds.end()) report.seconds.push_back(std::move(it->second)); + else report.seconds.push_back(Second{ .time = t }); + } + m_Seconds.erase(m_Seconds.begin(), m_Seconds.lower_bound(now)); + if (now - 1 > m_LastReported) m_LastReported = now - 1; + + report.messages.reserve(m_Messages.size()); + for (const auto& [_, message] : m_Messages) report.messages.push_back(message); + m_Messages.clear(); + std::sort(report.messages.begin(), report.messages.end(), [](const MessageTime& a, const MessageTime& b) { + return a.totalUs != b.totalUs ? a.totalUs > b.totalUs : a.key < b.key; + }); + if (report.messages.size() > TOP_MESSAGES) report.messages.resize(TOP_MESSAGES); + + report.worst = std::move(m_Worst); + m_Worst.clear(); + report.slow = std::move(m_Slow); + m_Slow.clear(); + return report; + } + + Recorder& Local() { + static Recorder recorder; + return recorder; + } + + void SetMainThread() { + t_Main = true; + } + + bool IsMainThread() { + return t_Main; + } + + int64_t NowNs() { + return std::chrono::duration_cast(std::chrono::steady_clock::now().time_since_epoch()).count(); + } + + int64_t UnixMs() { + return std::chrono::duration_cast(std::chrono::system_clock::now().time_since_epoch()).count(); + } + + const char* Intern(const std::string& name) { + // Never freed: scope trees point at these until the process ends + static auto* names = new std::unordered_set(); + static std::mutex mutex; + std::lock_guard lock(mutex); + return names->insert(name).first->c_str(); + } + + void BeginFrame() { + if (t_Main) Local().FrameBegin(NowNs(), UnixMs(), false); + } + + void EndFrame() { + if (!t_Main) return; + Local().FrameEnd(NowNs()); +#ifdef DLU_TRACY + ___tracy_emit_frame_mark(nullptr); +#endif + } + + FrameScope::FrameScope() { + if (!t_Main || Local().InFrame()) return; + m_Active = true; + Local().FrameBegin(NowNs(), UnixMs(), false); + } + + FrameScope::~FrameScope() { + if (!m_Active) return; + Local().FrameEnd(NowNs()); +#ifdef DLU_TRACY + ___tracy_emit_frame_mark(nullptr); +#endif + } + + Scope::Scope(const char* name, uint64_t arg) { + if (!t_Main) return; + m_Active = true; + Local().Enter(name, arg, NowNs()); +#ifdef DLU_TRACY + m_Tracy = TracyBegin(name, arg); +#endif + } + + Scope::Scope(const char* name, Phase phase) { + if (!t_Main) return; + m_Active = true; + const auto now = NowNs(); + auto& recorder = Local(); + recorder.Enter(name, 0, now); + m_Previous = recorder.SetPhase(phase, now); + m_SetPhase = true; +#ifdef DLU_TRACY + m_Tracy = TracyBegin(name, 0); +#endif + } + + Scope::~Scope() { + if (!m_Active) return; +#ifdef DLU_TRACY + TracyEnd(m_Tracy); +#endif + const auto now = NowNs(); + auto& recorder = Local(); + if (m_SetPhase) recorder.SetPhase(m_Previous, now); + recorder.Exit(now); + } + + PacketScope::PacketScope(const uint8_t* data, size_t length) { + if (!t_Main) return; + m_Active = true; + m_Key = TrafficStats::KeyOf(data, length, false).Packed(); + m_StartNs = NowNs(); + auto& recorder = Local(); + recorder.Enter(PACKET, m_Key, m_StartNs); + m_Previous = recorder.SetPhase(Phase::PACKETS, m_StartNs); + m_SetPhase = true; +#ifdef DLU_TRACY + m_Tracy = TracyBegin(PACKET, m_Key); +#endif + } + + PacketScope::~PacketScope() { + if (!m_Active) return; +#ifdef DLU_TRACY + TracyEnd(m_Tracy); +#endif + const auto now = NowNs(); + auto& recorder = Local(); + if (m_SetPhase) recorder.SetPhase(m_Previous, now); + recorder.Exit(now); + recorder.AddMessageTime(m_Key, now - m_StartNs); + } +} diff --git a/dCommon/Profiler.h b/dCommon/Profiler.h new file mode 100644 index 000000000..0f14013a1 --- /dev/null +++ b/dCommon/Profiler.h @@ -0,0 +1,274 @@ +#pragma once + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "TrafficStats.h" + +/** + * Frame timing and scope profiling of a server's main loop (see docs/Dashboard.md, "Performance"). + * + * Each server marks its main loop's frames (FrameScope) and named scopes inside them (Scope); a scope can also name the + * phase of the frame its time counts as (packets, entities, physics, ...). Everything is recorded on the main thread only: scopes on any other + * thread do nothing, so workers never touch this. Always on and cheap: two steady_clock reads and a short search of the + * current scope's children per scope; the frame's scope tree is reused from frame to frame. + * + * What comes out, every traffic report (dServer, SERVER_TRAFFIC's frames section): + * - per second: frames, total and longest frame time, a frame time histogram, and the time each phase took; + * - the packet types that took longest to handle; + * - the worst frames of the report with their phases and heaviest scopes; + * - slow frames (over the slow_frame_ms setting) with their scope tree, also logged as one line. + * On request, a profiling session merges every frame's scope tree for a few seconds into one tree (a flame graph). + * + * Scope names must live as long as the process (string literals, or names from Intern). + */ +namespace Profiler { + enum class Phase : uint8_t { OTHER, PACKETS, ENTITIES, PHYSICS, REPLICA, SCRIPTS, DATABASE, CDCLIENT, LOG_FLUSH, WEB, COUNT }; + constexpr size_t PHASES = static_cast(Phase::COUNT); + // "other", "packets", "entities", ...; "" past the known ones + const char* PhaseName(size_t phase); + + // Scope names whose argument means something to the dashboard + inline constexpr const char* PACKET = "Packet"; // arg: TrafficStats::MessageKey::Packed() + inline constexpr const char* COMPONENT = "Component"; // arg: eReplicaComponentType + inline constexpr const char* FRAME = "Frame"; // a main loop frame's root + inline constexpr const char* OUTSIDE = "Outside the main loop"; // the root of work before or between frames + + // One second of frames + struct Second { + int64_t time{}; // Unix seconds + uint32_t ticks{}; + uint64_t totalUs{}; + uint32_t maxUs{}; + TrafficStats::Histogram frames; // frame times + std::array phaseUs{}; + + void Merge(const Second& other); // adds (keeps this one's time) + }; + + // How long handling one packet type took (MessageKey::Packed) + struct MessageTime { + uint64_t key{}; + uint32_t count{}; + uint64_t totalUs{}; + uint32_t maxUs{}; + }; + + // A scope in a tree, in pre-order: children follow their parent with depth + 1 + struct Node { + std::string name; + uint64_t arg{}; + uint8_t depth{}; + uint32_t count{}; // times entered + uint64_t totalUs{}; // all of them together, children included + uint32_t startUs{}; // first entered, from the start of the frame (frames only) + bool operator==(const Node&) const = default; + }; + + struct Frame { + int64_t timeMs{}; // Unix milliseconds when it started + uint32_t durationUs{}; + bool implicit{}; // work outside the main loop's frames (startup, a web request between ticks) + std::array phaseUs{}; + std::vector scopes; // the heaviest scopes (and their parents), root first + + // "LoadPlayer > CreateEntity > Component 17: 58.1 s, CDClient Objects x9800", following the heaviest child + std::string Path(const std::function& label = {}) const; + }; + + struct Report { + bool present{}; // false in reports of servers too old to send frames + uint32_t slowThresholdMs{}; + std::vector seconds; // oldest first + std::vector messages; // longest total first + std::vector worst; // the longest frames of the report, longest first + std::vector slow; // frames over the threshold, oldest first + }; + + // What a profiling session collected: every frame's scopes merged + struct Profile { + uint32_t id{}; + uint32_t durationMs{}; // wall time it ran + uint32_t frames{}; + uint64_t totalUs{}; // time in frames (the rest the loop slept or waited) + bool truncated{}; // scopes were left out (too many) + std::vector nodes; // pre-order, root ("All frames") first; count and totalUs summed over the frames + }; + + // Folded stacks ("root;child;grandchild " per line), the format flame graph tools read + std::string Folded(const std::vector& nodes, const std::function& label = {}); + + // "name" or "name " when there is an argument + std::string DefaultLabel(const Node& node); + + class Recorder { + public: + static constexpr size_t MAX_NODES = 4096; // scopes one frame keeps apart; more are counted in their parent + static constexpr size_t MAX_CHILDREN = 64; // different children of one scope; more go to "(more)" + static constexpr size_t MAX_SESSION_NODES = 20000; + static constexpr size_t PROFILE_NODES = 3000; // scopes a finished session sends at most + static constexpr size_t SLOW_SCOPES = 40; // scopes a slow frame keeps + static constexpr size_t WORST_SCOPES = 12; // scopes a worst frame keeps + static constexpr size_t WORST_FRAMES = 3; // per report + static constexpr size_t MAX_SLOW_FRAMES = 8; // per report; more are only logged + static constexpr size_t TOP_MESSAGES = 16; // per report + static constexpr int64_t MAX_GAP = 120; // silent seconds a report fills in at most + static constexpr uint32_t MAX_SESSION_MS = 60000; + + // All of these: main thread (the explicit clock is for tests; Scope and friends read steady_clock) + void FrameBegin(int64_t nowNs, int64_t unixMs, bool implicit = false); + void FrameEnd(int64_t nowNs); + bool InFrame() const { return m_InFrame; } + void Enter(const char* name, uint64_t arg, int64_t nowNs); + void Exit(int64_t nowNs); + // The phase time goes to from now on; returns the one before + Phase SetPhase(Phase phase, int64_t nowNs); + // A finished piece of work of `durationNs` inside the current scope (a database statement timed elsewhere) + void Record(const char* name, uint64_t arg, int64_t durationNs, Phase phase, int64_t nowNs); + void AddMessageTime(uint64_t key, int64_t durationNs); + + // Any thread + void SetSlowThreshold(uint32_t milliseconds); + uint32_t SlowThreshold() const; + // Called on the main thread with each slow frame (dServer logs it); none by default + void SetSlowSink(std::function sink) { m_SlowSink = std::move(sink); } + + // Main thread. A session merges frames until `durationMs` passed (checked at the end of each frame), then + // calls `done`. One at a time: false when one runs already. + bool StartSession(uint32_t id, uint32_t durationMs, int64_t nowNs, std::function done); + // Ends it early (the result goes to `done` as usual); false when that session doesn't run + bool StopSession(uint32_t id, int64_t nowNs); + bool SessionActive() const { return m_Session.active; } + uint32_t SessionId() const { return m_Session.id; } + // Ends a session whose time is up, if no frame did (a loop that stopped framing) + void CheckSession(int64_t nowNs); + + // The seconds before `now` (Unix seconds) not reported yet, the message times, worst and slow frames since the + // last report; any thread + Report Take(int64_t now); + + private: + struct LiveNode { + const char* name{}; + uint64_t arg{}; + uint32_t parent{}; + uint32_t firstChild{}; // 0: none (node 0 is the root, never a child) + uint32_t nextSibling{}; + uint32_t children{}; + uint32_t count{}; + int64_t totalNs{}; + int64_t startNs{}; // first entered, from the start of the frame + }; + struct Open { + uint32_t node{}; + int64_t startNs{}; + bool counted{}; // false when it was folded into its parent (no room) + }; + struct Session { + bool active{}; + uint32_t id{}; + int64_t startNs{}; + int64_t endNs{}; + uint32_t frames{}; + int64_t totalNs{}; + bool truncated{}; + std::vector nodes; + std::function done; + }; + + static uint32_t Child(std::vector& nodes, uint32_t parent, const char* name, uint64_t arg, size_t maxNodes, bool& full); + // The `limit` heaviest nodes (and so their parents) in pre-order, children by first start or heaviest first + static std::vector Flatten(const std::vector& nodes, size_t limit, bool byStart, bool& truncated); + Frame MakeFrame(int64_t durationNs, size_t scopes) const; + void FinishSession(int64_t nowNs); + void MergeIntoSession(); + + // Main thread only + bool m_InFrame{}; + bool m_Implicit{}; + int64_t m_FrameStartNs{}; + int64_t m_FrameUnixMs{}; + std::vector m_Nodes; + std::vector m_Stack; + Phase m_Phase{ Phase::OTHER }; + int64_t m_PhaseStartNs{}; + std::array m_PhaseNs{}; + Session m_Session; + std::function m_SlowSink; + + // Shared with Take + mutable std::mutex m_Mutex; + uint32_t m_SlowThresholdMs{ 250 }; + std::map m_Seconds; + int64_t m_LastReported{}; + std::unordered_map m_Messages; + std::vector m_Worst; // longest first + std::vector m_Slow; + }; + + // This process's recorder + Recorder& Local(); + + // Marks the calling thread as the one whose scopes count (each server's main); the others' do nothing + void SetMainThread(); + bool IsMainThread(); + + int64_t NowNs(); // steady clock + int64_t UnixMs(); + + // A name that lives as long as the process, for scope names made at run time (main thread) + const char* Intern(const std::string& name); + + // A pass of the main loop begins or ends (FrameScope does both for a block); nothing off the main thread + void BeginFrame(); + void EndFrame(); + + // One pass of the main loop + class FrameScope { + public: + FrameScope(); + ~FrameScope(); + FrameScope(const FrameScope&) = delete; + FrameScope& operator=(const FrameScope&) = delete; + private: + bool m_Active{}; + }; + + // A named scope; with a phase, time inside it (less nested phases) counts as that phase + class Scope { + public: + explicit Scope(const char* name, uint64_t arg = 0); + Scope(const char* name, Phase phase); + ~Scope(); + Scope(const Scope&) = delete; + Scope& operator=(const Scope&) = delete; + private: + bool m_Active{}; + bool m_SetPhase{}; + Phase m_Previous{}; + uint64_t m_Tracy{}; // the Tracy zone, when built with DLU_TRACY + }; + + // Handling one packet: a PACKET scope named by its type, and its time counted for that type + class PacketScope { + public: + PacketScope(const uint8_t* data, size_t length); + ~PacketScope(); + PacketScope(const PacketScope&) = delete; + PacketScope& operator=(const PacketScope&) = delete; + private: + bool m_Active{}; + bool m_SetPhase{}; + Phase m_Previous{}; + uint64_t m_Key{}; + int64_t m_StartNs{}; + uint64_t m_Tracy{}; + }; +} diff --git a/tests/dCommonTests/CMakeLists.txt b/tests/dCommonTests/CMakeLists.txt index 98873d095..89d131177 100644 --- a/tests/dCommonTests/CMakeLists.txt +++ b/tests/dCommonTests/CMakeLists.txt @@ -33,6 +33,7 @@ set(DCOMMONTEST_SOURCES "PropertyReputationRulesTests.cpp" "BindAddressTests.cpp" "TrafficStatsTests.cpp" + "ProfilerTests.cpp" "Sd0Tests.cpp" "FdbReaderTests.cpp" ) diff --git a/tests/dCommonTests/ProfilerTests.cpp b/tests/dCommonTests/ProfilerTests.cpp new file mode 100644 index 000000000..66ed1766e --- /dev/null +++ b/tests/dCommonTests/ProfilerTests.cpp @@ -0,0 +1,303 @@ +#include + +#include "Profiler.h" + +#include + +using namespace Profiler; + +namespace { + constexpr int64_t MS = 1000000; // nanoseconds + constexpr int64_t UNIX_MS = 1700000000000; + + size_t PhaseIndex(Phase phase) { return static_cast(phase); } + + const Node* Find(const std::vector& nodes, const std::string& name) { + for (const auto& node : nodes) if (node.name == name) return &node; + return nullptr; + } +} + +TEST(ProfilerTest, FramesAddUpPerSecond) { + Recorder recorder; + int64_t now = 1000 * MS; + for (int i = 0; i < 3; i++) { + recorder.FrameBegin(now, UNIX_MS + i * 100); + recorder.Enter("Entities", 0, now); + recorder.SetPhase(Phase::ENTITIES, now); + now += 4 * MS; + recorder.SetPhase(Phase::OTHER, now); + recorder.Exit(now); + now += 1 * MS; + recorder.FrameEnd(now); + now += 30 * MS; // asleep + } + const auto report = recorder.Take(UNIX_MS / 1000 + 1); + ASSERT_TRUE(report.present); + ASSERT_EQ(report.seconds.size(), 1u); + const auto& second = report.seconds[0]; + EXPECT_EQ(second.time, UNIX_MS / 1000); + EXPECT_EQ(second.ticks, 3u); + EXPECT_EQ(second.totalUs, 15000u); + EXPECT_EQ(second.maxUs, 5000u); + EXPECT_EQ(second.frames.Count(), 3u); + EXPECT_EQ(second.phaseUs[PhaseIndex(Phase::ENTITIES)], 12000u); + EXPECT_EQ(second.phaseUs[PhaseIndex(Phase::OTHER)], 3000u); + // The longest frames, with their scopes + ASSERT_EQ(report.worst.size(), Recorder::WORST_FRAMES); + EXPECT_EQ(report.worst[0].durationUs, 5000u); + EXPECT_TRUE(report.slow.empty()); +} + +TEST(ProfilerTest, SecondsMerge) { + Second a{ .time = 10, .ticks = 2, .totalUs = 3000, .maxUs = 2000 }; + a.frames.Add(1000); + a.frames.Add(2000); + a.phaseUs[1] = 500; + Second b{ .time = 11, .ticks = 1, .totalUs = 9000, .maxUs = 9000 }; + b.frames.Add(9000); + b.phaseUs[1] = 250; + a.Merge(b); + EXPECT_EQ(a.time, 10); + EXPECT_EQ(a.ticks, 3u); + EXPECT_EQ(a.totalUs, 12000u); + EXPECT_EQ(a.maxUs, 9000u); + EXPECT_EQ(a.frames.Count(), 3u); + EXPECT_EQ(a.frames.Sum(), 12000u); + EXPECT_EQ(a.phaseUs[1], 750u); + // Merged histograms give the percentiles of all their frames + EXPECT_GE(a.frames.Percentile(1.0), 9000u * 9 / 10); +} + +TEST(ProfilerTest, SilentSecondsAreFilledIn) { + Recorder recorder; + const int64_t t = UNIX_MS / 1000; + recorder.FrameBegin(0, UNIX_MS); + recorder.FrameEnd(1 * MS); + auto report = recorder.Take(t + 1); + ASSERT_EQ(report.seconds.size(), 1u); + // A main loop stuck for 3 seconds: those seconds come as no frames + report = recorder.Take(t + 4); + ASSERT_EQ(report.seconds.size(), 3u); + EXPECT_EQ(report.seconds[0].time, t + 1); + EXPECT_EQ(report.seconds[2].ticks, 0u); +} + +TEST(ProfilerTest, SlowFrameCaptureHasItsScopes) { + Recorder recorder; + recorder.SetSlowThreshold(250); + std::vector logged; + recorder.SetSlowSink([&logged](const Frame& frame) { logged.push_back(frame); }); + + int64_t now = 0; + recorder.FrameBegin(now, UNIX_MS); + recorder.Enter(PACKET, 42, now); + recorder.SetPhase(Phase::PACKETS, now); + now += 1 * MS; + recorder.Enter("LoadPlayer", 0, now); + recorder.Enter("CreateEntity", 0, now); + for (int i = 0; i < 9800; i++) { + now += MS / 20; // 50 microseconds each + recorder.Record("CDClient Objects", 0, MS / 20, Phase::CDCLIENT, now); + } + recorder.Enter(COMPONENT, 17, now); + now += 60 * MS; + recorder.Exit(now); + recorder.Exit(now); // CreateEntity + recorder.Exit(now); // LoadPlayer + recorder.SetPhase(Phase::OTHER, now); + recorder.Exit(now); // packet + now += 2 * MS; + recorder.FrameEnd(now); + + ASSERT_EQ(logged.size(), 1u); + const auto report = recorder.Take(UNIX_MS / 1000 + 1); + ASSERT_EQ(report.slow.size(), 1u); + const auto& frame = report.slow[0]; + EXPECT_EQ(frame.timeMs, UNIX_MS); + EXPECT_EQ(frame.durationUs, 1000u + 490000u + 60000u + 2000u); + EXPECT_FALSE(frame.implicit); + EXPECT_EQ(frame.phaseUs[PhaseIndex(Phase::CDCLIENT)], 490000u); + EXPECT_EQ(frame.phaseUs[PhaseIndex(Phase::PACKETS)], 61000u); + EXPECT_EQ(frame.phaseUs[PhaseIndex(Phase::OTHER)], 2000u); + + // The tree, in pre-order with depths, children by when they started + ASSERT_EQ(frame.scopes.size(), 6u); + EXPECT_EQ(frame.scopes[0].name, FRAME); + EXPECT_EQ(frame.scopes[0].depth, 0); + EXPECT_EQ(frame.scopes[1].name, PACKET); + EXPECT_EQ(frame.scopes[1].arg, 42u); + EXPECT_EQ(frame.scopes[2].name, "LoadPlayer"); + EXPECT_EQ(frame.scopes[3].name, "CreateEntity"); + EXPECT_EQ(frame.scopes[3].depth, 3); + EXPECT_EQ(frame.scopes[4].name, "CDClient Objects"); + EXPECT_EQ(frame.scopes[4].count, 9800u); + EXPECT_EQ(frame.scopes[4].totalUs, 490000u); + EXPECT_EQ(frame.scopes[4].depth, 4); + EXPECT_EQ(frame.scopes[5].name, COMPONENT); + EXPECT_EQ(frame.scopes[5].totalUs, 60000u); + EXPECT_EQ(frame.scopes[2].totalUs, 550000u); + + const auto path = frame.Path(); + EXPECT_NE(path.find("LoadPlayer 550.0 ms > CreateEntity 550.0 ms > CDClient Objects 490.0 ms x9800"), std::string::npos) << path; + // Also in the report's worst frames, cut to fewer scopes + ASSERT_FALSE(report.worst.empty()); + EXPECT_EQ(report.worst[0].durationUs, frame.durationUs); +} + +TEST(ProfilerTest, SlowFramesKeepTheHeaviestScopesWithTheirParents) { + Recorder recorder; + recorder.SetSlowThreshold(1); + int64_t now = 0; + recorder.FrameBegin(now, UNIX_MS); + // Many light scopes and one heavy one deep down + for (int i = 0; i < 60; i++) { + recorder.Enter(Intern("light " + std::to_string(i)), 0, now); + now += MS / 100; + recorder.Exit(now); + } + recorder.Enter("a", 0, now); + recorder.Enter("b", 0, now); + recorder.Enter("heavy", 0, now); + now += 10 * MS; + recorder.Exit(now); + recorder.Exit(now); + recorder.Exit(now); + recorder.FrameEnd(now); + const auto report = recorder.Take(UNIX_MS / 1000 + 1); + ASSERT_EQ(report.slow.size(), 1u); + const auto& scopes = report.slow[0].scopes; + EXPECT_LE(scopes.size(), Recorder::SLOW_SCOPES + 1); + const auto* heavy = Find(scopes, "heavy"); + ASSERT_NE(heavy, nullptr); + EXPECT_EQ(heavy->depth, 3); + EXPECT_NE(Find(scopes, "a"), nullptr); + EXPECT_NE(Find(scopes, "b"), nullptr); +} + +TEST(ProfilerTest, TooManyDifferentChildrenShareOne) { + Recorder recorder; + int64_t now = 0; + recorder.SetSlowThreshold(1); + recorder.FrameBegin(now, UNIX_MS); + for (size_t i = 0; i < Recorder::MAX_CHILDREN + 10; i++) { + recorder.Enter("child", i + 1, now); + now += MS / 10; + recorder.Exit(now); + } + now += MS; + recorder.FrameEnd(now); + const auto report = recorder.Take(UNIX_MS / 1000 + 1); + ASSERT_EQ(report.slow.size(), 1u); + bool more = false; + for (const auto& node : report.slow[0].scopes) { + if (node.name == "(more)") { + more = true; + EXPECT_EQ(node.count, 10u); + } + } + EXPECT_TRUE(more); +} + +TEST(ProfilerTest, WorkOutsideFramesIsItsOwnFrame) { + Recorder recorder; + recorder.SetSlowThreshold(100); + std::vector logged; + recorder.SetSlowSink([&logged](const Frame& frame) { logged.push_back(frame); }); + // A scope with no frame open (a zone load at startup) is timed as one, but not counted as a tick + recorder.Enter("Zone load", 0, 0); + EXPECT_TRUE(recorder.InFrame()); + recorder.Exit(400 * MS); + EXPECT_FALSE(recorder.InFrame()); + ASSERT_EQ(logged.size(), 1u); + EXPECT_TRUE(logged[0].implicit); + EXPECT_EQ(logged[0].durationUs, 400000u); + ASSERT_EQ(logged[0].scopes.size(), 2u); + EXPECT_EQ(logged[0].scopes[0].name, OUTSIDE); + EXPECT_EQ(logged[0].scopes[1].name, "Zone load"); + const auto report = recorder.Take(Profiler::UnixMs() / 1000 + 1); + for (const auto& second : report.seconds) EXPECT_EQ(second.ticks, 0u); + ASSERT_EQ(report.slow.size(), 1u); +} + +TEST(ProfilerTest, SessionsMergeFramesIntoFoldedStacks) { + Recorder recorder; + std::optional result; + int64_t now = 0; + ASSERT_TRUE(recorder.StartSession(5, 1000, now, [&result](Profile&& profile) { result = std::move(profile); })); + EXPECT_FALSE(recorder.StartSession(6, 1000, now, [](Profile&&) {})); + for (int i = 0; i < 10; i++) { + recorder.FrameBegin(now, UNIX_MS); + recorder.Enter("Entities", 0, now); + now += 2 * MS; + recorder.Enter("Script timer", 0, now); + now += 1 * MS; + recorder.Exit(now); + recorder.Exit(now); + recorder.Enter("Physics step", 0, now); + now += 1 * MS; + recorder.Exit(now); + recorder.FrameEnd(now); + now += 30 * MS; + } + // Not yet: 340 ms of 1000 + EXPECT_FALSE(result.has_value()); + recorder.CheckSession(now + 1000 * MS); + ASSERT_TRUE(result.has_value()); + EXPECT_FALSE(recorder.SessionActive()); + EXPECT_EQ(result->id, 5u); + EXPECT_EQ(result->frames, 10u); + EXPECT_EQ(result->totalUs, 40000u); + EXPECT_FALSE(result->truncated); + ASSERT_EQ(result->nodes.size(), 4u); + EXPECT_EQ(result->nodes[0].name, "All frames"); + EXPECT_EQ(result->nodes[0].count, 10u); + // Heaviest child first + EXPECT_EQ(result->nodes[1].name, "Entities"); + EXPECT_EQ(result->nodes[1].count, 10u); + EXPECT_EQ(result->nodes[1].totalUs, 30000u); + EXPECT_EQ(result->nodes[2].name, "Script timer"); + EXPECT_EQ(result->nodes[2].depth, 2); + EXPECT_EQ(result->nodes[3].name, "Physics step"); + + // Folded stacks: each stack's own time + EXPECT_EQ(Folded(result->nodes), + "All frames;Entities 20000\n" + "All frames;Entities;Script timer 10000\n" + "All frames;Physics step 10000\n"); + // With labels (the dashboard names packets); ';' can't appear in a frame name + EXPECT_EQ(Folded({ { .name = "a;b", .count = 1, .totalUs = 5 } }, [](const Node& node) { return "x" + node.name; }), "xa,b 5\n"); +} + +TEST(ProfilerTest, SessionsStopEarly) { + Recorder recorder; + bool done = false; + ASSERT_TRUE(recorder.StartSession(1, 60000, 0, [&done](Profile&& profile) { done = true; EXPECT_EQ(profile.frames, 1u); })); + recorder.FrameBegin(0, UNIX_MS); + recorder.FrameEnd(MS); + EXPECT_FALSE(recorder.StopSession(2, MS)); + EXPECT_TRUE(recorder.StopSession(1, MS)); + EXPECT_TRUE(done); +} + +TEST(ProfilerTest, MessageTimesAreReportedLongestFirst) { + Recorder recorder; + recorder.AddMessageTime(1, 5 * MS); + recorder.AddMessageTime(2, 1 * MS); + recorder.AddMessageTime(1, 3 * MS); + const auto report = recorder.Take(10); + ASSERT_EQ(report.messages.size(), 2u); + EXPECT_EQ(report.messages[0].key, 1u); + EXPECT_EQ(report.messages[0].count, 2u); + EXPECT_EQ(report.messages[0].totalUs, 8000u); + EXPECT_EQ(report.messages[0].maxUs, 5000u); + EXPECT_TRUE(recorder.Take(11).messages.empty()); +} + +TEST(ProfilerTest, ScopesOffTheMainThreadDoNothing) { + // This test's thread isn't marked as a main thread: nothing is recorded in the process's recorder + { + Scope scope("Worker", Phase::DATABASE); + } + EXPECT_FALSE(Local().InFrame()); +} diff --git a/thirdparty/CMakeLists.txt b/thirdparty/CMakeLists.txt index 9a35d860a..d7bdaff29 100644 --- a/thirdparty/CMakeLists.txt +++ b/thirdparty/CMakeLists.txt @@ -209,6 +209,17 @@ if(DLU_OIDN) message(STATUS "Open Image Denoise ${OpenImageDenoise_VERSION}: the UGC server can denoise icons") endif() +# Tracy (BSD-3-Clause), a native profiler for deep dives: optional, off by default. Built with it, every server's +# frames and scopes (dCommon/Profiler.h) also go to Tracy's viewer, which connects to a running server (port 8086 and up; +# see docs/Dashboard.md, Performance). The dashboard's own profiling works without it. +option(DLU_TRACY "Build the servers with the Tracy profiler client" OFF) +if(DLU_TRACY) + set(TRACY_ON_DEMAND ON CACHE BOOL "Tracy collects only while a viewer is connected" FORCE) + FetchContent_Declare(tracy GIT_REPOSITORY https://github.com/wolfpld/tracy.git GIT_TAG v0.11.1 GIT_SHALLOW TRUE GIT_PROGRESS TRUE) + FetchContent_MakeAvailable(tracy) + message(STATUS "Tracy: the servers can be profiled with Tracy's viewer") +endif() + # HIPRT (MIT), the UGC server's ray_backend=hiprt on the GPU: optional, off by default. Needs HIPRT's SDK (its headers; # HIPRT_ROOT, else ROCm's /opt/rocm), whose library is loaded at run time (hiprtew), as HIP or CUDA are by Orochi (MIT, # fetched here; CUDA too when its toolkit is found). The headers are copied next to the servers: the GPU kernels are