util/profiler.cpp
| Line | Branch | Exec | Source |
|---|---|---|---|
| 1 | // SPDX-License-Identifier: BSD-3-Clause | ||
| 2 | /// @file profiler.cpp | ||
| 3 | /// @brief Frame and zone recording for the in-process profiler, and zone-tree reports with their | ||
| 4 | /// text, JSON and trace exports. | ||
| 5 | #include "ernie/util/profiler.h" | ||
| 6 | |||
| 7 | #include <nlohmann/json.hpp> | ||
| 8 | |||
| 9 | #include <algorithm> | ||
| 10 | #include <atomic> | ||
| 11 | #include <chrono> | ||
| 12 | #include <cstdio> | ||
| 13 | #include <deque> | ||
| 14 | #include <functional> | ||
| 15 | #include <map> | ||
| 16 | #include <mutex> | ||
| 17 | #include <set> | ||
| 18 | |||
| 19 | namespace ernie::profiler { | ||
| 20 | |||
| 21 | namespace { | ||
| 22 | |||
| 23 | std::atomic<bool> cpuEnabled{false}; | ||
| 24 | std::atomic<bool> gpuEnabled{false}; | ||
| 25 | |||
| 26 | struct State { | ||
| 27 | std::mutex mutex; | ||
| 28 | Frame current; | ||
| 29 | std::deque<Frame> frames; | ||
| 30 | std::size_t history = 300; | ||
| 31 | std::vector<std::string> threadNames; | ||
| 32 | }; | ||
| 33 | |||
| 34 | 812 | State& Global() { | |
| 35 | 812 | static State state; | |
| 36 | 812 | return state; | |
| 37 | } | ||
| 38 | |||
| 39 | thread_local std::uint32_t zoneDepth = 0; | ||
| 40 | |||
| 41 | } // namespace | ||
| 42 | |||
| 43 | 12 | void SetEnabled(bool on) { | |
| 44 | 12 | SetCpuEnabled(on); | |
| 45 | 12 | SetGpuEnabled(on); | |
| 46 | 12 | } | |
| 47 | |||
| 48 | ✗ | bool Enabled() { | |
| 49 | ✗ | return CpuEnabled() || GpuEnabled(); | |
| 50 | } | ||
| 51 | |||
| 52 | 23 | void SetCpuEnabled(bool on) { | |
| 53 | 23 | cpuEnabled.store(on, std::memory_order_relaxed); | |
| 54 | 23 | } | |
| 55 | |||
| 56 | 3525 | bool CpuEnabled() { | |
| 57 | 3525 | return cpuEnabled.load(std::memory_order_relaxed); | |
| 58 | } | ||
| 59 | |||
| 60 | 23 | void SetGpuEnabled(bool on) { | |
| 61 | 23 | gpuEnabled.store(on, std::memory_order_relaxed); | |
| 62 | 23 | } | |
| 63 | |||
| 64 | 450 | bool GpuEnabled() { | |
| 65 | 450 | return gpuEnabled.load(std::memory_order_relaxed); | |
| 66 | } | ||
| 67 | |||
| 68 | 987 | std::uint64_t Now() { | |
| 69 | 1974 | return static_cast<std::uint64_t>(std::chrono::duration_cast<std::chrono::nanoseconds>( | |
| 70 | 987 | std::chrono::steady_clock::now().time_since_epoch()) | |
| 71 | 987 | .count()); | |
| 72 | } | ||
| 73 | |||
| 74 | 14 | void BeginFrame() { | |
| 75 | 14 | State& s = Global(); | |
| 76 | 14 | const std::uint64_t now = Now(); | |
| 77 | 14 | std::lock_guard lock(s.mutex); | |
| 78 | 14 | if (s.current.start != 0) { | |
| 79 | 8 | s.current.end = now; | |
| 80 | 8 | s.frames.push_back(std::move(s.current)); | |
| 81 | 8 | while (s.frames.size() > s.history) { | |
| 82 | ✗ | s.frames.pop_front(); | |
| 83 | } | ||
| 84 | } | ||
| 85 | 14 | const std::uint64_t next = s.frames.empty() ? 0 : s.frames.back().index + 1; | |
| 86 | 14 | s.current = Frame{}; | |
| 87 | 14 | s.current.index = next; | |
| 88 | 14 | s.current.start = now; | |
| 89 | 14 | } | |
| 90 | |||
| 91 | 558 | std::uint64_t CurrentFrame() { | |
| 92 | 558 | State& s = Global(); | |
| 93 | 558 | std::lock_guard lock(s.mutex); | |
| 94 | 558 | return s.current.index; | |
| 95 | 558 | } | |
| 96 | |||
| 97 | 12 | std::vector<Frame> Frames() { | |
| 98 | 12 | State& s = Global(); | |
| 99 | 12 | std::lock_guard lock(s.mutex); | |
| 100 | 12 | return {s.frames.begin(), s.frames.end()}; | |
| 101 | 12 | } | |
| 102 | |||
| 103 | ✗ | void SetHistory(std::size_t frames) { | |
| 104 | ✗ | State& s = Global(); | |
| 105 | ✗ | std::lock_guard lock(s.mutex); | |
| 106 | ✗ | s.history = std::max<std::size_t>(frames, 1); | |
| 107 | ✗ | while (s.frames.size() > s.history) { | |
| 108 | ✗ | s.frames.pop_front(); | |
| 109 | } | ||
| 110 | ✗ | } | |
| 111 | |||
| 112 | ✗ | std::size_t History() { | |
| 113 | ✗ | State& s = Global(); | |
| 114 | ✗ | std::lock_guard lock(s.mutex); | |
| 115 | ✗ | return s.history; | |
| 116 | ✗ | } | |
| 117 | |||
| 118 | 4 | void Clear() { | |
| 119 | 4 | State& s = Global(); | |
| 120 | 4 | std::lock_guard lock(s.mutex); | |
| 121 | 4 | s.frames.clear(); | |
| 122 | 4 | s.current.cpu.clear(); | |
| 123 | 4 | s.current.gpu.clear(); | |
| 124 | 4 | } | |
| 125 | |||
| 126 | 176 | std::uint32_t ThreadIndex() { | |
| 127 | 212 | thread_local const std::uint32_t index = [] { | |
| 128 | 18 | State& s = Global(); | |
| 129 | 18 | std::lock_guard lock(s.mutex); | |
| 130 | 36 | s.threadNames.push_back("Thread " + std::to_string(s.threadNames.size())); | |
| 131 | 18 | return static_cast<std::uint32_t>(s.threadNames.size() - 1); | |
| 132 | 194 | }(); | |
| 133 | 176 | return index; | |
| 134 | } | ||
| 135 | |||
| 136 | 11 | void SetThreadName(std::string name) { | |
| 137 | 11 | const std::uint32_t index = ThreadIndex(); | |
| 138 | 11 | State& s = Global(); | |
| 139 | 11 | std::lock_guard lock(s.mutex); | |
| 140 | 11 | s.threadNames[index] = std::move(name); | |
| 141 | 11 | } | |
| 142 | |||
| 143 | 8 | std::vector<std::string> ThreadNames() { | |
| 144 | 8 | State& s = Global(); | |
| 145 | 8 | std::lock_guard lock(s.mutex); | |
| 146 | 8 | return s.threadNames; | |
| 147 | 8 | } | |
| 148 | |||
| 149 | 25 | const char* Intern(std::string_view name) { | |
| 150 | 25 | static std::mutex mutex; | |
| 151 | // Node-based: the strings never move. | ||
| 152 | 25 | static std::set<std::string, std::less<>> names; | |
| 153 | 25 | std::lock_guard lock(mutex); | |
| 154 | 25 | auto found = names.find(name); | |
| 155 | 25 | if (found == names.end()) { | |
| 156 | 19 | found = names.emplace(name).first; | |
| 157 | } | ||
| 158 | 25 | return found->c_str(); | |
| 159 | 25 | } | |
| 160 | |||
| 161 | 22 | void AddGpuZone(std::uint64_t frame, const Zone& zone) { | |
| 162 | 22 | State& s = Global(); | |
| 163 | 22 | std::lock_guard lock(s.mutex); | |
| 164 | 22 | if (frame == s.current.index) { | |
| 165 | 22 | s.current.gpu.push_back(zone); | |
| 166 | return; | ||
| 167 | } | ||
| 168 | ✗ | for (Frame& kept : s.frames) { | |
| 169 | ✗ | if (kept.index == frame) { | |
| 170 | ✗ | kept.gpu.push_back(zone); | |
| 171 | ✗ | return; | |
| 172 | } | ||
| 173 | } | ||
| 174 | 22 | } | |
| 175 | |||
| 176 | 3525 | ScopedZone::ScopedZone(const char* name) : name_(name) { | |
| 177 | 3525 | if (CpuEnabled()) { | |
| 178 | 165 | active_ = true; | |
| 179 | 165 | start_ = Now(); | |
| 180 | 165 | ++zoneDepth; | |
| 181 | } | ||
| 182 | 3525 | } | |
| 183 | |||
| 184 | 3690 | ScopedZone::~ScopedZone() { | |
| 185 | 3525 | if (!active_) { | |
| 186 | 3360 | return; | |
| 187 | } | ||
| 188 | 165 | --zoneDepth; | |
| 189 | 165 | Zone zone{name_, start_, Now(), ThreadIndex(), zoneDepth}; | |
| 190 | 165 | State& s = Global(); | |
| 191 | 165 | std::lock_guard lock(s.mutex); | |
| 192 | 165 | s.current.cpu.push_back(zone); | |
| 193 | 3525 | } | |
| 194 | |||
| 195 | // ---------------------------------------------------------------------------------------------- | ||
| 196 | // Reports | ||
| 197 | |||
| 198 | namespace { | ||
| 199 | |||
| 200 | /// Adds `zones`, ordered as they started, to the tree under `roots`, | ||
| 201 | /// each under the zone one level out that ran last; `ms` and `calls` | ||
| 202 | /// gather sums (nanoseconds) to be averaged. | ||
| 203 | 13 | void Gather(std::vector<ReportNode>& roots, std::vector<const Zone*> zones) { | |
| 204 | 13 | std::sort(zones.begin(), zones.end(), [](const Zone* a, const Zone* b) { | |
| 205 | 25 | return a->start != b->start ? a->start < b->start : a->depth < b->depth; | |
| 206 | }); | ||
| 207 | 13 | std::vector<ReportNode*> path; | |
| 208 | 45 | for (const Zone* zone : zones) { | |
| 209 | 32 | path.resize(std::min<std::size_t>(zone->depth, path.size())); | |
| 210 | 32 | std::vector<ReportNode>& siblings = path.empty() ? roots : path.back()->children; | |
| 211 | 32 | auto node = std::find_if(siblings.begin(), siblings.end(), | |
| 212 | 18 | [&](const ReportNode& n) { return n.name == zone->name; }); | |
| 213 | 32 | if (node == siblings.end()) { | |
| 214 | 20 | siblings.emplace_back().name = zone->name; | |
| 215 | 20 | node = siblings.end() - 1; | |
| 216 | } | ||
| 217 | 32 | node->ms += static_cast<double>(zone->end - zone->start); | |
| 218 | 32 | node->calls += 1.0; | |
| 219 | 32 | path.push_back(&*node); | |
| 220 | } | ||
| 221 | 13 | } | |
| 222 | |||
| 223 | /// Turns `Gather`'s sums over `frames` frames into means and shares | ||
| 224 | /// of `totalMs`. | ||
| 225 | 28 | void Average(std::vector<ReportNode>& nodes, double frames, double totalMs) { | |
| 226 | 48 | for (ReportNode& node : nodes) { | |
| 227 | 20 | node.ms = node.ms * 1e-6 / frames; | |
| 228 | 20 | node.calls /= frames; | |
| 229 | 20 | node.percent = totalMs > 0.0 ? 100.0 * node.ms / totalMs : 0.0; | |
| 230 | 20 | Average(node.children, frames, totalMs); | |
| 231 | } | ||
| 232 | 28 | } | |
| 233 | |||
| 234 | 32 | void AddRows(const std::vector<ReportNode>& nodes, const ReportFilter& filter, std::uint32_t depth, | |
| 235 | std::vector<ReportRow>& rows) { | ||
| 236 | // Siblings as they ran, or longest first (ties as they ran). | ||
| 237 | 32 | std::vector<const ReportNode*> order; | |
| 238 | 32 | order.reserve(nodes.size()); | |
| 239 | 48 | for (const ReportNode& node : nodes) { | |
| 240 | 16 | order.push_back(&node); | |
| 241 | } | ||
| 242 | 32 | if (filter.byTime) { | |
| 243 | 4 | std::stable_sort(order.begin(), order.end(), | |
| 244 | 1 | [](const ReportNode* a, const ReportNode* b) { return a->ms > b->ms; }); | |
| 245 | } | ||
| 246 | 48 | for (const ReportNode* node : order) { | |
| 247 | 16 | if (node->ms < filter.minMs) { | |
| 248 | 1 | continue; | |
| 249 | } | ||
| 250 | 15 | const std::size_t at = rows.size(); | |
| 251 | 15 | rows.push_back({node, depth, false}); | |
| 252 | 15 | if (depth < filter.depth) { | |
| 253 | 14 | AddRows(node->children, filter, depth + 1, rows); | |
| 254 | } | ||
| 255 | 15 | rows[at].parent = rows.size() > at + 1; | |
| 256 | } | ||
| 257 | 32 | } | |
| 258 | |||
| 259 | 8 | nlohmann::json ToJson(const std::vector<ReportNode>& nodes) { | |
| 260 | 8 | nlohmann::json zones = nlohmann::json::array(); | |
| 261 | 14 | for (const ReportNode& node : nodes) { | |
| 262 | 96 | zones.push_back({{"name", node.name}, | |
| 263 | 6 | {"ms", node.ms}, | |
| 264 | 6 | {"calls", node.calls}, | |
| 265 | 6 | {"percent", node.percent}, | |
| 266 | 6 | {"children", ToJson(node.children)}}); | |
| 267 | } | ||
| 268 | 8 | return zones; | |
| 269 | 84 | } | |
| 270 | |||
| 271 | 5 | std::string ThreadName(const std::vector<std::string>& names, std::uint32_t thread) { | |
| 272 | 7 | return thread < names.size() ? names[thread] : "Thread " + std::to_string(thread); | |
| 273 | } | ||
| 274 | |||
| 275 | } // namespace | ||
| 276 | |||
| 277 | 12 | Report Summarize(std::span<const Frame> frames, const std::vector<std::string>& threadNames) { | |
| 278 | 12 | Report report; | |
| 279 | 12 | std::map<std::uint32_t, std::vector<ReportNode>> threads; | |
| 280 | 19 | for (const Frame& frame : frames) { | |
| 281 | 7 | report.cpuMs += static_cast<double>(frame.end - frame.start); | |
| 282 | 7 | ++report.cpuFrames; | |
| 283 | 7 | std::map<std::uint32_t, std::vector<const Zone*>> byThread; | |
| 284 | 21 | for (const Zone& zone : frame.cpu) { | |
| 285 | 14 | byThread[zone.thread].push_back(&zone); | |
| 286 | } | ||
| 287 | 14 | for (auto& [thread, zones] : byThread) { | |
| 288 | 7 | Gather(threads[thread], std::move(zones)); | |
| 289 | } | ||
| 290 | 7 | if (frame.gpu.empty()) { | |
| 291 | 1 | continue; | |
| 292 | } | ||
| 293 | 6 | ++report.gpuFrames; | |
| 294 | 6 | std::vector<const Zone*> zones; | |
| 295 | 24 | for (const Zone& zone : frame.gpu) { | |
| 296 | 18 | zones.push_back(&zone); | |
| 297 | 18 | if (zone.depth == 0) { | |
| 298 | 6 | report.gpuMs += static_cast<double>(zone.end - zone.start); | |
| 299 | } | ||
| 300 | } | ||
| 301 | 6 | Gather(report.gpu, std::move(zones)); | |
| 302 | 7 | } | |
| 303 | 12 | if (report.gpuFrames > 0) { | |
| 304 | 4 | const double count = static_cast<double>(report.gpuFrames); | |
| 305 | 4 | report.gpuMs = report.gpuMs * 1e-6 / count; | |
| 306 | 4 | Average(report.gpu, count, report.gpuMs); | |
| 307 | } | ||
| 308 | 12 | if (report.cpuFrames > 0) { | |
| 309 | 4 | const double count = static_cast<double>(report.cpuFrames); | |
| 310 | 4 | report.cpuMs = report.cpuMs * 1e-6 / count; | |
| 311 | 8 | for (auto& [thread, roots] : threads) { | |
| 312 | 4 | Average(roots, count, report.cpuMs); | |
| 313 | 4 | ReportNode node; | |
| 314 | 4 | node.name = ThreadName(threadNames, thread); | |
| 315 | 8 | for (const ReportNode& root : roots) { | |
| 316 | 4 | node.ms += root.ms; | |
| 317 | } | ||
| 318 | 4 | node.calls = 1.0; | |
| 319 | 4 | node.percent = report.cpuMs > 0.0 ? 100.0 * node.ms / report.cpuMs : 0.0; | |
| 320 | 4 | node.children = std::move(roots); | |
| 321 | 4 | report.cpu.push_back(std::move(node)); | |
| 322 | 4 | } | |
| 323 | } | ||
| 324 | 12 | return report; | |
| 325 | 12 | } | |
| 326 | |||
| 327 | 18 | std::vector<ReportRow> Rows(const std::vector<ReportNode>& nodes, const ReportFilter& filter) { | |
| 328 | 18 | std::vector<ReportRow> rows; | |
| 329 | 18 | AddRows(nodes, filter, 0, rows); | |
| 330 | 18 | return rows; | |
| 331 | ✗ | } | |
| 332 | |||
| 333 | 1 | std::string ReportText(const Report& report, const ReportFilter& filter) { | |
| 334 | 1 | std::string text; | |
| 335 | 1 | char line[256]; | |
| 336 | 3 | const auto section = [&](const char* title, const std::vector<ReportNode>& nodes, | |
| 337 | double totalMs, std::size_t frames) { | ||
| 338 | // The section's total heads it; its zones below, indented. | ||
| 339 | 2 | std::snprintf(line, sizeof(line), "%-56s %12s %10s\n", "", "Duration (ms)", "Percent"); | |
| 340 | 2 | text += line; | |
| 341 | 4 | std::snprintf(line, sizeof(line), "%-56s %12.3f (%zu frames)\n", | |
| 342 | 4 | (std::string(title) + " total").c_str(), totalMs, frames); | |
| 343 | 2 | text += line; | |
| 344 | 8 | for (const ReportRow& row : Rows(nodes, filter)) { | |
| 345 | 6 | const std::string name = std::string(2 * (row.depth + 1), ' ') + row.node->name; | |
| 346 | 6 | std::snprintf(line, sizeof(line), "%-56s %12.3f %9.2f%%\n", name.c_str(), row.node->ms, | |
| 347 | 6 | row.node->percent); | |
| 348 | 6 | text += line; | |
| 349 | 8 | } | |
| 350 | 2 | text += "\n"; | |
| 351 | 2 | }; | |
| 352 | 1 | section("GPU", report.gpu, report.gpuMs, report.gpuFrames); | |
| 353 | 1 | section("CPU", report.cpu, report.cpuMs, report.cpuFrames); | |
| 354 | 1 | return text; | |
| 355 | ✗ | } | |
| 356 | |||
| 357 | 1 | std::string ReportJson(const Report& report) { | |
| 358 | 1 | const nlohmann::json json = { | |
| 359 | {"gpu", | ||
| 360 | 1 | {{"ms", report.gpuMs}, {"frames", report.gpuFrames}, {"zones", ToJson(report.gpu)}}}, | |
| 361 | {"cpu", | ||
| 362 | 26 | {{"ms", report.cpuMs}, {"frames", report.cpuFrames}, {"zones", ToJson(report.cpu)}}}}; | |
| 363 | 1 | return json.dump(2); | |
| 364 | 32 | } | |
| 365 | |||
| 366 | 1 | std::string TraceJson(std::span<const Frame> frames, const std::vector<std::string>& threadNames) { | |
| 367 | 1 | constexpr int kCpu = 1; | |
| 368 | 1 | constexpr int kGpu = 2; | |
| 369 | 1 | nlohmann::json events = nlohmann::json::array(); | |
| 370 | 16 | events.push_back( | |
| 371 | {{"name", "process_name"}, {"ph", "M"}, {"pid", kCpu}, {"args", {{"name", "CPU"}}}}); | ||
| 372 | 16 | events.push_back( | |
| 373 | {{"name", "process_name"}, {"ph", "M"}, {"pid", kGpu}, {"args", {{"name", "GPU"}}}}); | ||
| 374 | 19 | events.push_back({{"name", "thread_name"}, | |
| 375 | {"ph", "M"}, | ||
| 376 | {"pid", kGpu}, | ||
| 377 | 2 | {"tid", 0}, | |
| 378 | {"args", {{"name", "Queue"}}}}); | ||
| 379 | 1 | if (frames.empty()) { | |
| 380 | ✗ | return nlohmann::json{{"traceEvents", events}}.dump(); | |
| 381 | } | ||
| 382 | 1 | const std::uint64_t origin = frames.front().start; | |
| 383 | 25 | const auto us = [](double ns) { return ns * 1e-3; }; | |
| 384 | 1 | std::map<std::uint32_t, bool> threads; | |
| 385 | 3 | for (const Frame& frame : frames) { | |
| 386 | 42 | events.push_back({{"name", "Frame " + std::to_string(frame.index)}, | |
| 387 | {"ph", "X"}, | ||
| 388 | {"pid", kCpu}, | ||
| 389 | {"tid", "frames"}, | ||
| 390 | 4 | {"ts", us(static_cast<double>(frame.start - origin))}, | |
| 391 | 4 | {"dur", us(static_cast<double>(frame.end - frame.start))}}); | |
| 392 | 6 | for (const Zone& zone : frame.cpu) { | |
| 393 | 4 | threads[zone.thread] = true; | |
| 394 | 76 | events.push_back({{"name", zone.name}, | |
| 395 | {"ph", "X"}, | ||
| 396 | {"pid", kCpu}, | ||
| 397 | 4 | {"tid", zone.thread}, | |
| 398 | 8 | {"ts", us(static_cast<double>(zone.start - origin))}, | |
| 399 | 8 | {"dur", us(static_cast<double>(zone.end - zone.start))}}); | |
| 400 | } | ||
| 401 | 2 | std::uint64_t base = UINT64_MAX; | |
| 402 | 8 | for (const Zone& zone : frame.gpu) { | |
| 403 | 8 | base = std::min(base, zone.start); | |
| 404 | } | ||
| 405 | 8 | for (const Zone& zone : frame.gpu) { | |
| 406 | 114 | events.push_back({{"name", zone.name}, | |
| 407 | {"ph", "X"}, | ||
| 408 | {"pid", kGpu}, | ||
| 409 | 12 | {"tid", 0}, | |
| 410 | 12 | {"ts", us(static_cast<double>(frame.start - origin) + | |
| 411 | 6 | static_cast<double>(zone.start - base))}, | |
| 412 | 12 | {"dur", us(static_cast<double>(zone.end - zone.start))}}); | |
| 413 | } | ||
| 414 | } | ||
| 415 | 2 | for (const auto& [thread, used] : threads) { | |
| 416 | 19 | events.push_back({{"name", "thread_name"}, | |
| 417 | {"ph", "M"}, | ||
| 418 | {"pid", kCpu}, | ||
| 419 | {"tid", thread}, | ||
| 420 | ✗ | {"args", {{"name", ThreadName(threadNames, thread)}}}}); | |
| 421 | } | ||
| 422 | 7 | return nlohmann::json{{"traceEvents", events}, {"displayTimeUnit", "ms"}}.dump(); | |
| 423 | 234 | } | |
| 424 | |||
| 425 | } // namespace ernie::profiler | ||
| 426 |