Repository navigation
fix(vk): end the game with the GPU report when submitted work stops finishing - #2407
Conversation
…inishing NVIDIA's Xid 109 (CTX SWITCH TIMEOUT) can kill the game's GPU context without any Vulkan call returning VK_ERROR_DEVICE_LOST: the write-back waits keep returning VK_TIMEOUT and other threads sit in unbounded waits, so device_lost() never runs, the game freezes, and the log holds no checkpoint report. A watchdog thread, started at the first present, reads the timeline once a second. A device read as lost goes to device_lost(); work already sent to the queue that finishes nothing for RX_VK_GPU_HANG_SEC seconds (default 30) is logged as a hang and goes to device_lost() too: the checkpoint report, then the process ends. RX_VK_GPU_HANG_SEC=0 logs the stall and keeps waiting. Only submissions actually sent count, so a submission held back on the CPU side is not taken as a GPU hang. Refs NotRexed#1000 Co-authored-by: Cursor <cursoragent@cursor.com>
hckrman101
left a comment
There was a problem hiding this comment.
Looks good to me. A hang the driver never reports as lost is exactly the case device_lost() can't see, and reading the timeline from a side thread is the cheapest thing that can.
I went through the false-positive cases:
- Slow GPU / long frames: the counter resets on any progress, so it needs a single submission stuck for 30 s, and on Windows TDR would report the device lost long before that.
- Shader compile stalls (#2195), a paused game, batched submits on RADV: all of these hold work back on the CPU.
timeline_sentonly moves aftervkQueueSubmit2succeeds (and only on a flush when batching), sodone >= sentand the counter never runs. The same goes for a value held back as in #2222. - Minimised or hidden window: the only GPU-side wait is the present's
f.acquired. On Linux the acquire is already bounded at 100 ms on the CPU (the "window is not shown" path), so nothing gets queued behind an image that never comes back. On Windows the acquire returns before the semaphore matters. The 30 s margin plus=0covers whatever is left. - Suspend/resume, debugger: the watch counts its own 1 s ticks, not wall time, so a stopped process or a suspended machine doesn't add up.
The report path on a hung device: device_lost() → call_once(checkpoints_report) → replay_fatal → _Exit(3). It does no fence or semaphore waits, takes only watch_mu briefly, and if the main thread hits a real DEVICE_LOST at the same moment, call_once covers it. Nothing tears down the device at exit either, so the detached thread can't race a destroy. Parity is fine: plain std::thread/getenv, and the llvm-mingw back end builds.
Notes (none blocking):
- With the device hung but not lost,
vkGetQueueCheckpointDataNVis technically outside the spec (it requires the device to be in the lost state, and validation will flag it). On NVIDIA it should still return the last checkpoints, which is the point, but it hasn't been run in the game yet, so it's worth confirming the report actually has markers in it when this recurs. Related: when #2117 lands, its automaticvkGetDeviceFaultInfoEXTwill run on this path on a device that isn't lost. Whichever PR goes in second should check that the call returns there. The existing comment incheckpoints_reportalready says it may not return on NVIDIA, and the queued log is only flushed inreplay_fatal, after it. - The test takes ~15 s (three 5 s fixture runs). It's fine, but a shorter sleep in the fixture's
mainwould make it cheaper.
CI: the only failure is test_native_astc_texture_count.py on Windows (a scanf deprecation in its fixture). It fails the same way on main and isn't touched here. test_gpu_hang_watch.py passes on both Linux and Windows.
| static std::atomic<bool> started{false}; | ||
| if (!timeline || started.exchange(true)) return; | ||
| const char* e = getenv("RX_VK_GPU_HANG_SEC"); | ||
| const int limit = e ? std::max(0, atoi(e)) : 30; |
There was a problem hiding this comment.
Nit: atoi turns a typo (RX_VK_GPU_HANG_SEC=30s works, =abc doesn't) into 0, which silently switches the exit off. Logging the value it settled on once at start would make that visible.
There was a problem hiding this comment.
Done in 0361f50: the limit it settled on is logged at start, and with 0 it says the stall is only logged and shows the raw value it read, so =abc is visible.
| if (!timeline || started.exchange(true)) return; | ||
| const char* e = getenv("RX_VK_GPU_HANG_SEC"); | ||
| const int limit = e ? std::max(0, atoi(e)) : 30; | ||
| std::thread([limit] { |
There was a problem hiding this comment.
Nit: hang_watch_start() names its thread (SetThreadDescription(..., L"mkw_vk hang watch")). Doing the same here would make this one easy to tell apart in a hang dump.
There was a problem hiding this comment.
Done in 0361f50: named mkw_vk gpu hang watch.
| if (limit && still >= limit) { | ||
| logf("vk: GPU hang: no submission finished in %d s and the driver did not report the device lost (on " | ||
| "NVIDIA, journalctl -k names an Xid)", still); | ||
| device_lost(); |
There was a problem hiding this comment.
Nit: this ends in replay_fatal("the GPU device was lost (VK_ERROR_DEVICE_LOST)..."), so the stderr/FATAL line claims the driver returned DEVICE_LOST when here it didn't. The log line above it says so, but stderr (and anything that shows only the FATAL line) won't. A device_lost(const char* why = ...) overload or a flag would keep the two apart.
There was a problem hiding this comment.
Done in 0361f50: device_lost(const char* why = nullptr). The watch passes "the GPU hung: no submission finished in N s, and the driver never reported the device lost ...", and every other site keeps the VK_ERROR_DEVICE_LOST line. Both still share the one call_once report. test_device_lost_exit.py cuts the new signature, and test_gpu_hang_watch.py checks which line each path gives.
…hread, the limit logged - device_lost(why): the FATAL line says the GPU hung and the driver never reported it lost, instead of claiming VK_ERROR_DEVICE_LOST. The report stays once for both (the same call_once). - The thread is named "mkw_vk gpu hang watch", as hang_watch_start's is. - The limit it settled on is logged at start: atoi reads a typo as 0, which turned the exit off silently. - The test's fixture sleeps 3.5 s, not 5 (11 s for the test, was 15). Co-authored-by: Cursor <cursoragent@cursor.com>
|
Thanks for going through the false-positive cases. Besides the three nits, the fixture now sleeps 3.5 s (the test takes about 11 s, was 15). On the notes: I'll confirm the report has markers in it when the hang recurs. If #2117 lands first, I'll check here that
|
hckrman101
left a comment
There was a problem hiding this comment.
Re-checked at 0361f50. All three nits are done:
- The FATAL line now says what happened:
device_lost(why)gets "the GPU hung ... the driver never reported the device lost" from the watch, every other caller keeps the VK_ERROR_DEVICE_LOST text, and both still go through the onecall_oncereport. The test checks which line each path prints. - The limit is logged at start, and with 0 the raw value is shown, so
=abcno longer switches the exit off unnoticed. - The thread is named
mkw_vk gpu hang watch.
The test is down to about 11 s, which is fine.
The two notes stay notes. You plan to confirm the checkpoint markers when the hang happens again, and to check vkGetDeviceFaultInfoEXT on this path if #2117 lands first. That covers it.
CI: everything passes except Windows part 2/2, where the only failure is test_native_astc_texture_count.py (scanf deprecated under -Werror). That fails on main too and is fixed by #2397, so it isn't from this PR. No conflicts with main.
Good to merge from my side.
A GPU hang that the driver never reports as
VK_ERROR_DEVICE_LOSTfreezes the game for good and leaves no clue in the log about which GPU work died.device_lost()(#1275) only runs when a Vulkan call returns that error, and on NVIDIA's Xid 109 none does.What happened
RTX 4070 Ti, NVIDIA 595.99.02, Linux, sneaking into Hyrule Castle: the kernel logged
NVRM: Xid 109 ... name=hookshot ... CTX SWITCH TIMEOUT, and the game froze. The log's last lines are three offrom the main and presentation threads, and nothing after: the timeline stopped 4 short of what had been sent, the 250 ms write-back waits kept coming back
VK_TIMEOUT, and the other waits (recording_wait,wait_value) have no limit. No call returnedVK_ERROR_DEVICE_LOST, so the checkpoint report never ran.The change
hang_watch_start(), reads the timeline once a second (vkGetSemaphoreCounterValueonly: it needs no external synchronization, unlike the recordings' fences).device_lost().note_timeline_sent, at the two submissions that signal the timeline) that finishes nothing forRX_VK_GPU_HANG_SECseconds (default 30) is logged as a hang and goes todevice_lost(): the checkpoint report, the log flushed, exit code 3.RX_VK_GPU_HANG_SEC=0only logs the stall (at 10 s, then every 30 s) and lets the game wait.Trade-off
The present's submission waits for its swapchain image, and a window the system stops presenting could in principle hold the queue as long. That is why the limit is 30 s, not the few seconds a real GPU timeout takes, and why
=0exists. I have not seen it happen.Tests
tests/test_gpu_hang_watch.pycutsgpu_hang_watch_start()into a fixture with the timeline anddevice_lost()stubbed. A stuck timeline ends the process after the limit, a lost device ends it at once, and a moving timeline or=0never does. It also checks that both timeline-signalling submissions are counted and that the watch starts at the first present.tests/draw_stream_visibility_test.cppandtests/fsr_image_retirement_test.cppget anote_timeline_sentstub, since they compile the submit functions.python -I -B tests/run_all.pyon Linux: 381 passed, 15 skipped, 1 failed (test_make_game_cache.py, which fails the same way onmainwithout this change).vk_replay.cppbuilt withnx2/build.py's Vulkan flags.Complements #2117, which makes the report itself richer when there are no checkpoints. Refs #1000.