Profiler: a present sample lists its slowest frames, from one present to the next

A hitch on the render side never showed in a report: the client report lists slow client frames
only, and a present sample had no frames at all. While a present sample runs, the present hook
notes when each frame is presented; the report then lists the longest gaps between presents, each
with what the present thread's samples in it spent their time in and how many were waiting. This
is what found a 170 ms stall every 5 s: the game's batched GPU uploads blocking in the driver.

Engine/Core/Profiling/profiler.cpp

@@ -13,6 +13,9 @@ std::atomic<bool> zones_enabled{false};
 namespace detail {
 std::atomic<std::uint32_t> client_thread{0}, present_thread{0};
 std::atomic<bool> sampling{false};
+std::atomic<bool> marking_presents{false};
+std::atomic<std::uint32_t> present_mark_count{0};
+std::array<std::atomic<std::uint64_t>, present_mark_capacity> present_marks{};
 }
 namespace {
 std::atomic<Site*> sites{nullptr};
@@ -294,6 +297,10 @@ void record_client_frame(std::uint64_t frame_ns) noexcept {
 void record_present() noexcept {
     detail::present_thread.store(GetCurrentThreadId(), std::memory_order_relaxed);
     present_count.fetch_add(1, std::memory_order_relaxed);
+    if (detail::marking_presents.load(std::memory_order_relaxed)) {
+        const auto at = detail::present_mark_count.fetch_add(1, std::memory_order_relaxed);
+        if (at < detail::present_mark_capacity) detail::present_marks[at].store(now_ns(), std::memory_order_relaxed);
+    }
     if (!zones_enabled.load(std::memory_order_relaxed)) return;
     static std::uint64_t last{};
     const auto now = now_ns();

Engine/Core/Profiling/profiler_internal.h

@@ -1,6 +1,7 @@
 #pragma once
 #include "profiler.h"
 #include <Windows.h>
+#include <array>
 
 namespace dingosdk::profiler::detail {
 // Threads the summary and the sampler name: the one running the client update, and the one
@@ -8,6 +9,12 @@ namespace dingosdk::profiler::detail {
 extern std::atomic<std::uint32_t> client_thread, present_thread;
 // True while a sample runs; keeps the monitor (and so the zones) alive.
 extern std::atomic<bool> sampling;
+// While a sample of the present thread runs: when each frame was presented (now_ns), so its report
+// can give the slowest frames as the client one does. One writer, the present thread.
+constexpr std::size_t present_mark_capacity = 1 << 14;
+extern std::atomic<bool> marking_presents;
+extern std::atomic<std::uint32_t> present_mark_count;
+extern std::array<std::atomic<std::uint64_t>, present_mark_capacity> present_marks;
 // Starts the once-a-second monitor if anything wants it.
 void wake_monitor() noexcept;
 // What a thread is, for reports: its description, or what its start address belongs to.

Engine/Core/Profiling/sampler.cpp

@@ -286,6 +286,12 @@ void run(SampleRequest request, std::vector<Sampled> threads) {
 
     const HANDLE timer = CreateWaitableTimerExW(nullptr, nullptr, CREATE_WAITABLE_TIMER_HIGH_RESOLUTION, TIMER_ALL_ACCESS);
     const auto period = std::chrono::nanoseconds(1'000'000'000 / request.rate);
+    // Sampling the present thread: when each frame is presented, for its slowest frames.
+    const bool presents = request.target == Target::present;
+    if (presents) {
+        detail::present_mark_count.store(0, std::memory_order_relaxed);
+        detail::marking_presents.store(true, std::memory_order_release);
+    }
     const auto start = std::chrono::steady_clock::now();
     const auto finish = start + std::chrono::duration_cast<std::chrono::steady_clock::duration>(std::chrono::duration<double>(request.seconds));
     auto next = start;
@@ -337,6 +343,18 @@ void run(SampleRequest request, std::vector<Sampled> threads) {
     }
     if (timer) CloseHandle(timer);
     close();
+    // Each present, in microseconds into the sample as the samples are.
+    std::vector<std::uint32_t> present_at;
+    if (presents) {
+        detail::marking_presents.store(false, std::memory_order_release);
+        const auto start_ns = static_cast<std::uint64_t>(std::chrono::duration_cast<std::chrono::nanoseconds>(start.time_since_epoch()).count());
+        const auto marked = std::min<std::size_t>(detail::present_mark_count.load(std::memory_order_acquire), detail::present_mark_capacity);
+        for (std::size_t i = 0; i < marked; ++i) {
+            const auto at = detail::present_marks[i].load(std::memory_order_relaxed);
+            if (at > start_ns) present_at.push_back(static_cast<std::uint32_t>((at - start_ns) / 1000));
+        }
+        std::ranges::sort(present_at);
+    }
     report.seconds = std::chrono::duration<double>(std::chrono::steady_clock::now() - start).count();
     report.progress = 1;
 
@@ -487,6 +505,67 @@ void run(SampleRequest request, std::vector<Sampled> threads) {
             }
         }
 
+        // ---- the slowest presented frames: from one present to the next ----
+        // A hitch shows here as one long gap between presents. What the present thread did in it:
+        // the shares of its samples in that gap, and how many of them were waiting (on the GPU, the
+        // driver or another thread) rather than working.
+        if (presents && present_at.size() >= 9 && !records.empty()) {
+            struct Gap { std::uint32_t from{}, to{}; };
+            std::vector<Gap> gaps;
+            for (std::size_t i = 1; i < present_at.size(); ++i) gaps.push_back({present_at[i - 1], present_at[i]});
+            std::vector<std::uint32_t> lengths;
+            for (const auto& gap : gaps) lengths.push_back(gap.to - gap.from);
+            std::ranges::sort(lengths);
+            const auto median = std::max<std::uint32_t>(1, lengths[lengths.size() / 2]);
+            std::ranges::sort(gaps, [](const Gap& a, const Gap& b) { return a.to - a.from > b.to - b.from; });
+            hitches += std::format("Slowest presented frames, of {} (the usual one takes {:.1f} ms from one present to the next).\n"
+                                   "Under each: what the present thread spent that time in, as shares of its samples then.\n",
+                                   gaps.size(), median / 1000.0);
+            std::vector<std::uintptr_t> walked;
+            for (std::size_t n = 0; n < gaps.size() && n < 6; ++n) {
+                const auto& gap = gaps[n];
+                const auto length = gap.to - gap.from;
+                if (length < median * 2 && n) break;
+                std::unordered_map<std::uintptr_t, Counts> inner;
+                std::uint32_t samples{}, waited{};
+                // (The samples are in time order.)
+                const auto first = std::ranges::lower_bound(records, gap.from, {}, &Record::at_us);
+                for (auto it = first; it != records.end() && it->at_us < gap.to; ++it) {
+                    walked.clear();
+                    const auto* sample = pool.data() + it->offset;
+                    for (std::uint32_t f = 0; f < it->depth; ++f) {
+                        const Module* module{};
+                        walked.push_back(function_start(modules, f ? sample[f] - 1 : sample[f], &module));
+                        owners[walked.back()] = module;
+                    }
+                    if (walked.empty()) continue;
+                    ++samples;
+                    waited += waiting(name_of(walked.front(), owners[walked.front()])) ? 1u : 0u;
+                    for (std::size_t f = 0; f < walked.size(); ++f) {
+                        auto& counts = inner[walked[f]];
+                        counts.module = owners[walked[f]];
+                        if (!f) ++counts.self;
+                        const auto here = walked.begin() + static_cast<std::ptrdiff_t>(f);
+                        if (std::find(walked.begin(), here, walked[f]) == here) ++counts.total;
+                    }
+                }
+                hitches += std::format("\n  {:.1f} ms, {:.2f} s into the sample ({} samples, {:.0f}% of them waiting)\n", length / 1000.0,
+                    gap.from / 1e6, samples, samples ? 100.0 * waited / samples : 0.0);
+                if (!samples) continue;
+                std::vector<std::pair<std::uintptr_t, Counts>> order(inner.begin(), inner.end());
+                // The work, not the way down to it: what nearly every sample passes through is left out.
+                std::erase_if(order, [&](const auto& entry) { return entry.second.total * 100 >= samples * 97; });
+                std::ranges::sort(order, [](const auto& a, const auto& b) { return a.second.total > b.second.total; });
+                for (std::size_t i = 0; i < order.size() && i < 16; ++i)
+                    hitches += std::format("    {:5.1f}%  (self {:4.1f}%)  {}\n", 100.0 * order[i].second.total / samples,
+                        100.0 * order[i].second.self / samples, name_of(order[i].first, order[i].second.module));
+            }
+            hitches += "\n";
+        } else if (presents) {
+            hitches += std::format("No frame times: {} present(s) were seen while sampling (ReSkate's present hook notes them).\n\n",
+                                   present_at.size());
+        }
+
         // ---- files next to ReSkate.log ----
         const auto directory = logging::status().directory;
         SYSTEMTIME now{};