diff --git a/rpcs3/Emu/RSX/RSXFIFO.cpp b/rpcs3/Emu/RSX/RSXFIFO.cpp index e9d9b4465..fc1d1078e 100644 --- a/rpcs3/Emu/RSX/RSXFIFO.cpp +++ b/rpcs3/Emu/RSX/RSXFIFO.cpp @@ -912,6 +912,8 @@ namespace rsx m_ctx->register_state->decode(reg, value); + if (rsx::prof::enabled()) [[unlikely]] rsx::prof::g_method_counts[reg & (rsx::prof::method_slot_count - 1)]++; + if (auto method = methods[reg]) { method(m_ctx, reg, value); diff --git a/rpcs3/Emu/RSX/rsx_profiler.cpp b/rpcs3/Emu/RSX/rsx_profiler.cpp index f75c26909..d7fd2e5d7 100644 --- a/rpcs3/Emu/RSX/rsx_profiler.cpp +++ b/rpcs3/Emu/RSX/rsx_profiler.cpp @@ -4,6 +4,9 @@ #include "util/sysinfo.hpp" #include +#include +#include +#include "gcm_printing.h" LOG_CHANNEL(prof_log, "RSXPROF"); @@ -16,6 +19,7 @@ namespace rsx::prof const void* g_owner_thread = nullptr; u64 g_fifo_refills = 0; u64 g_fifo_commands = 0; + u32 g_method_counts[method_slot_count] = {}; u64 g_fifo_refill_bytes = 0; u64 g_fifo_refill_stalls = 0; u64 g_fifo_refill_stall_us = 0; @@ -249,9 +253,40 @@ namespace rsx::prof static_cast(decode_ticks) * to_ms * 1'000'000.0 / static_cast(g_fifo_commands)); } + { + // Top methods by volume. Names via gcm_printing, which is the same table the + // command dumps use, so these read the same as the log's own FIFO traces. + std::pair top[8] = {}; + for (u32 i = 0; i < method_slot_count; i++) + { + if (!g_method_counts[i]) continue; + if (g_method_counts[i] <= top[7].second) continue; + top[7] = { i, g_method_counts[i] }; + std::sort(std::begin(top), std::end(top), + [](const auto& a, const auto& b) { return a.second > b.second; }); + } + + if (top[0].second) + { + std::string list; + for (const auto& [slot, count] : top) + { + if (!count) continue; + std::string scratch; + const auto name = rsx::get_method_name(slot << 2, scratch).second; + fmt::append(list, "\n\t %-46s %8.0f/frame %4.1f%%", + name.empty() ? fmt::format("0x%05x", slot << 2) : std::string(name), + static_cast(count) / frames, + static_cast(count) * 100.0 / static_cast(g_fifo_commands)); + } + fmt::append(report, "\n\ttop methods%s", list); + } + } + prof_log.success("%s", report); g_fifo_commands = 0; + std::fill(std::begin(g_method_counts), std::end(g_method_counts), 0u); g_fifo_refills = 0; g_fifo_refill_bytes = 0; g_fifo_refill_stalls = 0; diff --git a/rpcs3/Emu/RSX/rsx_profiler.h b/rpcs3/Emu/RSX/rsx_profiler.h index a7afd006d..5542c6fe8 100644 --- a/rpcs3/Emu/RSX/rsx_profiler.h +++ b/rpcs3/Emu/RSX/rsx_profiler.h @@ -189,6 +189,19 @@ namespace rsx::prof */ extern u64 g_fifo_commands; + /** + * Commands seen per RSX method register, indexed by (id >> 2). + * + * The per-command figure came out around a microsecond, which is far too much for + * reading a word and calling a handler, so the cost is in a handler rather than spread + * evenly. Counting says which methods make up the volume; a handful dominating means a + * fast path is worth writing, an even spread means the dispatch itself is the problem. + * + * 64KB of counters, only touched while profiling is armed. + */ + inline constexpr usz method_slot_count = 0x4000; + extern u32 g_method_counts[method_slot_count]; + // Refills that could not take their data immediately and fell into the retry spin, plus // the microseconds burned there. That spin is billed to the FIFO bucket rather than to // idle, so without these there is no way to tell RSX doing work from RSX waiting on the