The watchdog was called under !Emu.IsPaused() && !Emu.IsStopped(). The
default IsStopped() overload is m_state <= system_state::stopping, and the
enum orders stopped, loading, stopping, running -- so it reports true for a
game that is LOADING.
A hang during a load is exactly what this watches for. Tales of Xillia 2
white-screens mid-load once its logos are skipped, so the guard skipped the
watchdog on every tick of the precise case it exists for, and skipped it
silently: not a declined decision anyone could read, just no call at all.
Nine minutes of held white screen produced no output whatsoever.
Use IsStopped(true), which is the fully-stopped test.
Also log the watchdog's decision once every 10s -- progress flag, last frame
timestamp, its age, dumps taken. Three attempts at this detector have failed
silently on a reproducible hang; the only evidence each time was an absence,
which cannot say which branch won. One line per ten seconds makes the next
failure a fact rather than another guess.
poll_frame_stall_watchdog returned early when g_last_frame_time was zero,
where the RSX-side check seeds it -- and seeding is what starts the clock.
Since the whole reason the watchdog exists is an RSX thread too stuck to run
that check, nothing ever seeded it: the value stayed zero and the watchdog
bailed on every tick forever, blocked in exactly the scenario it was written
for.
Reproduced on Tales of Xillia 2: white screen held for nearly nine minutes,
guest mutex traffic zero throughout, and not one dump.
check_frame_stall() runs from do_local_task, on the RSX thread's own FIFO
loop. That works for a guest-side hang with the RSX idle -- every hang chased
so far -- and is useless for the opposite case, where the RSX thread is the
one stuck. It never returns to do_local_task, so the detector that would
report the hang is starved by the hang.
Tales of Xillia 2 (BLUS31397) is exactly that. Reproduced on device: guest
mutex traffic at zero for minutes while sys_event_queue_receive and
sys_timer_usleep tick at flat identical rates, rsx::thread accumulating 4.99s
of CPU per 5s of wall clock, and NV406E_SEMAPHORE_ACQUIRE its costliest method
at 1.59ms a call. The RSX is spinning on a guest semaphore the stopped guest
will never write, and nothing reported any of it.
The same condition is now polled once a second from the PPU syscall usage
thread, which is independent and keeps running. That half only dumps; the
on-screen message and the native-UI flip stay on the RSX side, because the
overlay is not safe to drive from another thread. Both share one dump budget
so they cannot produce four dumps between them.
check_frame_stall() arms native-UI flipping when it reports a stall, so the
guest has something on screen while it is hung. Those synthetic flips reach
flip(), which finds nothing queued and calls on_frame_end(buffer, true), and
on_frame_end refreshed g_last_frame_time unconditionally. So the first hang of
a session switched on a flip source that then refreshed the timestamp forever,
and no later hang in that session could be detected at all.
Only a frame the guest actually produced counts as guest progress now.
Found on Tales of Xillia 2 (BLUS31397), which reproduces the same white screen
as Xillia 1: a stall was reported at 0:29:06, that game was closed, another was
booted, and when it hung 90 seconds later nothing fired. Guest mutex traffic
sat at exactly zero for over two minutes -- sys_event_queue_receive and
sys_timer_usleep continuing at flat, identical rates every interval, which is
idle service loops and nothing else -- while VKGSRender::flip kept running and
the detector kept believing frames were landing.
That is the one case this was written for: a hang where something still flips
looks perfectly healthy to a detector that only watches frames.
A callback the backend cannot fill completely is a hole in the output: the
device asked for N frames, the emulator did not have them, and the gap is
filled by repeating the last sample. That is what crackling IS, and nothing
counted it. The buffer-level report samples every ten seconds while a starved
callback lasts milliseconds, so every transient underrun passed between
samples unseen -- a Call of Duty: World at War capture shows a perfectly
healthy buffer (queued 22.7-48ms against a 36.7ms target, never near dry)
through a session where the audio was audibly breaking up.
Counted in AudioBackend rather than per backend so Cubeb and Oboe report the
same number the same way, one count per starved callback rather than per
padded frame -- the audible event is the gap, and its length is already
implied by how much of the callback had to be invented.
Reported on the existing audio line as a delta since the previous one, not a
running total: what matters is whether the output is breaking up now, and a
total from a rough patch minutes ago hides that.
There was exactly one previous log: RPCSX.log became RPCSX.old.log and the
previous old was deleted. That loses the capture reliably, because of how
people send it -- play, stop, relaunch the app to reach the file, and the
relaunch rotates the wanted session into .old; relaunch once more, to find it
or to share it or because the launcher restored the app, and it is gone.
Three captures have been lost this way (#87, #91, and the Call of Duty audio
one). In two of them what arrived was a 47-line log ending before the game had
booted, which is the replacement session rather than the one played.
Two defences, because generations alone would not have saved those:
1. A session that produced almost nothing does not get a slot. The logs that
did the damage were boot-only -- a few KB, stopping within a second of
launch -- and pushing one of those down the chain is what evicted the real
capture. Below the threshold the file is discarded instead. A session with
'Silence All Logs' on still writes far more than this (~190 KB for a
29-minute one), so that setting does not trip it.
2. Three generations instead of one, so an ordinary mistake costs nothing.
Ported from ARMSX2. Android has no supported API for SoC temperatures --
HardwarePropertiesManager is gated behind the signature-level DEVICE_POWER --
so the only route is the thermal sysfs, which is readable without permission
on essentially every device but is not a contract: zone count, order, naming
and even the unit are all vendor-specific. So the app discovers zones once by
name, tolerates every failure by having no reading, and never displays a value
it could not actually read. A device that exposes nothing shows nothing, which
is a normal outcome rather than an error.
The core cannot read these and should not learn how, so the app pushes them in
through _rpcsx_setThermals into atomics beside the overlay. The overlay line is
appended after the detail-level switch, the same way the frame generation line
is, so all four levels get it without their format strings and positional
arguments having to agree.
The sentinel is -1000.0f on both sides. ARMSX2 spells the Kotlin half
Float.MIN_VALUE, which in Kotlin is the smallest POSITIVE float (1.4e-45) and
so arrives as a real temperature of 0 degrees rather than as absent; worth
correcting there too.
Default on, poll interval configurable 1-5s (default 2s) since sensor overhead
was the concern raised when this was asked for. No realtime option: a
temperature that moves slower than a second is not worth the syscalls.
It stays a feature -- the hotkey, the touch button and the OSD indicator are
untouched -- it just no longer occupies a tile in either panel.
Removing it also repairs the Session grid's controller dispatch, which was
broken. EmulationMenuViewModel indexes three things by the same number: the
grid in SessionPane, actionCount(), and activateSelection(). Fast-forward sat
at index 1 in the grid and had no entry in activateSelection, so every index
from 1 up dispatched to its neighbour -- a pad press on Fast Forward restarted
the game, Restart swapped the disc, Swap Disc closed the game, and Close could
not be activated at all. actionCount had been corrected to 5 to let the pad
reach the last tile, which made the misalignment reachable rather than fixing
it. With the tile gone the grid is resume/restart/swap/close, exactly what
activateSelection already dispatched, and actionCount goes to 4.
Touch users are unaffected: the grid is tapped by index through onSelect, so
it was always correct there. This only ever misfired for a controller.
Upstream bc22df8ba skips waking waiters after a SUCCESSFUL conditional store
when the SPU sits at pc 0x11e4 with the SPURS control block reserved, unless
byte 0x73 of that block shows this thread going running->idle. It is a
throughput optimisation: SPURS kernels store to that block constantly and
waking every waiter each time is a thundering herd.
Both constants are assumptions about one specific SPURS kernel build. 0x11e4
is a guest code address and 0x73 an offset inside the guest's control block,
and SPURS ships in many versions across titles. On a kernel whose layout
differs, the running->idle test reads the wrong byte, answers no forever, and
the store succeeds while every waiter stays asleep -- reported by nothing.
Tales of Xillia (BLUS31006) hangs with all five graphics SPUs reserving that
block, each suppressing ~100,000 notifications, ~4.85M conditional stores at
a 16.5% failure rate. Its SPURS kernel then executes its own HALT at
pc=0x00f00: r16 & r17 = 0x40000000, two workload masks that must be disjoint
both claiming workload bit 30. The group never joins, no frame is ever
presented again, and every PPU thread parks.
Whether the missed wakeups cause that inconsistency or merely accompany it is
NOT established. What is established is that notifying is correct and
suppressing is the optimisation, so the optimisation goes. Expect a
throughput cost on SPURS-heavy titles; it is measurable and revertable.
The counter is kept, now recording how often the heuristic would have
suppressed, so that cost shows up in a log instead of being guessed at.
The stall report picked its detailed SPU by raddr == spurs_addr -- a kernel
waiting on its own control block, i.e. an IDLE one -- on the assumption that
every kernel parks at the same pc so any of them would do. Tales of Xillia
is the counter-example: one graphics kernel executed a guest HALT and sits
stopped at pc=0x00f00 while the other four idle normally at 0x011a8, so the
rule picked an idle SPU. The only thread in the process with anything to say
printed no registers at all.
A stopped, halted or exited SPU now wins outright, chosen in a pass before
the walk. Nothing else in a SPURS group stops on its own, so if one has, it
is why the group never joined and the rest are only waiting on it.
Also dump all 128 GPRs rather than the first 16. Xillia's assertion is a
validity check over r12/r16/r17/r19/r33/r34, so the sixteen that were printed
did not include a single operand of the test the log had just disassembled.
average_playtime_ratio divided m_average_playtime -- a rolling average of
get_enqueued_playtime(), in microseconds -- by audio_buffer_length, which is
a sample count (AUDIO_BUFFER_SAMPLES * channels, 512 for stereo). The result
was microseconds per sample: roughly 78 on a healthy stereo buffer and never
below 1, so the 'not as full as desired' branch it gates has not executed
once since it was written. The buffer target has therefore always been the
fixed desired_buffer_duration + half a block, with the adaptive widening
silently inert.
Wrong from introduction rather than drifted: m_average_playtime has been a
duration since before that line existed. audio_buffer_length had no other
reader anywhere in the tree, which is why nothing caught it; it is deleted
here so it cannot be picked up again by mistake.
The denominator is now desired_buffer_duration, which is what the comment
above it names and the only choice that makes the branch meaningful --
audio_block_period would leave the ratio near 7 and the branch just as dead.
Guarded against a zero denominator, and the existing max(ratio, 0.25) clamp
still bounds the widening at 4x.
This arms a path that has effectively never run, so it changes behaviour for
every game: a consistently under-filled buffer now raises the target instead
of being ignored, trading latency for fewer dropouts. That is what it was
written to do. The audio buffer report added alongside prints the ratio, so
the effect is visible in a log rather than inferred.
Progressive audio delay keeps being reported (#87: Guitar Hero titles, where
audio starts synchronised and falls further behind the notes the longer a
song runs, and pausing resets it). It reproduces on both Cubeb and Oboe, so
it is not the backend -- it is this ring, and how full this ring is IS the
delay the player hears. It was recorded nowhere, so every theory about it is
unfalsifiable from the logs we receive.
One line per 10s: queued depth, the target the algorithm is aiming for, and
the dynamic period as a percentage of nominal, which says how hard it is
correcting. Enough to see the curve across a song; few enough that the log
volume cannot become a stall in its own right.
Noted while reading the algorithm, deliberately NOT changed here:
average_playtime_ratio divides m_average_playtime (microseconds) by
audio_buffer_length (samples times channels, 512 for stereo), so it reads
about 78 when healthy and its 'not as full as desired' branch has never once
executed. The intended denominator is a duration. Correcting it would arm a
widening path that has effectively never run, which raises latency in exactly
the under-buffered case -- the opposite of the symptom being chased. It wants
its own change, with the numbers this report will provide.
check_frame_stall() already detects a hang reliably and always-on: it
reports "No frame presented in 30s" and puts a message on screen. But the
one thing that says WHERE the guest is parked -- dump_guest_threads_stalled(),
which prints every PPU thread's registers, guest call stack and the
instructions around its cia, plus SPU state -- was only ever reached from the
RSX profiler's poll_stall(), and that returns false immediately unless the
profiler is switched on. Testers do not switch it on.
So every freeze report arrives with the detection line and nothing behind
it. Confirmed against a Kane & Lynch (BLUS30102) capture: guest execution
collapsed at 0:04:15 -- sys_mutex_lock fell from ~200,000 per 10s to ~300,
CPU from 43% to 5.5% -- and this fired at 0:04:45 having recorded none of
it. Three such reports across two different SoCs, none reproducible locally,
all equally undiagnosable.
Call it from the detector instead. Twice, ~15s apart, because one sample
cannot tell a thread spinning from one making very slow progress -- a cia
that has not moved between two samples is itself the finding. Twice and no
more, and re-armed only when a frame actually lands: the detail runs to
hundreds of lines per thread, and log volume alone is enough to stall the
emulator on Android. The profiler path is unchanged.
port_new opened with "if (g_started) return 1". That was defensible while
gl1's state was whatever the previous saver left behind, but nativeInit now
calls gl1_lost() before every create, so gl1 is guaranteed DOWN on entry.
Reporting success there would hand the caller a saver with no shim under it.
So the gl1_lost() added alongside the leak fix did not just close the leak,
it turned that early return from redundant into wrong -- its safety rested
on a call-graph property that same change removed. All six ports now tear
down a stale run through port_free and always run gl1_init(). Each needs a
forward declaration of port_free, which is defined below port_new.
No behaviour change on any path reachable today: port_free always clears
g_started, so the guard never fires. The point is that a saver added later,
or an upstream cleanup that returns early, should fail in its own saver
rather than poison the next one -- the same reason port_free tears gl1 down
unconditionally.
Adapted from the ARMSX2 change (be674a64c5).
Ported from the ARMSX2 fix; ARMSX3 had the same bug, plus a sixth saver.
A saver that dies natively made the app unlaunchable. The choice is a
persisted pref read on the library screen -- the first screen -- so the
crash repeated on every launch and Settings was never reachable to turn it
off. The only escape was clearing app data, which takes memory cards and
save states with it.
Cause: gl1's state is a file-scope global holding GL object names, and
gl1_init() early-returns on g.ready. Skyrocket and Lattice defer initSaver()
to port_resize, so a create-then-teardown with no surface size left
g_started false and their port_free returned BEFORE gl1_shutdown(); flux,
plasma and solarwinds leaked it the other way, since returning 0 when
initSaver() leaves readyToDraw clear means port_free is never called at all.
Either way g.ready stayed set with names from a destroyed EGL context, and
the next saver -- new view, new context -- drew against them. Drivers answer
that with anything from a black screen to a segfault.
Every port now gives gl1 back on every exit, unconditionally, so the rule
holds by construction rather than by arguing about which paths are
reachable. gl1_lost() already existed here but was never called; nativeInit
calls it now as the standing invariant, so a new context cannot inherit old
GL names even if a saver added later forgets.
Containment, independent of the fix: native GL can always find a new way to
die, so the setting arms itself with a synchronous commit() before the
render thread starts and disarms when that thread exits in an orderly way.
Still armed at startup means the last run died with a saver up -- the
background switches off and a toast names it. A crash or a kill cannot reach
the disarm; that is the entire signal.
Also guards Thread.start(): it asks for a 16MB stack (Skyrocket declares a
3MB starmap as a local) and an OutOfMemoryError there is an uncaught throw
on the main thread -- the same lockout with no native crash involved.
The backend asked for the guest's rate with sample rate conversion
disabled, then recorded the rate it ASKED for rather than the one the
stream actually opened at. A device that cannot run at the guest rate
opens at its own, and with conversion off nothing resamples -- so the
emulator feeds samples at one rate into a device consuming them at
another. That is a permanent rate mismatch, not a one-off pitch error:
the gap between what is heard and what is on screen grows for as long as
playback continues, and nothing downstream can see it, because every
later calculation (including the buffering algorithm's idea of how much
audio is queued) uses the rate we requested.
Check the opened rate and, on a mismatch, reopen letting Oboe convert.
Converting is a worse signal path than matching rates outright and a far
better one than not converting at all; Cubeb resamples for the same
reason. If the rate is still wrong after that, say so in the log rather
than drifting in silence.
Refs #87
jpolo1224