fix(vk): a readback's wait for its write-back ends after 250 ms #2222

Merged
Brett-D merged 1 commit from fix/readback-wait-limit into main 2026-11-11 22:42:36 +00:00
Brett-D commented 2026-11-11 09:05:50 +00:00 (Migrated from github.com)

Problem

invalidate() waits for a GPU result's write-back before the CPU reads it. When the recordings' timeline doesn't know the value (wait_recorded returns false), it falls back to wait_value(v), which waits on the main timeline without a limit.

On a Steam Deck (RADV, no buffer mirrors, queues replayed in submit order with RX_VK_EVENT_WAITS=0), this hung the game for good right after a save loaded:

  • 2 of 8 starts with default settings, and 4 of 4 with RX_VK_CAPTURE_WAIT=0.
  • Under gdb, the game's main thread and one of its jobs were both in invalidate -> wait_value -> drmSyncobjTimelineWait, the presentation thread was idle, and the kernel logged no GPU timeout.
  • The new log line shows the value had been submitted but the timeline stayed one short while they waited, e.g. write-back 26867 ... (done 26866, submitted 26868, handed out 26868).

Change

  • readback_wait_value() waits at most RX_VK_READBACK_WAIT_MS (default 250). This matches the capture's vk_timeline_wait, which already gives up after 250 ms for the same reason ("a submission held back behind the caller's thread goes on without it"). Past the limit, the CPU reads what memory holds.
  • The first eight timeouts are logged with done / submitted / handed-out values.
  • RX_VK_READBACK_WAIT_MS=0 restores the unlimited wait.
  • wait_recorded's path is unchanged.

Testing

  • tests/test_readback_wait_bounded.py compiles the actual function against a stand-in timeline that never arrives: reached, timed out with log, a custom limit, and 0 = unlimited. It also checks that invalidate uses it, and fails on main.
  • Linux game-free suite: 350 passed, 2 failed, 22 skipped. The two failures (test_dlss_actor, byte-compile) fail identically on clean main (349 passed).
  • Steam Deck OLED, SteamOS 3.9, Mesa 26.2 RADV, Game Mode, same save: 0 of 4 starts hung. There were 6–8 timeouts per start, all during the save's load and none in play. Gameplay ran at 26–29 fps with 0 of 80 screenshots flagged, and HUD and exposure were as before.

Not tested: discrete GPUs and Windows. The default path there only changes if a write-back takes longer than 250 ms.

**Problem** `invalidate()` waits for a GPU result's write-back before the CPU reads it. When the recordings' timeline doesn't know the value (`wait_recorded` returns false), it falls back to `wait_value(v)`, which waits on the main timeline **without a limit**. On a Steam Deck (RADV, no buffer mirrors, queues replayed in submit order with `RX_VK_EVENT_WAITS=0`), this hung the game for good right after a save loaded: - 2 of 8 starts with default settings, and 4 of 4 with `RX_VK_CAPTURE_WAIT=0`. - Under gdb, the game's main thread and one of its jobs were both in `invalidate -> wait_value -> drmSyncobjTimelineWait`, the presentation thread was idle, and the kernel logged no GPU timeout. - The new log line shows the value had been submitted but the timeline stayed one short while they waited, e.g. `write-back 26867 ... (done 26866, submitted 26868, handed out 26868)`. **Change** - `readback_wait_value()` waits at most `RX_VK_READBACK_WAIT_MS` (default 250). This matches the capture's `vk_timeline_wait`, which already gives up after 250 ms for the same reason ("a submission held back behind the caller's thread goes on without it"). Past the limit, the CPU reads what memory holds. - The first eight timeouts are logged with done / submitted / handed-out values. - `RX_VK_READBACK_WAIT_MS=0` restores the unlimited wait. - `wait_recorded`'s path is unchanged. **Testing** - `tests/test_readback_wait_bounded.py` compiles the actual function against a stand-in timeline that never arrives: reached, timed out with log, a custom limit, and 0 = unlimited. It also checks that `invalidate` uses it, and fails on main. - Linux game-free suite: 350 passed, 2 failed, 22 skipped. The two failures (`test_dlss_actor`, byte-compile) fail identically on clean main (349 passed). - Steam Deck OLED, SteamOS 3.9, Mesa 26.2 RADV, Game Mode, same save: 0 of 4 starts hung. There were 6–8 timeouts per start, all during the save's load and none in play. Gameplay ran at 26–29 fps with 0 of 80 screenshots flagged, and HUD and exposure were as before. Not tested: discrete GPUs and Windows. The default path there only changes if a write-back takes longer than 250 ms.
hckrman101 (Migrated from github.com) reviewed 2026-11-11 16:29:14 +00:00
hckrman101 (Migrated from github.com) left a comment

Thanks, the write-up is clear and the gdb + log evidence (value recorded, timeline one short, no GPU timeout) is exactly what's needed to reason about this. The code itself is fine and CI is green. My concerns are about what the limit does rather than how it's written:

Stale data on a timeout. Past 250 ms the CPU reads the range before its write-back lands, and the write-back then lands after the CPU's read. For the exposure meter that is the very failure the readback wait was added for (the comment above it in invalidate: CPU reads and zeroes the sum, the old sum comes back over the 0, the frame adds to it, white flash). Your Deck runs only hit it during the save load, so it's harmless there, but it's now a silent correctness fallback for every config where wait_recorded doesn't know the value (async replay, RX_VK_PER_QUEUE_FENCES=0, or the value not recorded yet). On discrete GPUs a real write-back taking >250 ms should be rare, so I'm not worried about the default path in practice, just that a timeout now means "possibly wrong data" and the log line should say that, not only "timed out".

It hides the deadlock rather than explaining it. A timeline stuck one short, with the value recorded and no GPU hang, and the game moving again once the waiting thread gives up, means the signal for that value depends on something the waiting thread (or the job holding the main thread) blocks. So either (a) memory_writeback_value returned a write-back newer than the work this read actually depends on in the game's order (then not waiting is the right answer, and the fix is the value, not the timeout), or (b) the work that signals it is stopped behind this thread (then the data really isn't there yet and we read stale). The new log line can't tell those apart. Could you log a bit more on the first timeouts, e.g. blocked_n, replay_behind(), whether pend was empty, and which queue value_queue[v] belongs to and whether it's blocked()? That would tell us which case the Deck is in. For (b), wait() already has a pattern for this: after the hold it calls sync_drain(2) and waits again, which gets the right data at the cost of forcing stopped work; worth considering before falling back to reading what memory holds.

Interaction with #2125. #2125 changes the lines just above (the catch-up becomes unforced ? sync_settle() : wait_queue_empty() when behind0), so they should merge without a textual conflict, but they overlap in effect: with the settle, met stopped work goes on before the wait, which may be exactly what holds the Deck's value one short, so #2125 alone might fix this hang (on the per-queue-fences path; the async / fences-off paths still go through here). It'd be good to retest the Deck on #2125 with RX_VK_READBACK_WAIT_MS=0: if it no longer hangs, this PR becomes a safety net and its timeouts should be ~0 a start; if it still hangs, the extra logging above would show why.

I'm fine with a bounded wait as a safety net (a frozen game is worse than one wrong readback during a load), but I'd like the root cause understood or at least followed up, and the default (250 ms vs. something longer that can't hit real GPU work) is a call for @NotRexed.

Nits inline. Tests: the new test is self-contained and declared properly (RUN_ALL_ARGS, Windows skip), and checks invalidate uses the new function.

Thanks, the write-up is clear and the gdb + log evidence (value recorded, timeline one short, no GPU timeout) is exactly what's needed to reason about this. The code itself is fine and CI is green. My concerns are about what the limit does rather than how it's written: **Stale data on a timeout.** Past 250 ms the CPU reads the range before its write-back lands, and the write-back then lands *after* the CPU's read. For the exposure meter that is the very failure the readback wait was added for (the comment above it in `invalidate`: CPU reads and zeroes the sum, the old sum comes back over the 0, the frame adds to it, white flash). Your Deck runs only hit it during the save load, so it's harmless there, but it's now a silent correctness fallback for every config where `wait_recorded` doesn't know the value (async replay, `RX_VK_PER_QUEUE_FENCES=0`, or the value not recorded yet). On discrete GPUs a real write-back taking >250 ms should be rare, so I'm not worried about the default path in practice, just that a timeout now means "possibly wrong data" and the log line should say that, not only "timed out". **It hides the deadlock rather than explaining it.** A timeline stuck one short, with the value recorded and no GPU hang, and the game moving again once the waiting thread gives up, means the signal for that value depends on something the waiting thread (or the job holding the main thread) blocks. So either (a) `memory_writeback_value` returned a write-back newer than the work this read actually depends on in the game's order (then not waiting is the right answer, and the fix is the value, not the timeout), or (b) the work that signals it is stopped behind this thread (then the data really isn't there yet and we read stale). The new log line can't tell those apart. Could you log a bit more on the first timeouts, e.g. `blocked_n`, `replay_behind()`, whether `pend` was empty, and which queue `value_queue[v]` belongs to and whether it's `blocked()`? That would tell us which case the Deck is in. For (b), `wait()` already has a pattern for this: after the hold it calls `sync_drain(2)` and waits again, which gets the right data at the cost of forcing stopped work; worth considering before falling back to reading what memory holds. **Interaction with #2125.** #2125 changes the lines just above (the catch-up becomes `unforced ? sync_settle() : wait_queue_empty()` when `behind0`), so they should merge without a textual conflict, but they overlap in effect: with the settle, met stopped work goes on before the wait, which may be exactly what holds the Deck's value one short, so #2125 alone might fix this hang (on the per-queue-fences path; the async / fences-off paths still go through here). It'd be good to retest the Deck on #2125 with `RX_VK_READBACK_WAIT_MS=0`: if it no longer hangs, this PR becomes a safety net and its timeouts should be ~0 a start; if it still hangs, the extra logging above would show why. I'm fine with a bounded wait as a safety net (a frozen game is worse than one wrong readback during a load), but I'd like the root cause understood or at least followed up, and the default (250 ms vs. something longer that can't hit real GPU work) is a call for @NotRexed. Nits inline. Tests: the new test is self-contained and declared properly (`RUN_ALL_ARGS`, Windows skip), and checks `invalidate` uses the new function.
@ -2250,0 +2265,4 @@
wi.semaphoreCount = 1;
wi.pSemaphores = &timeline;
wi.pValues = &v;
if (vkWaitSemaphores(dev.device, &wi, (uint64_t)limit_ms * 1000000ull) != VK_TIMEOUT) return true;
hckrman101 (Migrated from github.com) commented 2026-11-11 16:29:14 +00:00

Nit: VK_ERROR_DEVICE_LOST (or any other error) counts as reached here; wait() routes it to device_lost(). Probably worth == VK_SUCCESS for the true return and a device_lost() call on that error, so a lost device isn't treated as a completed write-back. Also suggest the log line say the CPU reads the range without its write-back (possibly stale), so a later report of a flash can be tied to it.

Nit: `VK_ERROR_DEVICE_LOST` (or any other error) counts as reached here; `wait()` routes it to `device_lost()`. Probably worth `== VK_SUCCESS` for the true return and a `device_lost()` call on that error, so a lost device isn't treated as a completed write-back. Also suggest the log line say the CPU reads the range without its write-back (possibly stale), so a later report of a flash can be tied to it.
hckrman101 (Migrated from github.com) commented 2026-11-11 16:29:14 +00:00

The return value is dropped. If you add the drain/retry suggested in the review body, this is where it would go; otherwise maybe count timeouts into the every-3000 "readbacks of GPU results" stats line so they show up beyond the first eight.

The return value is dropped. If you add the drain/retry suggested in the review body, this is where it would go; otherwise maybe count timeouts into the every-3000 "readbacks of GPU results" stats line so they show up beyond the first eight.
Joey-Magnus (Migrated from github.com) reviewed 2026-11-11 21:25:24 +00:00
Joey-Magnus (Migrated from github.com) left a comment

The code is correct and the test passes merged into main. It is a safety net, though: after the timeout the CPU reads stale data, which is the exposure-flash bug the wait exists to prevent (invalidate, vk_replay.cpp ~2300).

#2125 has since landed (settle before wait), and it may fix the Deck hang on its own. Could the Deck be retested on current main with RX_VK_READBACK_WAIT_MS=0, with more detail logged on timeouts? The 250 ms default applies on every GPU whenever wait_recorded doesn't know the value (async replay, or RX_VK_PER_QUEUE_FENCES=0).

The code is correct and the test passes merged into main. It is a safety net, though: after the timeout the CPU reads stale data, which is the exposure-flash bug the wait exists to prevent (`invalidate`, `vk_replay.cpp` ~2300). #2125 has since landed (settle before wait), and it may fix the Deck hang on its own. Could the Deck be retested on current main with `RX_VK_READBACK_WAIT_MS=0`, with more detail logged on timeouts? The 250 ms default applies on every GPU whenever `wait_recorded` doesn't know the value (async replay, or `RX_VK_PER_QUEUE_FENCES=0`).
Commenting is not possible because the repository is archived.
No description provided.