Skip to content

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

Merged
hckrman101 merged 1 commit into
NotRexed:mainfrom
Brett-D:fix/readback-wait-limit
Nov 11, 2026
Merged

hckrman101 merged 1 commit into
NotRexed:mainfrom
Brett-D:fix/readback-wait-limit

Conversation

@Brett-D

@Brett-D Brett-D commented Nov 11, 2026

Copy link
Copy Markdown
Contributor

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.

invalidate waited without a limit (wait_value) for the write-back's timeline
value when the recordings' timeline did not know it. On the Steam Deck (RADV, no
buffer mirrors, queues replayed in submit order) the game's main thread and one of
its jobs waited there right after Kokiri Forest's save loaded; the value had been
submitted but the timeline stayed one short while they waited, and the game stopped
for good: 2 of 8 starts, 4 of 4 with RX_VK_CAPTURE_WAIT=0 (gdb: both threads in
invalidate -> wait_value -> drmSyncobjTimelineWait, the presentation thread idle).

The wait now ends after RX_VK_READBACK_WAIT_MS (default 250; 0: no limit, as
before), as the capture's wait (vk_timeline_wait) does, and the first eight are
logged with the timeline's progress. With it: 0 of 4 starts stopped, 6-8 timeouts a
start, all during the save's load; 0/80 screenshots flagged, HUD and exposure as
before.

tests/test_readback_wait_bounded.py compiles the actual function against a
stand-in timeline that never arrives, and checks invalidate uses it.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

@hckrman101 hckrman101 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment thread gpu/vk/vk_replay.cpp
wi.semaphoreCount = 1;
wi.pSemaphores = &timeline;
wi.pValues = &v;
if (vkWaitSemaphores(dev.device, &wi, (uint64_t)limit_ms * 1000000ull) != VK_TIMEOUT) return true;

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment thread gpu/vk/vk_replay.cpp
if (!(unforced && wait_recorded(v, UINT64_MAX, &ok))) {
if (unforced && replay_behind()) wait_queue_empty(); // (not recorded whole: as before)
wait_value(v);
readback_wait_value(v);

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 Joey-Magnus left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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).

hckrman101 pushed a commit that referenced this pull request Nov 11, 2026
…inishing (#2407)

A GPU hang that the driver never reports as `VK_ERROR_DEVICE_LOST`
freezes 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 of

```
vk: a capture's wait for write-back 467375 timed out (done 467371)
```

from 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 returned `VK_ERROR_DEVICE_LOST`, so
the checkpoint report never ran.

**The change**

- A watchdog thread, started at the first present next to the existing
`hang_watch_start()`, reads the timeline once a second
(`vkGetSemaphoreCounterValue` only: it needs no external
synchronization, unlike the recordings' fences).
- A lost device it reads goes to `device_lost()`.
- Work already sent to the queue (`note_timeline_sent`, at the two
submissions that signal the timeline) that finishes nothing for
`RX_VK_GPU_HANG_SEC` seconds (default 30) is logged as a hang and goes
to `device_lost()`: the checkpoint report, the log flushed, exit code 3.
- `RX_VK_GPU_HANG_SEC=0` only logs the stall (at 10 s, then every 30 s)
and lets the game wait.
- Only submissions actually sent count. A value held back on the CPU
side (the case #2222 bounds) is not taken as a GPU hang.

**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 `=0` exists. I have not seen it happen.

**Tests**

- `tests/test_gpu_hang_watch.py` cuts `gpu_hang_watch_start()` into a
fixture with the timeline and `device_lost()` stubbed. A stuck timeline
ends the process after the limit, a lost device ends it at once, and a
moving timeline or `=0` never 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.cpp` and
`tests/fsr_image_retirement_test.cpp` get a `note_timeline_sent` stub,
since they compile the submit functions.
- `python -I -B tests/run_all.py` on Linux: 381 passed, 15 skipped, 1
failed (`test_make_game_cache.py`, which fails the same way on `main`
without this change).
- `vk_replay.cpp` built with `nx2/build.py`'s Vulkan flags.
- Not yet run in the game. The hang is rare, so the path will be
confirmed when it recurs.

Complements #2117, which makes the report itself richer when there are
no checkpoints. Refs #1000.

---------

Co-authored-by: Joey Magnus <22943903+Joey-Magnus@users.noreply.github.com>
Co-authored-by: Cursor <cursoragent@cursor.com>
Co-authored-by: Joey Magnus <joey.magnus@cxalloy.com>
@hckrman101
hckrman101 merged commit fa2b25b into NotRexed:main Nov 11, 2026
12 checks passed
dazemc added a commit to dazemc/Hookshot-rs that referenced this pull request Nov 12, 2026
invalidate() waits for a GPU result's write-back before the CPU reads it.
When the recordings' timeline does not know the value, it falls back to a
wait on the main timeline with no limit. On a Steam Deck (RADV, no buffer
mirrors, queues replayed in submit order) the game's main thread and one of
its jobs waited there for good right after a save loaded: 2 of 8 starts
hung, 4 of 4 with RX_VK_CAPTURE_WAIT=0, and the timeline had the value
submitted but stayed one short while they waited.

The fallback now waits at most RX_VK_READBACK_WAIT_MS (250 by default), as
the capture's wait already gives up after 250 ms; past the limit the CPU
reads what memory holds. The first eight timeouts are logged with the done,
submitted and handed-out values. RX_VK_READBACK_WAIT_MS=0 restores the
unlimited wait. wait_recorded's path is unchanged.

readback_wait.h holds the limit and its timeout so
tests/readback_wait_test.cpp can check them without a timeline.

Ported from upstream fa2b25b (NotRexed#2222). Steam Deck/RADV hardware not
available here: the timeout is checked, the hang is unverified.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants