Add exclusive RSX thread time accounting

The overlay's RSX percentage measures what the thread is not doing: get_load()
counts everything outside four idle sites, so a thread decoding commands and a
thread spinning on a Vulkan fence both read as fully loaded. That is exactly the
distinction that decides what is worth optimising, and it could not be read off
any existing counter.

Splits RSX thread time into exclusive buckets instead. Entering a scope charges
elapsed time to whatever was active and switches, so nesting attributes to the
innermost scope and the totals sum to wall clock rather than double counting a
caller with its callee. Reports to the log every 300 frames, including an
explicit unscoped remainder so the percentages cannot read as complete coverage
when they are not.

Behind the "RSX Profiler" video setting, dynamic, so it can be armed once a
slowdown has already started. Off by default, costing one predictable branch per
scope. Accounting is per thread because some of these paths run on whichever
guest thread faulted rather than on RSX; only the RSX thread's copy is reported.

No optimisation here, only measurement.

rpcs3/Emu/CMakeLists.txt

@@ -574,6 +574,7 @@ target_sources(rpcs3_emu PRIVATE
     RSX/RSXThread.cpp
     RSX/RSXZCULL.cpp
     RSX/rsx_methods.cpp
+    RSX/rsx_profiler.cpp
     RSX/rsx_utils.cpp
     RSX/rsx_vertex_data.cpp
 )

rpcs3/Emu/RSX/NV47/HW/nv406e.cpp

@@ -1,85 +1,86 @@
-#include "stdafx.h"
-#include "nv406e.h"
-#include "nv47_sync.hpp"
-
-#include "Emu/RSX/RSXThread.h"
-
-#include "context_accessors.define.h"
-
-namespace rsx
-{
-	namespace nv406e
-	{
-		void set_reference(context* ctx, u32 /*reg*/, u32 arg)
-		{
-			RSX(ctx)->sync();
-
-			// Write ref+get (get will be written again with the same value at command end)
-			auto& dma = *vm::_ptr<RsxDmaControl>(RSX(ctx)->dma_address);
-			dma.get.release(RSX(ctx)->fifo_ctrl->get_pos());
-			dma.ref.store(arg);
-		}
-
-		void semaphore_acquire(context* ctx, u32 /*reg*/, u32 arg)
-		{
-			RSX(ctx)->sync_point_request.release(true);
-			const u32 addr = get_address(REGS(ctx)->semaphore_offset_406e(), REGS(ctx)->semaphore_context_dma_406e());
-
-			// Syncronization point, may be associated with memory changes without actually changing addresses
-			RSX(ctx)->m_graphics_state |= rsx::pipeline_state::fragment_program_needs_rehash;
-
-			const auto& sema = vm::_ref<RsxSemaphore>(addr);
+#include "stdafx.h"
+#include "nv406e.h"
+#include "nv47_sync.hpp"
+
+#include "Emu/RSX/RSXThread.h"
+#include "Emu/RSX/rsx_profiler.h"
+
+#include "context_accessors.define.h"
+
+namespace rsx
+{
+	namespace nv406e
+	{
+		void set_reference(context* ctx, u32 /*reg*/, u32 arg)
+		{
+			RSX(ctx)->sync();
+
+			// Write ref+get (get will be written again with the same value at command end)
+			auto& dma = *vm::_ptr<RsxDmaControl>(RSX(ctx)->dma_address);
+			dma.get.release(RSX(ctx)->fifo_ctrl->get_pos());
+			dma.ref.store(arg);
+		}
+
+		void semaphore_acquire(context* ctx, u32 /*reg*/, u32 arg)
+		{
+			RSX(ctx)->sync_point_request.release(true);
+			const u32 addr = get_address(REGS(ctx)->semaphore_offset_406e(), REGS(ctx)->semaphore_context_dma_406e());
+
+			// Syncronization point, may be associated with memory changes without actually changing addresses
+			RSX(ctx)->m_graphics_state |= rsx::pipeline_state::fragment_program_needs_rehash;
+
+			const auto& sema = vm::_ref<RsxSemaphore>(addr);
 			const auto& atomic_sema = vm::_ref<atomic_t<RsxSemaphore>>(addr);
-
-			if (sema == arg)
-			{
-				// Flip semaphore doesnt need wake-up delay
-				if (addr != RSX(ctx)->label_addr + 0x10)
-				{
-					RSX(ctx)->flush_fifo();
-					RSX(ctx)->fifo_wake_delay(2);
-				}
-
-				return;
-			}
-			else
-			{
-				RSX(ctx)->flush_fifo();
-			}
-
-			u64 start = get_system_time();
-			u64 last_check_val = start;
-
-			while (sema != arg)
-			{
-				if (RSX(ctx)->test_stopped())
-				{
-					RSX(ctx)->state += cpu_flag::again;
-					return;
-				}
-
-				if (const auto tdr = static_cast<u64>(g_cfg.video.driver_recovery_timeout))
-				{
-					const u64 current = get_system_time();
-
-					if (current - last_check_val > 20'000)
-					{
-						// Suspicious amnount of time has passed
-						// External pause such as debuggers' pause or operating system sleep may have taken place
-						// Ignore it
-						start += current - last_check_val;
-					}
-
-					last_check_val = current;
-
-					if ((current - start) > tdr)
-					{
-						// If longer than driver timeout force exit
-						rsx_log.error("nv406e::semaphore_acquire has timed out. semaphore_address=0x%X", addr);
-						break;
-					}
-				}
-
+
+			if (sema == arg)
+			{
+				// Flip semaphore doesnt need wake-up delay
+				if (addr != RSX(ctx)->label_addr + 0x10)
+				{
+					RSX(ctx)->flush_fifo();
+					RSX(ctx)->fifo_wake_delay(2);
+				}
+
+				return;
+			}
+			else
+			{
+				RSX(ctx)->flush_fifo();
+			}
+
+			u64 start = get_system_time();
+			u64 last_check_val = start;
+
+			while (sema != arg)
+			{
+				if (RSX(ctx)->test_stopped())
+				{
+					RSX(ctx)->state += cpu_flag::again;
+					return;
+				}
+
+				if (const auto tdr = static_cast<u64>(g_cfg.video.driver_recovery_timeout))
+				{
+					const u64 current = get_system_time();
+
+					if (current - last_check_val > 20'000)
+					{
+						// Suspicious amnount of time has passed
+						// External pause such as debuggers' pause or operating system sleep may have taken place
+						// Ignore it
+						start += current - last_check_val;
+					}
+
+					last_check_val = current;
+
+					if ((current - start) > tdr)
+					{
+						// If longer than driver timeout force exit
+						rsx_log.error("nv406e::semaphore_acquire has timed out. semaphore_address=0x%X", addr);
+						break;
+					}
+				}
+
 				if (RSX(ctx)->external_interrupt_lock ||
 					(RSX(ctx)->state & (cpu_flag::dbg_global_pause + cpu_flag::exit)) == cpu_flag::dbg_global_pause)
 				{
@@ -89,51 +90,53 @@ namespace rsx
 
 				RSX(ctx)->on_semaphore_acquire_wait();
 
+				RSX_PROF_SCOPE(idle);
+
 				// Wait until the value changes or until 100us pass.
 				utils::spin_on_cacheline_once(atomic_sema, sema, 100);
-			}
-
-			RSX(ctx)->fifo_wake_delay();
-			RSX(ctx)->performance_counters.idle_time += (get_system_time() - start);
-		}
-
-		void semaphore_release(context* ctx, u32 reg, u32 arg)
-		{
-			const u32 offset = REGS(ctx)->semaphore_offset_406e();
-
-			if (offset % 4)
-			{
-				rsx_log.warning("NV406E semaphore release is using unaligned semaphore, ignoring. (offset=0x%x)", offset);
-				return;
-			}
-
-			const u32 ctxt = REGS(ctx)->semaphore_context_dma_406e();
-
-			// By avoiding doing this on flip's semaphore release
-			// We allow last gcm's registers reset to occur in case of a crash
-			if (const bool is_flip_sema = (offset == 0x10 && ctxt == CELL_GCM_CONTEXT_DMA_SEMAPHORE_R);
-				!is_flip_sema)
-			{
-				RSX(ctx)->sync_point_request.release(true);
-			}
-
-			const u32 addr = get_address(offset, ctxt);
-
-			// TODO: Check if possible to write on reservations
-			if (RSX(ctx)->label_addr >> 28 != addr >> 28)
-			{
-				rsx_log.error("NV406E semaphore unexpected address. Please report to the developers. (offset=0x%x, addr=0x%x)", offset, addr);
-				RSX(ctx)->recover_fifo();
-				return;
-			}
-
-			if (addr == RSX(ctx)->device_addr + 0x30 && !arg)
-			{
-				// HW flip synchronization related, 1 is not written without display queue command (TODO: make it behave as real hw)
-				arg = 1;
-			}
-
-			util::write_gcm_label<false, true>(ctx, reg, addr, arg);
-		}
-	}
-}
+			}
+
+			RSX(ctx)->fifo_wake_delay();
+			RSX(ctx)->performance_counters.idle_time += (get_system_time() - start);
+		}
+
+		void semaphore_release(context* ctx, u32 reg, u32 arg)
+		{
+			const u32 offset = REGS(ctx)->semaphore_offset_406e();
+
+			if (offset % 4)
+			{
+				rsx_log.warning("NV406E semaphore release is using unaligned semaphore, ignoring. (offset=0x%x)", offset);
+				return;
+			}
+
+			const u32 ctxt = REGS(ctx)->semaphore_context_dma_406e();
+
+			// By avoiding doing this on flip's semaphore release
+			// We allow last gcm's registers reset to occur in case of a crash
+			if (const bool is_flip_sema = (offset == 0x10 && ctxt == CELL_GCM_CONTEXT_DMA_SEMAPHORE_R);
+				!is_flip_sema)
+			{
+				RSX(ctx)->sync_point_request.release(true);
+			}
+
+			const u32 addr = get_address(offset, ctxt);
+
+			// TODO: Check if possible to write on reservations
+			if (RSX(ctx)->label_addr >> 28 != addr >> 28)
+			{
+				rsx_log.error("NV406E semaphore unexpected address. Please report to the developers. (offset=0x%x, addr=0x%x)", offset, addr);
+				RSX(ctx)->recover_fifo();
+				return;
+			}
+
+			if (addr == RSX(ctx)->device_addr + 0x30 && !arg)
+			{
+				// HW flip synchronization related, 1 is not written without display queue command (TODO: make it behave as real hw)
+				arg = 1;
+			}
+
+			util::write_gcm_label<false, true>(ctx, reg, addr, arg);
+		}
+	}
+}

rpcs3/Emu/RSX/RSXFIFO.cpp

@@ -8,6 +8,7 @@
 #include "Emu/Memory/vm_reservation.h"
 #include "Emu/Cell/lv2/sys_rsx.h"
 #include "NV47/HW/context.h"
+#include "rsx_profiler.h"
 
 #include "util/asm.hpp"
 
@@ -131,6 +132,12 @@ namespace rsx
 				const bool force_cache_fill = g_cfg.core.rsx_fifo_accuracy == rsx_fifo_mode::atomic_ordered;
 				const bool strict_fetch_ordering = g_cfg.core.rsx_fifo_accuracy >= rsx_fifo_mode::atomic_ordered;
 
+				if (rsx::prof::enabled()) [[unlikely]]
+				{
+					rsx::prof::g_fifo_refills++;
+					rsx::prof::g_fifo_refill_bytes += m_cache_size;
+				}
+
 				rsx::reservation_lock<true, 1> rsx_lock(addr1, m_cache_size, true);
 				const auto src = vm::_ptr<spu_rdata_t>(addr1);
 
@@ -184,7 +191,10 @@ namespace rsx
 							return {};
 						}
 
-						m_thread->cpu_wait({});
+						{
+							RSX_PROF_SCOPE(idle);
+							m_thread->cpu_wait({});
+						}
 
 						const auto then = std::exchange(now, get_system_time());
 						start_time = now;
@@ -641,6 +651,8 @@ namespace rsx
 
 	void thread::run_FIFO()
 	{
+		RSX_PROF_SCOPE(fifo_decode);
+
 		FIFO::register_pair command;
 		fifo_ctrl->read(command);
 		const auto cmd = command.reg;

rpcs3/Emu/RSX/RSXThread.cpp

@@ -10,6 +10,7 @@
 #include "NV47/HW/context.h"
 #include "Program/GLSLCommon.h"
 #include "rsx_methods.h"
+#include "rsx_profiler.h"
 
 #include "gcm_printing.h"
 #include "RSXDisAsm.h"
@@ -3204,6 +3205,11 @@ namespace rsx
 
 	void thread::on_frame_end(u32 buffer, bool forced)
 	{
+		// Cheap enough to re-read every frame, and being able to arm the profiler while a
+		// slowdown is already happening matters more here than saving a config lookup.
+		prof::set_enabled(g_cfg.video.rsx_profiler.get());
+		prof::tick_frame();
+
 		bool pause_emulator = false;
 
 		// MM sync. This is a pre-emptive operation, so we can use a deferred request.
@@ -3429,7 +3435,10 @@ namespace rsx
 				if (target_rsx_flip_time > time + 1000)
 				{
 					const auto delay_us = target_rsx_flip_time - time;
-					lv2_obj::wait_timeout(delay_us, nullptr, false);
+					{
+						RSX_PROF_SCOPE(idle);
+						lv2_obj::wait_timeout(delay_us, nullptr, false);
+					}
 					performance_counters.idle_time += delay_us;
 				}
 			}

rpcs3/Emu/RSX/VK/VKGSRender.cpp

@@ -8,6 +8,7 @@
 #include "VKCommonPipelineLayout.h"
 #include "VKCompute.h"
 #include "VKGSRender.h"
+#include "Emu/RSX/rsx_profiler.h"
 #include "VKHelpers.h"
 #include "VKRenderPass.h"
 #include "VKResourceManager.h"
@@ -923,6 +924,8 @@ VKGSRender::~VKGSRender()
 
 bool VKGSRender::on_access_violation(u32 address, bool is_writing)
 {
+	RSX_PROF_SCOPE(texcache_lookup);
+
 	rsx::mm_flush(address);
 
 	vk::texture_cache::thrashed_set result;
@@ -1818,6 +1821,8 @@ void VKGSRender::do_local_task(rsx::FIFO::state state)
 
 bool VKGSRender::load_program()
 {
+	RSX_PROF_SCOPE(pipeline);
+
 	const auto shadermode = g_cfg.video.shadermode.get();
 
 	// TODO: EXT_dynamic_state should get rid of this sillyness soon (kd)
@@ -1986,6 +1991,8 @@ bool VKGSRender::load_program()
 
 void VKGSRender::load_program_env()
 {
+	RSX_PROF_SCOPE(descriptors);
+
 	if (!m_program)
 	{
 		fmt::throw_exception("Unreachable right now");
@@ -2368,6 +2375,8 @@ void VKGSRender::init_buffers(rsx::framebuffer_creation_context context, bool)
 
 void VKGSRender::close_and_submit_command_buffer(vk::fence* pFence, VkSemaphore wait_semaphore, VkSemaphore signal_semaphore, VkPipelineStageFlags pipeline_stage_flags)
 {
+	RSX_PROF_SCOPE(submit);
+
 	ensure(!m_queue_status.test_and_set(flush_queue_state::flushing));
 
 	// Host MM sync before executing anything on the GPU
@@ -2474,6 +2483,8 @@ void VKGSRender::close_and_submit_command_buffer(vk::fence* pFence, VkSemaphore
 
 void VKGSRender::prepare_rtts(rsx::framebuffer_creation_context context)
 {
+	RSX_PROF_SCOPE(rt_prep);
+
 	const bool clipped_scissor = (context == rsx::framebuffer_creation_context::context_draw);
 	if (m_current_framebuffer_context == context && !m_graphics_state.test(rsx::rtt_config_dirty) && m_draw_fbo)
 	{
@@ -2731,6 +2742,8 @@ void VKGSRender::renderctl(u32 request_code, void* args)
 
 bool VKGSRender::scaled_image_from_memory(const rsx::blit_src_info& src, const rsx::blit_dst_info& dst, bool interpolate)
 {
+	RSX_PROF_SCOPE(blit_resolve);
+
 	if (swapchain_unavailable)
 		return false;
 

rpcs3/Emu/RSX/VK/VKPresent.cpp

@@ -5,6 +5,7 @@
 #include "Emu/RSX/Overlays/overlay_manager.h"
 #include "Emu/RSX/Overlays/overlay_debug_overlay.h"
 #include "Emu/Cell/Modules/cellVideoOut.h"
+#include "Emu/RSX/rsx_profiler.h"
 
 #include "upscalers/bilinear_pass.hpp"
 #include "upscalers/fsr_pass.h"
@@ -615,6 +616,7 @@ void VKGSRender::flip(const rsx::display_flip_info_t& info)
 	ensure(m_current_frame->swap_command_buffer == nullptr);
 
 	u64 timeout = m_swapchain->get_swap_image_count() <= 2? 0ull: 100000000ull;
+	rsx::prof::scope acquire_scope{rsx::prof::bucket::present_wait};
 	while (VkResult status = m_swapchain->acquire_next_swapchain_image(m_current_frame->acquire_signal_semaphore, timeout, &m_current_frame->present_image))
 	{
 		switch (status)

rpcs3/Emu/RSX/VK/vkutils/sync.cpp

@@ -7,6 +7,7 @@
 #include "shared.h"
 
 #include "Emu/Cell/timers.hpp"
+#include "Emu/RSX/rsx_profiler.h"
 
 #include "util/sysinfo.hpp"
 #include "util/asm.hpp"
@@ -561,6 +562,8 @@ namespace vk
 
 	VkResult wait_for_fence(fence* pFence, u64 timeout)
 	{
+		RSX_PROF_SCOPE(fence_wait);
+
 		pFence->wait_flush();
 
 		if (timeout)
@@ -588,6 +591,8 @@ namespace vk
 
 	VkResult wait_for_event(event* pEvent, u64 timeout)
 	{
+		RSX_PROF_SCOPE(fence_wait);
+
 		// Convert timeout to TSC cycles. Timeout accuracy isn't super-important, only fast response when event is signaled (within 10us if possible)
 		const u64 freq = utils::get_tsc_freq();
 

rpcs3/Emu/RSX/rsx_profiler.cpp

@@ -0,0 +1,148 @@
+#include "stdafx.h"
+#include "rsx_profiler.h"
+
+#include "util/sysinfo.hpp"
+
+#include <string>
+
+LOG_CHANNEL(prof_log, "RSXPROF");
+
+namespace rsx::prof
+{
+	std::atomic<bool> g_enabled{false};
+	thread_local accounting g_acc{};
+	thread_local bucket g_current = bucket::unclassified;
+	thread_local u64 g_last_switch = 0;
+
+	const char* name_of(bucket b)
+	{
+		switch (b)
+		{
+		case bucket::fifo_decode: return "FIFO decode";
+		case bucket::draw_setup: return "Draw setup";
+		case bucket::vertex: return "Vertex/index";
+		case bucket::shader_translate: return "Shader translate";
+		case bucket::shader_compile: return "Shader compile";
+		case bucket::pipeline: return "Pipeline";
+		case bucket::descriptors: return "Descriptors";
+		case bucket::texcache_lookup: return "Texcache lookup";
+		case bucket::texture_upload: return "Texture upload";
+		case bucket::rt_prep: return "RT prep";
+		case bucket::blit_resolve: return "Blit/resolve";
+		case bucket::barrier: return "Barriers";
+		case bucket::cmdbuf: return "Cmdbuf record";
+		case bucket::submit: return "Submit";
+		case bucket::fence_wait: return "Fence wait";
+		case bucket::present_wait: return "Present wait";
+		case bucket::idle: return "Idle";
+		case bucket::unclassified: return "Unclassified";
+		default: return "?";
+		}
+	}
+
+	void set_enabled(bool enabled)
+	{
+		if (enabled == g_enabled.load(std::memory_order_relaxed))
+		{
+			return;
+		}
+
+		// Drop whatever was accumulated, so a window never straddles the switch and
+		// reports a partial frame's worth of one bucket against a full window.
+		g_acc = {};
+		g_acc.window_start = utils::get_tsc();
+		g_last_switch = g_acc.window_start;
+		// Arming happens from inside the RSX dispatch loop, so that is genuinely where we
+		// are. Without this the loop's scope, constructed back when the profiler was off,
+		// never became active and its time fell through to unclassified.
+		g_current = bucket::fifo_decode;
+
+		g_enabled.store(enabled, std::memory_order_relaxed);
+		prof_log.success("RSX profiling %s", enabled ? "enabled" : "disabled");
+	}
+
+	void tick_frame()
+	{
+		if (!g_enabled.load(std::memory_order_relaxed)) [[likely]]
+		{
+			return;
+		}
+
+		g_acc.frames++;
+
+		// Report on a frame boundary rather than a timer, so per-frame costs divide by a
+		// whole number of frames and a long stall lands in the window that contains it.
+		if (g_acc.frames >= 300)
+		{
+			dump_and_reset();
+		}
+	}
+
+	void dump_and_reset()
+	{
+		if (!g_acc.frames)
+		{
+			return;
+		}
+
+		const u64 now = utils::get_tsc();
+		const u64 freq = utils::get_tsc_freq();
+		const u64 window = now - g_acc.window_start;
+
+		if (!freq || !window)
+		{
+			g_acc = {};
+			g_acc.window_start = now;
+			return;
+		}
+
+		// Charge the in-flight bucket too, otherwise whatever is running at the moment of
+		// the dump is silently missing from its own report.
+		g_acc.ticks[static_cast<usz>(g_current)] += now - g_last_switch;
+		g_last_switch = now;
+
+		const double to_ms = 1000.0 / static_cast<double>(freq);
+		const double frames = static_cast<double>(g_acc.frames);
+
+		u64 accounted = 0;
+		for (const u64 t : g_acc.ticks)
+		{
+			accounted += t;
+		}
+
+		std::string report = fmt::format(
+			"RSX profile over %u frames, %.1f ms of thread time (%.2f ms/frame)",
+			g_acc.frames, static_cast<double>(window) * to_ms,
+			static_cast<double>(window) * to_ms / frames);
+
+		for (usz i = 0; i < bucket_count; i++)
+		{
+			const u64 ticks = g_acc.ticks[i];
+			if (!ticks)
+			{
+				continue;
+			}
+
+			fmt::append(report, "\n\t%-18s %7.3f ms/frame  %5.1f%%",
+				name_of(static_cast<bucket>(i)),
+				static_cast<double>(ticks) * to_ms / frames,
+				static_cast<double>(ticks) * 100.0 / static_cast<double>(window));
+		}
+
+		// A large gap means RSX thread time is going somewhere with no scope on it, which
+		// makes every percentage above an overestimate of its share. Worth saying so
+		// rather than letting the buckets read as if they covered the frame.
+		if (window > accounted)
+		{
+			const u64 gap = window - accounted;
+			fmt::append(report, "\n\t%-18s %7.3f ms/frame  %5.1f%%  (no scope)",
+				"Unscoped", static_cast<double>(gap) * to_ms / frames,
+				static_cast<double>(gap) * 100.0 / static_cast<double>(window));
+		}
+
+		prof_log.success("%s", report);
+
+		g_acc = {};
+		g_acc.window_start = now;
+	}
+}

rpcs3/Emu/RSX/rsx_profiler.h

@@ -0,0 +1,144 @@
+#pragma once
+
+#include "util/types.hpp"
+#include "util/tsc.hpp"
+
+#include <array>
+#include <atomic>
+
+/**
+ * Exclusive time accounting for the RSX thread.
+ *
+ * The overlay's RSX percentage cannot answer "what is the RSX thread doing", because it
+ * only measures what the thread is NOT doing: rsx::thread::get_load() counts everything
+ * except four idle sites (frame limiter sleep, FIFO starvation, FIFO spin, guest semaphore
+ * wait). A thread burning CPU decoding commands and a thread spinning on a Vulkan fence
+ * both read as 100% load, which is exactly the distinction that decides what to optimise.
+ *
+ * This splits that time into exclusive buckets. Exclusive, not inclusive: entering a scope
+ * charges the elapsed time to whatever bucket was active and then switches, so nested
+ * scopes attribute to the innermost one and the totals sum to wall-clock rather than
+ * double counting a caller and its callee.
+ *
+ * Reads the counter-timer directly rather than get_system_time(), because the fine scopes
+ * run thousands of times per frame. On Qualcomm the virtual counter ticks at 19.2MHz, so a
+ * single scope resolves to about 52ns; individual samples are coarse but the per-frame
+ * aggregate is not, which is what gets reported.
+ *
+ * Off by default and gated on a relaxed atomic load, so an untouched build pays for one
+ * predictable branch per scope.
+ */
+namespace rsx::prof
+{
+	enum class bucket : u8
+	{
+		fifo_decode,      // Reading and dispatching FIFO commands
+		draw_setup,       // Draw clause setup and state validation
+		vertex,           // Vertex and index processing, including layout conversion
+		shader_translate, // RSX shader decompilation to GLSL/SPIR-V
+		shader_compile,   // Host driver compiling the translated shader
+		pipeline,         // Vulkan pipeline lookup and creation
+		descriptors,      // Descriptor set lookup and update
+		texcache_lookup,  // Texture cache address search and match
+		texture_upload,   // Texture upload, deswizzle and format conversion
+		rt_prep,          // Render target allocation and binding
+		blit_resolve,     // Framebuffer copies, resolves and blits
+		barrier,          // Pipeline barriers and render pass transitions
+		cmdbuf,           // Command buffer recording
+		submit,           // Queue submission
+		fence_wait,       // Waiting on fences and events, including readback sync
+		present_wait,     // Swapchain acquire and present
+		idle,             // Deliberately idle: FIFO empty, frame limiter, semaphore
+		unclassified,     // RSX thread time not covered by any scope above
+
+		count
+	};
+
+	inline constexpr usz bucket_count = static_cast<usz>(bucket::count);
+
+	const char* name_of(bucket b);
+
+	/** Live totals in counter ticks, plus the frame count they were gathered over. */
+	struct accounting
+	{
+		std::array<u64, bucket_count> ticks{};
+		u64 frames = 0;
+		u64 window_start = 0;
+	};
+
+	extern std::atomic<bool> g_enabled;
+	extern thread_local accounting g_acc;
+	extern thread_local bucket g_current;
+	extern thread_local u64 g_last_switch;
+
+	/**
+	 * Charge elapsed time to the active bucket and make `next` active. Returns the old one.
+	 *
+	 * Per-thread, deliberately. Some of these scopes sit on paths that run on whichever
+	 * guest thread faulted rather than on the RSX thread: on_access_violation is reached
+	 * from the PPU or SPU that touched GPU-written memory. Sharing one accumulator would
+	 * mix another thread's wall clock into the RSX figures, and since the first switch on
+	 * a fresh thread has no previous timestamp it would charge `now` itself as a duration.
+	 * Only the RSX thread's copy is ever reported, so work attributed to a guest thread is
+	 * simply not counted rather than counted wrongly.
+	 */
+	inline bucket switch_to(bucket next)
+	{
+		const u64 now = utils::get_tsc();
+		const bucket prev = g_current;
+
+		// Zero means this thread has never switched, so there is no interval to charge.
+		if (g_last_switch) [[likely]]
+		{
+			g_acc.ticks[static_cast<usz>(prev)] += now - g_last_switch;
+		}
+
+		g_current = next;
+		g_last_switch = now;
+
+		return prev;
+	}
+
+	/** RAII bucket switch. Restores the enclosing bucket, so nesting attributes inward. */
+	class scope
+	{
+		bucket m_prev;
+		bool m_active;
+
+	public:
+		explicit scope(bucket b)
+			: m_prev(bucket::unclassified)
+			, m_active(g_enabled.load(std::memory_order_relaxed))
+		{
+			if (m_active) [[unlikely]]
+			{
+				m_prev = switch_to(b);
+			}
+		}
+
+		~scope()
+		{
+			if (m_active) [[unlikely]]
+			{
+				switch_to(m_prev);
+			}
+		}
+
+		scope(const scope&) = delete;
+		scope& operator=(const scope&) = delete;
+	};
+
+	/** Call once per frame from the RSX thread so the report can express per-frame cost. */
+	void tick_frame();
+
+	/** Write the current window to the log and start a new one. Safe to call from anywhere. */
+	void dump_and_reset();
+
+	void set_enabled(bool enabled);
+	inline bool enabled() { return g_enabled.load(std::memory_order_relaxed); }
+}
+
+// Two levels, so __LINE__ expands to its value before being pasted rather than literally.
+#define RSX_PROF_CAT_(a, b) a##b
+#define RSX_PROF_CAT(a, b) RSX_PROF_CAT_(a, b)
+#define RSX_PROF_SCOPE(b) ::rsx::prof::scope RSX_PROF_CAT(rsx_prof_scope_, __LINE__) { ::rsx::prof::bucket::b }

rpcs3/Emu/system_config.h

@@ -161,6 +161,10 @@ struct cfg_root : cfg::node
 		cfg::_bool strict_texture_flushing{ this, "Strict Texture Flushing", false };
 		cfg::_bool multithreaded_rsx{ this, "Multithreaded RSX", false };
 		cfg::_bool relaxed_zcull_sync{ this, "Relaxed ZCULL Sync", false };
+		// Splits RSX thread time into exclusive buckets and reports them to the log every
+		// 300 frames. Dynamic, so it can be turned on mid-session to catch a slowdown that
+		// only appears after a while. See Emu/RSX/rsx_profiler.h.
+		cfg::_bool rsx_profiler{ this, "RSX Profiler", false, true };
 		cfg::_bool force_hw_MSAA_resolve{ this, "Force Hardware MSAA Resolve", false, true };
 		cfg::_bool stereo_enabled{ this, "3D Display Enabled", false };
 		cfg::_enum<stereo_render_mode_options> stereo_render_mode{ this, "3D Display Mode", stereo_render_mode_options::disabled, true };