diff --git a/Engine/Core/Profiling/profiler.cpp b/Engine/Core/Profiling/profiler.cpp index b730b9e3..f5138083 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 4e7f9ddd..b366313f 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 0258ed18..83e7ba84 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{};