perf: Guardians of the Galaxy: menu at ~1.7 FPS with the GPU mostly idle, the graphics queue busy recording and the compute queue in WAIT_REG_MEM_64 #10441

Activity

1. Tamalero commented on Oct 24, 2026

   

   Tamalero

   on Oct 24, 2026

   ContributorAuthor

   More actions

   Trace:

   aps5-trace-abe0d257ac4c-2.json.gz
2. Tamalero commented on Oct 24, 2026

   

   Tamalero

   on Oct 24, 2026

   ContributorAuthor

   More actions

   The same pattern shows up in a second title on a different engine: LEGO Batman: Legacy of the Dark Knight (PPSA16833, 01.010.000, Unreal Engine).

   Build: plain main e13027a, with only APS5_PREBUILD_THREADS=16 APS5_TRACE_SUMMARY_EVERY=10. Same machine (RTX 4090, NVIDIA 615.78.08, Linux 7.3, i9-14900K). The title boots, reaches the menu and loads the Mountain Climb level with no errors. Standing still at the start of that level:

   • Graphics mode doesn't matter. The in-game overlay shows 3.1 FPS (316 ms average) in Performance and 3.0 FPS in Fidelity, at about 1,750 draws and 300 dispatches per frame. So the GPU is not the limit.
   • Summary intervals (10 s each, the last four before closing, in Fidelity):

   Interval	Presents	Frame p50	GPU busy per present	Driver.Packet.memory_wait per frame	Driver.Packet.dispatch per frame
   1	28	328 ms	94 ms	346 ms	230 ms
   2	31	328 ms	89 ms	326 ms	214 ms
   3	31	315 ms	84 ms	320 ms	207 ms
   4	31	322 ms	88 ms	322 ms	222 ms

   • Both queue workers (0x0 and 0x20) report 99–100% busy, while the whole process uses only about two cores of CPU. As in the Guardians capture above, the time goes to waits and per-packet work on the queue workers, not to the GPU or to raw CPU load.

   This run had no trace window, and no APS5_PROFILE_DRAW, so I can't yet split the waits by queue or packet type the way the Guardians tables do. If it helps, I can capture a clean APS5_TRACE_FRAMES window for this scene to compare with the Guardians trace.

   Tested and written by Claude (AI assistant) on a contributor's machine.
3. Tamalero commented on Oct 24, 2026

   

   Tamalero

   on Oct 24, 2026

   ContributorAuthor

   More actions

   Follow-up on what queue 0x23 waits for. Same build and menu scene as the report, about 60 s with APS5_TRACE_GPU=1 APS5_PROFILE_DRAW=1 (both add overhead, so only the proportions matter).

   Almost all of the compute queue's wait time is on one label:

   Queue	Awaited address	Waits (~60 s)	Waits ≥ 0.5 ms	Total waited
   0x23	0x281170038	529	526	57.1 s (~108 ms each)
   0x0	0x281170058	127	120	4.3 s (~36 ms each)
   0x23	10 others in 0x2a62fe6xx–8xx	10 each	0	0

   • It's a counter. Each wait expects the next value, and at the start of each wait the label is exactly one behind:

     queue 0x23 waits 0x281170038 == 0x102 (now 0x101)
     queue 0x23 waits 0x281170038 == 0x103 (now 0x102)
     queue 0x23 waits 0x281170038 == 0x104 (now 0x103)
     

     Queue 0x0 does the same on 0x281170058 (== 0xc1 (now 0xc0), == 0xc4 (now 0xc3), …).

   • Queue 0x23 mostly waits on its own writes. Per 10 s, the [packets] line for 0x23 shows from recorder 307 (… same queue 255 …) and from recorder 308 (… same queue 248 …), with 11–22 polled and 0–1 at entry over the seven intervals. So about 80% of these waits are on a label that the recorder holds as pending from queue 0x23 itself. The title increments the counter after its own work and then waits for it, and each of those waits takes about 108 ms while the GPU is mostly idle (134 ms of GPU per ~590 ms frame in the clean capture).

   • The GPU-mutex waits on these lines are small by comparison: waited behind (holder/site ms): q0x23/dispatch 61 q0x0/dispatch 29 … and q0x23/dispatch 34 q0x0/draw 14 … per 10 s.

   Within one queue the GPU executes in order. Would it be possible to satisfy a same-queue wait on a label still pending from that queue in submission order (a barrier) instead of a full CPU round trip for every increment? I can run any diagnostic on this scene that would help.

   Tested and written by Claude (AI assistant) on a contributor's machine.
4. MarcZX10 commented on Oct 24, 2026

   

   MarcZX10

   on Oct 24, 2026

   Contributor

   More actions

   I checked the current wait paths. There is already a recorder-label fast path: waitMemory() returns when a pending recorder write matches the wait value, and the queue-0 draw pipeline has an additional pending-label shortcut in PacketExecution.cpp. Those fast-path hits do not execute a GPU wait packet or enter the long polling loop. That means the reported 255 same-queue recorder hits are being bypassed already; the 526 waits lasting at least 0.5 ms are likely among the other waits, but the counters shown are not correlated per address or with elapsed wait time, so the report does not yet show which ones dominate the 57.1 s.

   A useful next capture would correlate each long wait by address/reference with its eventual outcome (fromRecorder, polled, or timed out) and elapsed time, in one run. In particular, please check whether the repeated waits on 0x281170038 that exceed 0.5 ms are recorder misses or poll-loop waits. If they are misses, the trace should help identify whether the producer write is not yet recorded/submitted or whether the label lookup refuses it; if they are already recorder hits, that would point elsewhere because those return immediately. This will distinguish a missing GPU-side ordering opportunity from the existing fast path working as designed.
5. MarcZX10 commented on Oct 24, 2026

   

   MarcZX10

   on Oct 24, 2026

   Contributor

   More actions

   I checked the current WaitMemory.cpp diagnostics. There is no switch that prints a producer for every wait, but a short run with APS5_TRACE_GPU=1 APS5_TRACE_LATE_LABELS=1 APS5_PROFILE_DRAW=1 should narrow this further: APS5_TRACE_GPU prints the address and duration for each wait over 0.5 ms, while APS5_TRACE_LATE_LABELS prints any recorder-table hit/refusal examined on the path (up to 200 lines). Please include the paired [gpu] ... waits / done after lines for 0x281170038 and any corresponding [late] lines, plus the same interval's [packets] counters. That will tell us whether those long instances found a recorder label or continued into polling. The label-trace switch may add logging overhead, so a brief representative capture is enough.
6. MarcZX10 commented on Oct 24, 2026

   

   MarcZX10

   on Oct 24, 2026

   Contributor

   More actions

   Correction to my previous comment: APS5_TRACE_LATE_LABELS logs recorder lookup refusals and late-label hits, not ordinary successful hits. The [gpu] address/duration pairs plus the aggregate [packets] counters will still help separate polling from fast-path behavior; any [late] lines can explain specific rejected candidates. I should not have described that switch as logging every table hit.
7. Tamalero commented on Oct 24, 2026

   

   Tamalero

   on Oct 24, 2026

   ContributorAuthor

   More actions

   @MarcZX10 thanks. Here's the run you asked for: same build and menu scene, APS5_TRACE_GPU=1 APS5_TRACE_LATE_LABELS=1 APS5_PROFILE_DRAW=1, about 35 s on the menu with no input.

   [late] lines: none, neither in that window nor anywhere in the log from launch.

   Waits on 0x281170038: 216 by queue 0x23, 213 of them with a done after line, for 28.7 s in total (~134 ms each). The first pairs, with the timestamps removed:

   [gpu] queue 0x23 waits 0x281170038 == 0x4c1 (now 0x4bf)
   [gpu] queue 0x23 wait on 0x281170038 done after 242.0 ms
   [gpu] queue 0x23 waits 0x281170038 == 0x4c2 (now 0x4c1)
   [gpu] queue 0x23 wait on 0x281170038 done after 37.6 ms
   [gpu] queue 0x23 waits 0x281170038 == 0x4c3 (now 0x4c2)
   [gpu] queue 0x23 wait on 0x281170038 done after 128.7 ms
   [gpu] queue 0x23 waits 0x281170038 == 0x4c4 (now 0x4c3)
   [gpu] queue 0x23 wait on 0x281170038 done after 192.8 ms
   [gpu] queue 0x23 waits 0x281170038 == 0x4c5 (now 0x4c4)
   [gpu] queue 0x23 wait on 0x281170038 done after 210.2 ms
   [gpu] queue 0x23 waits 0x281170038 == 0x4c6 (now 0x4c5)
   [gpu] queue 0x23 wait on 0x281170038 done after 11.0 ms
   

   Queue 0x0's 0x281170058 had 53 waits for 2.0 s in the same window.

   [packets] for queue 0x23, the four 10 s intervals in the window:

   Interval	WAIT_REG_MEM_64	At entry	From recorder (while polling, same queue)	Polled	Timed out	Late candidates	Late-trusted
   1	×291, 7,923 ms	1	239 (39, 200)	20	0	0	0
   2	×281, 7,826 ms	1	232 (32, 200)	25	0	0	0
   3	×296, 7,884 ms	1	236 (34, 202)	26	0	0	0
   4	×303, 8,053 ms	0	255 (41, 214)	21	0	0	0

   So about 80–85% of the waits were satisfied from a recorder label, mostly one queue 0x23 recorded itself, and only 20–26 per interval went to polling, with no refusals and nothing late. The long waits are therefore not polling misses. Yet the done after times for those same waits are 11–242 ms. If it helps, I can add a timestamp at each step inside one of these waits on a local build (table lookup, the wait on the producer's batch, return) to show where the ~134 ms goes.

   Tested and written by Claude (AI assistant) on a contributor's machine.
8. Tamalero commented on Oct 29, 2026

   

   Tamalero

   on Oct 29, 2026

   ContributorAuthor

   More actions

   An update on current main, with a CPU profile of the menu and a list of what does not change it.

   Build: main 319621b with #9789 reverted (the title stops at start-up without that, #11513). The same menu as in this issue: p50 495.9 to 532.9 ms in four runs, with APS5_TRACE_FRAMES=1150:40, no input, warm caches, RTX 4090, NVIDIA 615.78.08, Linux 7.3. The title also still gets through New Game to the Milano on this build, at 0.8 to 2 FPS.

   CPU profile (perf record -p, 10 s on the menu, no trace switches set):

   • 89 % of the samples are in the title's own code, and about 70 % are in one helper at 0x611c30 that reads a global flag and executes pause. It is called from the title's job-system idle wait (a loop of up to 199 calls with a per-thread counter compared against 500). So 14 worker threads are busy-waiting with no work.
   • The emulator's own code is in the low single digits (mostly mutexes and condition variables).

   So the menu is not throughput-bound on either side. The frame seems to be a chain of round trips: the title waits for queue work, and queue 0x23 waits (Driver.Packet.memory_wait, 406 to 460 ms per frame in the base runs) on labels that only advance after its own work completes, as in my earlier comments.

   No change (menu p50, one run each unless noted; base 495.9 / 532.9 / 512.8 / 511.1 ms):

   Change	p50
   #12616 (two runs)	589.1 / 520.3 ms
   #9858	503.2 ms
   #11847	532.6 ms
   #7261	486.6 ms
   #12264	517.1 ms
   #9289	517.3 ms
   APS5_POLL_REAP=1	519.8 ms
   APS5_LABEL_FLUSH_US=100	505.0 ms
   APS5_DRAIN_COMPLETION_LABELS=1	515.2 ms
   APS5_POLL_TRY_EACH=1	470.5 ms (the power profile changed during this run)
   APS5_LABEL_SUBMIT_NOW=1 (three runs)	466.6 / 486.8 / 511.1 ms

   APS5_LABEL_SUBMIT_NOW=1 is the one consistent change: GPU busy per present falls from about 115 ms to about 40 ms in all three runs, but the frame time stays within the spread. So GPU time is not what limits this frame.

   From #12640: the dispatch cache hits about 10 % of the time on this menu, and neither 8 variants nor 65,536 entries change the frame time (+0 % and +3.5 %).

   I can rerun any of these with other switches, or capture traces of the base and APS5_LABEL_SUBMIT_NOW runs if those would help.

   Tested and written by Claude (AI assistant) on a contributor's machine.