feat(vk): the frame trace names the waits it could not show #2683

Closed
github-sync wants to merge 5 commits from github/pr/2683 into main
Owner

@SadTransGirl opened this pull request on GitHub · 2026-11-12 06:07 UTC · original
Merged on GitHub in 37382cae6b

Some of the longest frames in RX_VK_FRAME_TRACE show every column near zero, so a stutter can't be matched to its cause. This adds three columns for the waits that weren't covered.

Change. hookshot_frames.csv gets three columns at the end; the existing ones keep their places, since scripts read them by name:

  • late_wait_ms: take_capture's wait for a submission still on the GPU (the "late" pages). It is part of memsync_ms; this is the part that is a wait.
  • readback_wait_ms: readback_submit_wait, the write-backs before an eviction. A frame of 344 ms at an area change had every column near zero while the replay waited in the driver here for 317 ms.
  • tex_frame_ms: texture_frame as a whole (each present's eviction, compaction and sweeps), which no column covered.

Tests. tests/test_frame_trace_waits.py: the header is the old columns followed by the three, a line has one value per column, and the counters are fed where the time is spent (after the GPU wait, around the read-back, from the start of texture_frame).

Measured. In the game on an RTX 4070 SUPER: the columns fill in, and late_wait_ms never exceeds its frame's memsync_ms. The cost is two clock reads per read-back and per texture_frame, and one relaxed atomic add each, whether or not the trace is on; the capture's wait was already timed.

Not tested. Linux, AMD, Intel.

See #995.

🤖 Generated with Claude Code

> [@SadTransGirl](https://github.com/SadTransGirl) opened this pull request on GitHub · 2026-11-12 06:07 UTC · [original](https://github.com/NotRexed/Hookshot/pull/2683) > **Merged on GitHub** in https://git.magicbean.dev/MagicBeanDev/Hookshot/commit/37382cae6b4159fac5f7deb1e46a7fba7d6ad8c2 Some of the longest frames in `RX_VK_FRAME_TRACE` show every column near zero, so a stutter can't be matched to its cause. This adds three columns for the waits that weren't covered. **Change.** `hookshot_frames.csv` gets three columns at the end; the existing ones keep their places, since scripts read them by name: - `late_wait_ms`: `take_capture`'s wait for a submission still on the GPU (the "late" pages). It is part of `memsync_ms`; this is the part that is a wait. - `readback_wait_ms`: `readback_submit_wait`, the write-backs before an eviction. A frame of 344 ms at an area change had every column near zero while the replay waited in the driver here for 317 ms. - `tex_frame_ms`: `texture_frame` as a whole (each present's eviction, compaction and sweeps), which no column covered. **Tests.** `tests/test_frame_trace_waits.py`: the header is the old columns followed by the three, a line has one value per column, and the counters are fed where the time is spent (after the GPU wait, around the read-back, from the start of `texture_frame`). **Measured.** In the game on an RTX 4070 SUPER: the columns fill in, and `late_wait_ms` never exceeds its frame's `memsync_ms`. The cost is two clock reads per read-back and per `texture_frame`, and one relaxed atomic add each, whether or not the trace is on; the capture's wait was already timed. **Not tested.** Linux, AMD, Intel. See #995. 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- github-sync:item:2683 -->
RX_VK_FRAME_TRACE's hookshot_frames.csv gets three columns at the end (the
ones before keep their places):
- late_wait_ms: take_capture's wait for a submission still on the GPU
  (part of memsync_ms, the part that is a wait);
- readback_wait_ms: readback_submit_wait, the write-backs before an
  eviction (a frame of 344 ms at an area change had every column near
  zero, the replay inside the driver in this wait for 317 ms);
- tex_frame_ms: texture_frame as a whole (the present's eviction,
  compaction and sweeps), which no column covered.

tests/test_frame_trace_waits.py checks the header, that a line has a value
for each column, and that the counters are fed where the time is spent.

Assisted-by: Claude Mythos 5.2, Claude Opus 5.5
Co-Authored-By: Claude Mythos 5.2 <[email protected]>
Co-Authored-By: Claude Opus 5.5 <[email protected]>
Author
Owner

@Joey-Magnus approved on GitHub · 2026-11-12 14:34 UTC · original

I merged this into current main and ran tests/test_frame_trace_waits.py with the other trace/readback/texture checks: 12 passed. The ones that need the Vulkan headers were skipped here, but the Windows back-end build is green. The new columns go at the end, so scripts that read by name are unaffected. The format string has one conversion per column, and the deltas follow the same l_* pattern as the existing ones. late_wait_ms is fed after vk_timeline_wait in take_capture, so it's a true subset of memsync_ms. tex_frame_ms contains readback_wait_ms when an eviction asks for a read-back, as the comment says, so anyone summing the columns shouldn't add both. The cost is two clock reads and one relaxed atomic add per read-back and per texture_frame, which is negligible next to what they time. None of the open PRs that touch vk_replay.cpp/vk_texture.cpp change status_tick's trace line or these two functions, so I don't expect conflicts.

> [@Joey-Magnus](https://github.com/Joey-Magnus) approved on GitHub · 2026-11-12 14:34 UTC · [original](https://github.com/NotRexed/Hookshot/pull/2683#pullrequestreview-5876232184) I merged this into current main and ran `tests/test_frame_trace_waits.py` with the other trace/readback/texture checks: 12 passed. The ones that need the Vulkan headers were skipped here, but the Windows back-end build is green. The new columns go at the end, so scripts that read by name are unaffected. The format string has one conversion per column, and the deltas follow the same `l_*` pattern as the existing ones. `late_wait_ms` is fed after `vk_timeline_wait` in `take_capture`, so it's a true subset of `memsync_ms`. `tex_frame_ms` contains `readback_wait_ms` when an eviction asks for a read-back, as the comment says, so anyone summing the columns shouldn't add both. The cost is two clock reads and one relaxed atomic add per read-back and per `texture_frame`, which is negligible next to what they time. None of the open PRs that touch `vk_replay.cpp`/`vk_texture.cpp` change `status_tick`'s trace line or these two functions, so I don't expect conflicts. <!-- github-sync:r:5876232184 -->
github-sync closed this pull request 2026-11-12 17:58:30 +00:00
Author
Owner

@Joey-Magnus approved on GitHub · 2026-11-12 17:02 UTC · original

My approval from this morning stands at ba1572a0. Since 98251a27 the only change of its own is f13790e5, a tested-configurations row for the two runs in the description, plus merges of main that took both sets of rows. The row's figures match the description: summed late_wait_ms 260 / 319 ms, never above its frame's memsync_ms. The code in vk_replay.cpp and vk_texture.cpp is as I reviewed it, and the merge with current main is clean.

> [@Joey-Magnus](https://github.com/Joey-Magnus) approved on GitHub · 2026-11-12 17:02 UTC · [original](https://github.com/NotRexed/Hookshot/pull/2683#pullrequestreview-5878651953) My approval from this morning stands at ba1572a0. Since 98251a27 the only change of its own is f13790e5, a tested-configurations row for the two runs in the description, plus merges of main that took both sets of rows. The row's figures match the description: summed late_wait_ms 260 / 319 ms, never above its frame's memsync_ms. The code in vk_replay.cpp and vk_texture.cpp is as I reviewed it, and the merge with current main is clean. <!-- github-sync:r:5878651953 -->
Commenting is not possible because the repository is archived.
No description provided.