From d6b56fa1e848e285a862536056daa9ce31523e35 Mon Sep 17 00:00:00 2001 From: AyeZeeBB Date: Sat, 17 Oct 2026 01:44:22 -0500 Subject: [PATCH] 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 | 7 ++ Engine/Core/Profiling/profiler_internal.h | 7 ++ Engine/Core/Profiling/sampler.cpp | 79 +++++++++++++++++++++++ 3 files changed, 93 insertions(+) diff --git a/Engine/Core/Profiling/profiler.cpp b/Engine/Core/Profiling/profiler.cpp index b730b9e..f513808 100644 --- a/Engine/Core/Profiling/profiler.cpp +++ b/Engine/Core/Profiling/profiler.cpp @@ -13,6 +13,9 @@ std::atomic zones_enabled{false}; namespace detail { std::atomic client_thread{0}, present_thread{0}; std::atomic sampling{false}; +std::atomic marking_presents{false}; +std::atomic present_mark_count{0}; +std::array, present_mark_capacity> present_marks{}; } namespace { std::atomic 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(); diff --git a/Engine/Core/Profiling/profiler_internal.h b/Engine/Core/Profiling/profiler_internal.h index 4e7f9dd..b366313 100644 --- a/Engine/Core/Profiling/profiler_internal.h +++ b/Engine/Core/Profiling/profiler_internal.h @@ -1,6 +1,7 @@ #pragma once #include "profiler.h" #include +#include 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 client_thread, present_thread; // True while a sample runs; keeps the monitor (and so the zones) alive. extern std::atomic 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 marking_presents; +extern std::atomic present_mark_count; +extern std::array, 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. diff --git a/Engine/Core/Profiling/sampler.cpp b/Engine/Core/Profiling/sampler.cpp index 0258ed1..83e7ba8 100644 --- a/Engine/Core/Profiling/sampler.cpp +++ b/Engine/Core/Profiling/sampler.cpp @@ -286,6 +286,12 @@ void run(SampleRequest request, std::vector 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::duration(request.seconds)); auto next = start; @@ -337,6 +343,18 @@ void run(SampleRequest request, std::vector threads) { } if (timer) CloseHandle(timer); close(); + // Each present, in microseconds into the sample as the samples are. + std::vector present_at; + if (presents) { + detail::marking_presents.store(false, std::memory_order_release); + const auto start_ns = static_cast(std::chrono::duration_cast(start.time_since_epoch()).count()); + const auto marked = std::min(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((at - start_ns) / 1000)); + } + std::ranges::sort(present_at); + } report.seconds = std::chrono::duration(std::chrono::steady_clock::now() - start).count(); report.progress = 1; @@ -487,6 +505,67 @@ void run(SampleRequest request, std::vector 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 gaps; + for (std::size_t i = 1; i < present_at.size(); ++i) gaps.push_back({present_at[i - 1], present_at[i]}); + std::vector lengths; + for (const auto& gap : gaps) lengths.push_back(gap.to - gap.from); + std::ranges::sort(lengths); + const auto median = std::max(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 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 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(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> 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{};