Repository navigation
perf: High on Life: one 16-byte-record buffer copy compute shader takes ~96% of GPU time near Blorto's Chef Stand #9980
Description
Title and scene
PPSA15388 (01.120.000), Blim City, standing still and facing Blorto's Chef Stand (the restaurant counter with the chef and two seated customers). Window 2236×1258, guest 3840×2160.
What is slow or what changed
Facing the Chef Stand the title runs at 2.5–3.2 FPS. Turning away so the stand leaves the view brings it straight back to 8–13 FPS, and the frame-time drop happens on the same frame the stand leaves. The number of draws and dispatches hardly changes between the two views, so the cost is not the amount of work on screen:
| View (F10 overlay) | Draws | Dispatches | Frame |
|---|---|---|---|
| Side street | 2,219 | 185 | 89 ms |
| Behind the stand | 1,568 | 163 | 75 ms |
| Facing the stand | 2,230 | 229 | 338 ms |
While it is slow the GPU reports 77–100% utilisation at about 117 W (38% in the side street). The desktop stutters too.
One compute shader accounts for it. With APS5_PROFILE_GPU=1 (a separate run from the trace below), the [gputime] line facing the stand reads:
[gputime] 7684 ms of GPU time in 3629 batches over 10 s (…; 35 presents; …); by program: 0x20350f0000 x435 7401ms 0x20357c0000 x36 124ms 0x2035bb0000 x1078 24ms …
In the side street the same line totals about 835 ms per 10 s, and 0x20350f0000 is not among the costly programs. So 0x20350f0000 runs about 12 times per frame at roughly 17 ms of GPU time each.
What the shader does (its request, replayed offline with agc_shader_replay): 76 code words, wave64, 64×1×1 threads, no LDS. Each thread takes group × 64 + lane, reads a count and two offsets from a 1-record constant buffer, exits past the count, and copies one 16-byte record from one buffer to another:
| Buffer | Stride | Records | Size |
|---|---|---|---|
| source (read) | 16 B | 294,912 | 4.5 MiB |
| destination (written) | 16 B | 262,144 | 4 MiB |
That is at most 4 MiB moved per dispatch, about 235 MiB/s at 17 ms. The [buffers] CPU-copy counters for both buffers' 256 MiB ranges do not grow between the side street and the stand, so AnyPS5 is not copying them on the CPU. I have not found out where the 17 ms goes on the GPU side (host-visible placement, a slow access path in the translated loads and stores, or something else). I can run a build with extra logging, or replay the request with a given setting, if that helps.
Summary lines
{"commit":"3e7b0a645924","dirty":false,"env":{"APS5_MOUSE_DIAG":"1","APS5_PLAYGO_UNLISTED_CHUNKS":"installed","APS5_TRACE_SECONDS":"240:10"},"gpu":"NVIDIA GeForce RTX 4090","driver":"NVIDIA 615.78.08","os":"Linux 7.3.0-3-cachyos","cpu":"Intel(R) Core(TM) i9-14900K","cpu_threads":32,"memory_mib":64108,"title_id":"PPSA15388","title":"High on Life","content_version":"01.120.000","resolution":"3840x2160","window":{"spec":"seconds 240:10","first_present":3730,"ms":10194.886},"presents":18,"frame_ms":{"p50":566.901,"p90":648.164,"p99":663.230,"max":663.230},"gpu_busy_ms_per_present":417.351,"worker_busy_pct":{"queue worker 0x0":99.516,"queue worker 0x20":99.489},"top_phases_ms_per_frame":{"Driver.Packet":1099.501,"Driver.Packet.memory_wait":480.242,"Driver.Packet.dispatch":447.145,"Driver.Dispatch":123.691,"Driver.Packet.draw":119.613,"Driver.Draw":118.902,"Recorder.Submit":101.262,"Resources.Complete":84.185},"trace_dropped":false,"trace":"aps5-trace-3e7b0a645924-2.json.gz"}Traces
aps5-trace-3e7b0a645924-2.json.gz, attached below (18 presents, standing still facing the stand).
Digest
seconds 240:10 from present 3730: 18 presents, frame p50 566.9 / p90 648.2 / p99 663.2 / max 663.2 ms, GPU busy 417.4 ms per present
NVIDIA GeForce RTX 4090, NVIDIA 615.78.08, Linux 7.3.0-3-cachyos, 3840x2160, commit 3e7b0a645924, dropped: no
{"commit":"3e7b0a645924","dirty":false,"env":{"APS5_MOUSE_DIAG":"1","APS5_PLAYGO_UNLISTED_CHUNKS":"installed","APS5_TRACE_SECONDS":"240:10"},"gpu":"NVIDIA GeForce RTX 4090","driver":"NVIDIA 615.78.08","os":"Linux 7.3.0-3-cachyos","cpu":"Intel(R) Core(TM) i9-14900K","cpu_threads":32,"memory_mib":64108,"title_id":"PPSA15388","title":"High on Life","content_version":"01.120.000","resolution":"3840x2160","window":{"spec":"seconds 240:10","first_present":3730,"ms":10194.886},"presents":18,"frame_ms":{"p50":566.901,"p90":648.164,"p99":663.23,"max":663.23},"gpu_busy_ms_per_present":417.351,"worker_busy_pct":{"queue worker 0x0":99.516,"queue worker 0x20":99.489},"top_phases_ms_per_frame":{"Driver.Packet":1099.501,"Driver.Packet.memory_wait":480.242,"Driver.Packet.dispatch":447.145,"Driver.Dispatch":123.691,"Driver.Packet.draw":119.613,"Driver.Draw":118.902,"Recorder.Submit":101.262,"Resources.Complete":84.185},"trace_dropped":false,"trace":"aps5-trace-3e7b0a645924-2.json.gz"}Slowest frames (largest slices inside each, inclusive)
- present 3734: 663.2 ms at 2180 ms: Driver.Packet (queue worker 0x0) 632.5, Driver.Packet (queue worker 0x20) 616.3, batch (gpu) 395.6, Driver.Packet.dispatch (queue worker 0x20) 316.3
- present 3745: 648.2 ms at 8551 ms: Driver.Packet (queue worker 0x20) 644.2, Driver.Packet (queue worker 0x0) 616.1, batch (gpu) 393.8, Driver.Packet.dispatch (queue worker 0x20) 331.6
- present 3742: 635.3 ms at 6865 ms: Driver.Packet (queue worker 0x20) 631.9, Driver.Packet (queue worker 0x0) 603.2, batch (gpu) 391.8, Driver.Packet.dispatch (queue worker 0x20) 329.7
- present 3739: 622.7 ms at 5083 ms: Driver.Packet (queue worker 0x0) 587.7, Driver.Packet (queue worker 0x20) 537.8, batch (gpu) 399.6, Driver.Packet.dispatch (queue worker 0x20) 336.4
- present 3740: 608.4 ms at 5705 ms: Driver.Packet (queue worker 0x20) 604.9, Driver.Packet (queue worker 0x0) 577.1, batch (gpu) 396.5, Driver.Packet.dispatch (queue worker 0x20) 333.4
Threads (ms per frame)
| thread | busy | wait | untraced | in slices < 20 us | largest |
|---|---|---|---|---|---|
| queue worker 0x0 | 254.5 (45 %) | 279.7 (49 %) | 32.2 | 154.9 | Driver.Packet 533.7, Driver.EndSubmission 0.4 |
| draw committer | 83.0 (15 %) | 30.6 (5 %) | 452.8 | 36.0 | Graphics.Draw 54.1, Recorder.Submit 28.3 |
| queue worker 0x20 | 357.9 (63 %) | 208.0 (37 %) | 0.6 | 1.6 | Driver.Packet 536.1, Driver.EndSubmission 27.0 |
| presenter | 0.3 (0 %) | 0.3 (0 %) | 565.8 | 0.1 | VideoOut.Flip 0.6, Driver.Present 0.0 |
| gpu | 394.6 (70 %) | 0.0 (0 %) | 171.8 | 0.0 | batch 394.6 |
Largest slices (ms per frame, inclusive, all threads): Driver.Packet 1069.7, Driver.Packet.memory_wait 480.2, Driver.Packet.dispatch 446.1, batch 394.6, Driver.Dispatch 122.6, Driver.Packet.draw 105.9, Driver.Draw 105.2, Recorder.Submit 100.3, Resources.Complete 82.7, Vulkan.Dispatch 79.7
Longest waits
- Driver.Packet.memory_wait (queue worker 0x0) 293.7 ms at 1820 ms, present 3733
- Driver.Packet.memory_wait (queue worker 0x0) 290.4 ms at 8227 ms, present 3744
- Driver.Packet.memory_wait (queue worker 0x0) 288.1 ms at 3602 ms, present 3736
- Driver.Packet.memory_wait (queue worker 0x0) 287.5 ms at 8808 ms, present 3745
- Driver.Packet.memory_wait (queue worker 0x0) 287.0 ms at 5909 ms, present 3740
- Driver.Packet.memory_wait (queue worker 0x0) 286.5 ms at 4110 ms, present 3737
- Driver.Packet.memory_wait (queue worker 0x0) 285.1 ms at 2973 ms, present 3735
- Driver.Packet.memory_wait (queue worker 0x0) 279.0 ms at 1300 ms, present 3732
- Driver.Packet.memory_wait (queue worker 0x0) 278.8 ms at 9403 ms, present 3746
- Driver.Packet.memory_wait (queue worker 0x0) 274.6 ms at 7138 ms, present 3742
Largest GPU batches (GPU ranges inside, and the CPU slices that recorded each, inclusive)
- batch 1091: 189.3 ms at 5416 ms, present 3739: GPU no ranges; recorded by Graphics.Draw (draw committer) 1.5, Graphics.Draw.draw_and_resource_release (draw committer) 1.2, Resources.Complete (draw committer) 0.7, Resources.Prepare (draw committer) 0.1
- batch 965: 189.1 ms at 4743 ms, present 3738: GPU no ranges; recorded by Graphics.Draw (draw committer) 0.3, Graphics.Draw.draw_and_resource_release (draw committer) 0.2
- batch 401: 188.6 ms at 1872 ms, present 3733: GPU no ranges; recorded by Graphics.Draw (draw committer) 1.7, Graphics.Draw.draw_and_resource_release (draw committer) 1.4, Resources.Complete (draw committer) 0.8, Resources.Prepare (draw committer) 0.0
- batch 1204: 188.2 ms at 5954 ms, present 3740: GPU no ranges; recorded by Driver.Packet (queue worker 0x0) 440.4, Driver.Packet.memory_wait (queue worker 0x0) 287.0, Driver.Packet.draw (queue worker 0x0) 142.5, Driver.Draw (queue worker 0x0) 142.2
- batch 523: 187.9 ms at 2453 ms, present 3734: GPU no ranges; recorded by Graphics.Draw (draw committer) 1.9, Graphics.Draw.draw_and_resource_release (draw committer) 1.5, Resources.Complete (draw committer) 0.7, Resources.Prepare (draw committer) 0.1
Capture
- The caches were warm (the scene ran once and the title was restarted)
- No other APS5_TRACE_* or APS5_PROFILE_* switch was set. Two notes:
APS5_MOUSE_DIAG(local logging, see below) was set, but it only logs while the mouse moves, and the view was still during the window; and the launcher copies stdout and stderr to a file throughtee. - Captures compared here come from the same machine, scene and settings (one capture only; the side-street numbers above come from the F10 overlay and
[gputime], not from a trace)
The trace build is main 895f47f plus a local commit that only adds logging to libSceMouse, for a separate input change (APS5_MOUSE_DIAG in env). Linux (CachyOS), RTX 4090.
Tested and written by Claude (AI assistant) on a contributor's machine.
TRACE FILE:
Activity
Tamalero commentedon Oct 23, 2026
With F10 trace:
EagleBearerYS commentedon Oct 23, 2026
@Tamalero thanks, the per-program GPU time and the replayed request narrow this a lot. About 4 MiB per dispatch in ~17 ms on an RTX 4090 points at where the two buffers live or how their loads and stores are translated, not at the copy itself. Two things would tell those apart:
APS5_TRACE_HOST_IMPORT=1, plus the[gpu] host importlines whose ranges cover the source and destination buffers. They say whether the buffers are imported host memory, and how;MarcZX10 commentedon Oct 23, 2026
I inspected the attached Chrome trace. Its dispatch and GPU events identify batch numbers but do not include shader addresses or descriptor/buffer ranges, so it cannot connect
0x20350f0000to a particular host import or explain that shader's access path. It does show substantial overlappingDriver.Packet.memory_waitand GPU batch spans, but those aggregates do not identify which dispatch causes them. The requested host-import range log and replay request are still the evidence needed to distinguish buffer placement from translated-load/store cost.Tamalero commentedon Oct 23, 2026
A data point on current
main(c188e01): the scene is GPU-bound whatever CPU it gets, so the copy shader is what limits it.Same spot facing Blorto's Chef Stand, standing still, warm caches, with only
APS5_TRACE_SUMMARY_EVERY=10. Lines are 10-second intervals fromaps5-summary.jsonl. The CPU set was changed live on the running process.The GPU is busy for ~270 of every ~300 ms, and only the remaining CPU part changes with the core type. In the view where the save loads, nearby but without the stand in view, the same build runs at about 75 ms per frame, with about 35 ms of GPU per present. For reference, the F10 overlay on
main895f47f showed 338 ms at the stand.The build is c188e01 plus one local libkernel commit that adds an opt-in thread-affinity switch. It was off here.
Tested and written by Claude (AI assistant) on a contributor's machine.
Tamalero commentedon Oct 23, 2026
@EagleBearerYS @MarcZX10 here is the host-import run you asked for:
mainc188e01,APS5_TRACE_HOST_IMPORT=1, facing the stand, warm caches.Both copy buffers are in imported host memory. The source buffer is split across several imports with gaps between them.
[gpu] host importlines covering it0x20c4fa0000+0x1790000 … joined at bind by join; the join grows over the run (0x12b0000 → 0x1440000 → 0x15e0000 → 0x1790000). It also overlapsby mapimports 0x20c5fc0000+0x290000, 0x20c6250000+0x190000 and 0x20c63e0000+0x1a0000.by mapimports: 0x20d4a20000+0xd0000, 0x20d4b20000+0x130000, 0x20d4c50000+0x90000 and 0x20d4d20000+0x200000. No import covers 0x20d4af0000–0x20d4b20000 or 0x20d4ce0000–0x20d4d20000, and there's no join for this range.The trace has 31,660
[gpu] host importlines: 20,430by map, 9,676retired: the range was mapped again, 1,413by build, 109by access, 28joined at bind, 4by segment. I haven't checked which binding path the dispatch takes for the source range, which isn't covered by one import. If there's a counter or trace for that (staged, split or something else), I can run it.Caveat: the buffer addresses come from the V#s in the request I captured in an earlier run of the same scene. The title could lay these allocations out differently between runs. If you want, I'll capture the V#s and the import lines in the same run.
About attaching the replay request: I can't attach it, because it carries the title's shader code and captured guest memory. I can run any comparison you describe on it locally, for example a device-local copy of the same 16-byte records against the translated access path, and post the timings.
Tested and written by Claude (AI assistant) on a contributor's machine.
EagleBearerYS commentedon Oct 23, 2026
@Tamalero thanks, this is the piece that was missing. The destination sits inside one import (the growing join), but the source doesn't. It spans four
by mapimports, and two stretches of it, 0x20d4af0000–0x20d4b20000 and 0x20d4ce0000–0x20d4d20000, have no import at all. Somaincan't read the source in place through a single import. I haven't confirmed yet which path it takes instead. That fits a cost tied to where the buffers live rather than to the copy itself, but it doesn't show it yet.One run facing the Chef Stand in High on Life (PPSA15388), plus one A/B, would settle it:
APS5_TRACE_BIGBUF=1 APS5_PROFILE_DRAW=1 APS5_PROFILE_GPU=1toAPS5_TRACE_HOST_IMPORT=1:[bigbuf] uploadlists every guest region of 1 MiB or more that is copied for the GPU, withsparse=1when only parts of it are backed. Does 0x20d4a70000's range appear there, and how often per 10 s?[buffers] … uploadsline counts the regions copied out of imports on the GPU.APS5_NO_HOST_IMPORT=1added. It turns importing off, so shaders read copies of guest memory instead of using it in place (ENVIRONMENT.md). The whole frame may get slower; only0x20350f0000's entry in the[gputime]line matters.Tamalero commentedon Oct 23, 2026
@EagleBearerYS @MarcZX10 this is fixed on current
main. The fix is #8336 (8 MiB written-buffer staging on discrete GPUs), merged today.Same spot facing Blorto's Chef Stand, standing still, warm caches, RTX 4090. Every run had
APS5_PROFILE_DRAW=1 APS5_PROFILE_GPU=1 APS5_TRACE_SUMMARY_EVERY=10. Values are three consecutive 10-second[gputime]and summary intervals at the stand.0x20350f0000per 10 smainc188e01maine13027amaine13027aAPS5_NO_COPY_HLE=1maine13027aAPS5_NO_COPY_HLE=1 APS5_WRITTEN_SHADOW_MAX_KIB=2048[copy]reports every match taken as a GPU copy, with no refusals and no kernel run instead. With perf(agc): stage written buffer elements up to 8 MiB on discrete GPUs #8336 in place, though, it isn't what makes the difference: the copy takes ~0.15 ms against ~0.055 ms for the kernel, and the frame times are about the same.The scene is now limited by other programs, and the frame is no longer dominated by this copy. Is there any objection to closing this issue as fixed by #8336? If you'd like more data from this scene first, I can run it.
Tested and written by Claude (AI assistant) on a contributor's machine.
EagleBearerYS commentedon Oct 24, 2026
@Tamalero thank you, that settles it: on current
mainthat dispatch at Blorto's Chef Stand takes about 0.15 ms instead of 17 ms (about 0.055 ms for the kernel itself withAPS5_NO_COPY_HLE=1), and putting back the old 2 MiB staging window brings the 17 ms back, so #8336 is the fix. Nothing further is needed from you on this one.Tamalero commentedon Oct 24, 2026
Thanks @EagleBearerYS, and @MarcZX10 for the earlier pointers. Closing as fixed by #8336.
Tested and written by Claude (AI assistant) on a contributor's machine.