Release 0.4.2

A guest that stops progressing presents nothing further, so whatever was drawn
last stays on screen for good. When that frame held the boot progress bar it read
as stuck compiling at 1s remaining, and it looked identical across five unrelated
faults -- it sent every report of them to the wrong place, including this week's.
Nothing contradicted it either, since the emulator has not crashed and logs no
error.

Reports once, to the log and to the screen, after thirty seconds with no frame
and nothing claiming to be in progress. The progress text is what separates
working quietly from stopped: a shader or PPU compile presents no frames for
minutes and holds a dialog saying so. Drawing it needs the native UI flip,
because the guest is not flipping -- which is the point.

android/armsx3-ui/app/build.gradle.kts

@@ -29,8 +29,8 @@ android {
         applicationId = "com.armsx3"
         minSdk = 26
         targetSdk = 37
-        versionCode = 7
-        versionName = "0.4.1"
+        versionCode = 8
+        versionName = "0.4.2"
 
         // ARMSX2's UI reads these. STORAGE_ALL_FILES gates the all-files storage path in
         // onboarding; IN_APP_UPDATER gates the in-app GitHub-release updater.

rpcs3/Emu/Cell/SPULLVMRecompiler.cpp

@@ -1671,6 +1671,15 @@ public:
 					return nullptr;
 				}
 
+				// The owner finished and published nothing. It is not coming back, so
+				// waiting on `compiled` here is waiting forever -- state 2 is set after
+				// the publication it promises, so seeing it with nothing published means
+				// there is nothing to wait for.
+				if (add_loc->llvm_compile_state == 2)
+				{
+					return nullptr;
+				}
+
 				add_loc->compiled.wait(nullptr, atomic_wait_timeout{10'000'000});
 			}
 
@@ -1684,9 +1693,14 @@ public:
 		// of cold compilation work.
 		if (add_loc->llvm_compile_state.compare_and_swap(0, 1) != 0)
 		{
+			// Bounded, like the duplicate wait above. An untimed wait on a claim is only
+			// as sound as every path the owner can leave by, and a waiter that misses the
+			// transition waits for the rest of the session -- SPURS brings all its kernels
+			// to the same block at once, so it is five threads, and the game sits polling
+			// for an SPU that will never answer.
 			while (add_loc->llvm_compile_state == 1)
 			{
-				add_loc->llvm_compile_state.wait(1);
+				add_loc->llvm_compile_state.wait(1, atomic_wait_timeout{10'000'000});
 			}
 
 			if (add_loc->llvm_compile_state == 2)

rpcs3/Emu/RSX/RSXFIFO.cpp

@@ -715,6 +715,21 @@ namespace rsx
 			}
 			case FIFO::FIFO_EMPTY:
 			{
+				// Publish GET before going idle.
+				//
+				// GET is published on a bounded lag -- every eighth packet -- to keep a
+				// cross-cluster coherence miss off the per-packet path. That is only safe while
+				// something is still coming to flush it. Draining the ring is precisely when
+				// nothing is: the guest reads GET to see how far we have consumed, and with up
+				// to seven packets of lag frozen into it and no further packets to publish, it
+				// waits forever for progress that was made and never announced.
+				//
+				// Presents as a boot that hangs with the RSX perfectly healthy and idle, every
+				// guest thread in a legitimate wait, and sys_timer_usleep climbing -- and only
+				// when the packet count is not a multiple of eight as the ring drains, which is
+				// why it is game- and timing-dependent rather than reliable.
+				fifo_ctrl->sync_get_force();
+
 				if (performance_counters.state == FIFO::state::running)
 				{
 					performance_counters.FIFO_idle_timestamp = get_system_time();
@@ -729,7 +744,9 @@ namespace rsx
 			}
 			case FIFO::FIFO_BUSY:
 			{
-				// Do something else
+				// Do something else. Same reasoning as the empty case: this leaves the consume
+				// loop, so GET goes out rather than sitting behind the lag counter.
+				fifo_ctrl->sync_get_force();
 				return;
 			}
 			case FIFO::FIFO_ERROR:

rpcs3/Emu/RSX/RSXThread.cpp

@@ -25,6 +25,8 @@
 #include "Overlays/overlay_perf_metrics.h"
 #include "Overlays/overlay_debug_overlay.h"
 #include "Overlays/overlay_manager.h"
+#include "Overlays/overlay_message.h"
+#include "Emu/system_progress.hpp"
 
 #include "Utilities/date_time.h"
 
@@ -1062,11 +1064,27 @@ namespace rsx
 			u64 local_vblank_count = 0;
 
 			// TODO: exit condition
+			u64 last_heartbeat = 0;
+			u64 iterations = 0;
+
 			while (!is_stopped() && !unsent_gcm_events && thread_ctrl::state() != thread_state::aborting)
 			{
 				// Get current time
 				const u64 current = get_system_time();
 
+				// Heartbeat. This thread is the only source of the interrupt gcm waits on, so
+				// when it stops the guest hangs after gcm init with everything else looking
+				// idle -- and it said nothing either way. Distinguishes "still looping" from
+				// "blocked inside post_vblank_event" from "left the loop", which need
+				// different fixes and are indistinguishable from outside.
+				if (current - last_heartbeat >= 5'000'000)
+				{
+					last_heartbeat = current;
+					rsx_log.notice("VBlank: alive, iterations=%u, vblank_count=%u", iterations, local_vblank_count);
+				}
+
+				iterations++;
+
 				// Calculate the time at which we need to send a new VBLANK signal
 				const u64 post_event_time = start_time + (local_vblank_count + 1) * vblank_period / vblank_rate;
 
@@ -1124,6 +1142,13 @@ namespace rsx
 					start_time = get_system_time() - start_time;
 				}
 			}
+
+			// Which condition ended it. unsent_gcm_events is the savestate hand-off, so seeing
+			// it here outside a savestate means a live send failed and took the vblank source
+			// down with it -- permanently, since nothing restarts this thread.
+			rsx_log.error("VBlank: loop exited after %u iterations (stopped=%d, unsent_gcm_events=0x%x, aborting=%d)",
+				iterations, is_stopped() ? 1 : 0, unsent_gcm_events.load(),
+				thread_ctrl::state() == thread_state::aborting ? 1 : 0);
 		})));
 
 		struct join_vblank
@@ -1281,8 +1306,101 @@ namespace rsx
 		return t + timestamp_subvalue;
 	}
 
+	// Frame-stall notice. See check_frame_stall.
+	static atomic_t<u64> g_last_frame_time{0};
+	static atomic_t<bool> g_frame_stall_reported{false};
+
+	// Say when the picture has stopped, instead of leaving the last frame standing.
+	//
+	// A guest that stops progressing presents nothing further, so whatever was last drawn stays
+	// on screen indefinitely. When that frame happens to contain the boot progress bar, it reads
+	// as "stuck compiling at 1s remaining" -- and it looked exactly the same across five
+	// unrelated faults, sending every report of them to the wrong place. Nothing contradicts it
+	// either: the emulator has not crashed, so there is no error to be found.
+	//
+	// Only fires while nothing is legitimately in progress. A shader or PPU compile presents no
+	// frames for minutes at a time, and it holds a progress dialog that says as much, so an
+	// empty progress text is what separates "working, quietly" from "stopped".
+	static void check_frame_stall()
+	{
+		const u64 now = get_system_time();
+
+		// Something is reporting progress, or no frame has ever landed yet: not a stall.
+		if (g_progr_text || !g_last_frame_time)
+		{
+			g_last_frame_time = now;
+			g_frame_stall_reported = false;
+			return;
+		}
+
+		const u64 since = now - g_last_frame_time;
+
+		if (since < 30'000'000 || g_frame_stall_reported)
+		{
+			return;
+		}
+
+		g_frame_stall_reported = true;
+
+		rsx_log.error("No frame presented in %us with nothing in progress: the game has stopped.",
+			since / 1'000'000);
+
+		// Draw it, rather than logging into a file nobody has when they file the report. The
+		// native UI flip is what gets it on screen at all -- the guest is not flipping, which is
+		// the whole point.
+		rsx::overlays::queue_message(
+			std::string("Game has stopped responding - it is no longer drawing frames"),
+			10'000'000);
+
+		set_native_ui_flip();
+	}
+
+	// Say where every guest thread is parked once frames have stopped arriving.
+	//
+	// A hang with the RSX idle is a guest-side wait, and nothing named the thread or the place.
+	// The syscall stats report sys_timer_usleep without saying who called it, /proc shows a
+	// thread that never started as indistinguishable from one that is blocked, and the RSX
+	// profiler only covers this side of the boundary. Name, state, PC and the function each
+	// PPU is in separate all of those.
+	//
+	// idm::unlocked deliberately: this runs on the RSX thread, and taking the id lock here to
+	// diagnose a hang would add exactly the kind of dependency being diagnosed. A torn read of
+	// a diagnostic line costs nothing.
+	static void dump_guest_threads_stalled()
+	{
+		std::string out;
+
+		idm::select<named_thread<ppu_thread>>([&out](u32 id, ppu_thread& ppu)
+		{
+			const auto func = ppu.current_function ? ppu.current_function : ppu.last_function;
+
+			fmt::append(out, "\n  PPU 0x%07x '%s': state=%s cia=0x%08x %s func='%s'",
+				id, *ppu.ppu_tname.load(), ppu.state.load(), ppu.cia,
+				ppu.current_function ? "in" : "last", func ? func : "");
+		}, idm::unlocked);
+
+		rsx_log.error("Guest PPU threads while no frame has completed:%s", out);
+	}
+
 	void thread::do_local_task(FIFO::state state)
 	{
+		// Arm and poll from here as well as on_frame_end. Both of those run only once a frame
+		// has completed, so a boot that hangs before presenting left the profiler switched off
+		// and silent -- and that is the case where what the RSX thread is looping in is the
+		// whole question. Both calls return immediately once armed and are rate-limited.
+		prof::set_enabled(g_cfg.video.rsx_profiler.get());
+
+		// Always on, unlike the profiler-gated reports below: the whole point is that this
+		// reaches a user who has not enabled anything.
+		check_frame_stall();
+
+		// Both halves on the same condition. Every hang chased so far has been the guest
+		// waiting while the RSX idles, and only the RSX half was ever visible.
+		if (prof::poll_stall()) [[unlikely]]
+		{
+			dump_guest_threads_stalled();
+		}
+
 		m_eng_interrupt_mask.clear(rsx::backend_interrupt);
 
 		if (async_flip_requested & flip_request::emu_requested)
@@ -3272,6 +3390,9 @@ namespace rsx
 	{
 		// 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.
+		g_last_frame_time = get_system_time();
+		g_frame_stall_reported = false;
+
 		prof::set_enabled(g_cfg.video.rsx_profiler.get());
 		prof::tick_frame();
 

rpcs3/Emu/RSX/rsx_profiler.cpp

@@ -18,6 +18,11 @@ namespace rsx::prof
 	bucket g_current = bucket::unclassified;
 	u64 g_last_switch = 0;
 	const void* g_owner_thread = nullptr;
+
+	// Stall reporting state. See poll_stall.
+	u64 g_last_stall_check = 0;
+	u64 g_stall_frames = umax;
+	u64 g_stall_started = 0;
 	u64 g_fifo_refills = 0;
 	u64 g_fifo_commands = 0;
 	u64 g_fifo_dispatches = 0;
@@ -253,6 +258,65 @@ namespace rsx::prof
 		}
 	}
 
+	// Say what the RSX thread is sitting in when frames have stopped arriving.
+	//
+	// tick_frame is the only thing that reports and set_enabled is the only thing that arms,
+	// and both are reached from on_frame_end -- so a hang that happens before a frame completes
+	// leaves the profiler switched off and silent however the setting is set. That is exactly
+	// the case worth instrumenting: a boot that never presents, where the compile has finished
+	// and the thread is looping somewhere without consuming. Called from do_local_task, which
+	// the FIFO loop reaches whether or not frames advance.
+	bool poll_stall()
+	{
+		if (!g_enabled.load(std::memory_order_relaxed)) [[likely]]
+		{
+			return false;
+		}
+
+		// Only the thread the buckets are armed against; anyone else's clock is meaningless.
+		if (current_thread_token() != g_owner_thread)
+		{
+			return false;
+		}
+
+		const u64 freq = utils::get_tsc_freq();
+
+		if (!freq)
+		{
+			return false;
+		}
+
+		const u64 now = utils::get_tsc();
+
+		if (now - g_last_stall_check < freq * 5)
+		{
+			return false;
+		}
+
+		g_last_stall_check = now;
+
+		if (g_acc.frames != g_stall_frames)
+		{
+			// Frames are still arriving, so tick_frame is doing the reporting.
+			g_stall_frames = g_acc.frames;
+			g_stall_started = now;
+			return false;
+		}
+
+		if (!g_stall_started)
+		{
+			g_stall_started = now;
+			return false;
+		}
+
+		prof_log.error("RSX has not finished a frame in %.1fs; current bucket '%s', in it for %.2fs",
+			static_cast<double>(now - g_stall_started) / static_cast<double>(freq),
+			name_of(g_current),
+			static_cast<double>(now - g_last_switch) / static_cast<double>(freq));
+
+		return true;
+	}
+
 	void dump_and_reset()
 	{
 		if (!g_acc.frames)

rpcs3/Emu/RSX/rsx_profiler.h

@@ -505,6 +505,12 @@ namespace rsx::prof
 	/** Write the current window to the log and start a new one. Safe to call from anywhere. */
 	void dump_and_reset();
 
+	/** Report the bucket the RSX thread is stuck in when frames have stopped arriving.
+	 *  Rate-limited internally; safe to call from the FIFO loop.
+	 *  Returns true on the calls that actually reported, so a caller can attach its own
+	 *  diagnosis to the same condition without repeating the rate limit. */
+	bool poll_stall();
+
 	void set_enabled(bool enabled);
 	inline bool enabled() { return g_enabled.load(std::memory_order_relaxed); }
 }