Histogram FIFO commands by method

The per-command figure came back at 1017ns across 43870 commands per frame. That
is not a fair price for reading a word and calling a handler, so the cost is
concentrated in particular handlers rather than spread across the dispatch, and
the useful question is which.

Counts commands per method register and reports the top eight with their share,
named through gcm_printing so they read the same as the log's own FIFO traces.

A handful of methods dominating means a fast path is worth writing for them. An
even spread means the dispatch itself is the problem and this was the wrong tree.
Either way it is the last thing hidden inside fifo_decode, which now holds 44.6ms
of a 59.2ms frame with every sub-unit around it measured and small: ZCULL 0.111ms,
page protect 0.133ms, local tasks 1.357ms, the whole draw path under 6ms.

One increment behind the enabled() branch, no counter-timer read, 64KB of
counters touched only while armed.

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);

rpcs3/Emu/RSX/rsx_profiler.cpp

@@ -4,6 +4,9 @@
 #include "util/sysinfo.hpp"
 
 #include <string>
+#include <algorithm>
+#include <utility>
+#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<double>(decode_ticks) * to_ms * 1'000'000.0 / static_cast<double>(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<u32, u32> 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<double>(count) / frames,
+						static_cast<double>(count) * 100.0 / static_cast<double>(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;

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