perf: ASTRO BOT's Crash Site is about 47 ms slower per frame since #6948's label readback store

Title and scene

PPSA21567 (ASTRO BOT 01.019.000), Crash Site, 3840x2160, no input. Each capture is the 5 s window that starts 150 s after launch (APS5_TRACE_SECONDS=150:5).

What is slow or what changed

From main 8499ea5 (22 October) to main 777bdbb (23 October), the frame p50 at Crash Site went from about 174 ms to about 221 ms.

Nearly all of the difference is the label readback store that #6948 added (a7d342e, with 14fd985 for small tiled images). With APS5_NO_LABEL_READBACK_STORE=1, 777bdbb is back at the frame of 8499ea5.

Setup

Machine: Windows 11 (10.0.26200), NVIDIA GeForce RTX 4070 Ti SUPER, driver 616.64, Intel Core i7-11700K, 32 GB.
Environment: only APS5_HOST_IMPORT_MIB=13312, besides the trace switches. On this machine the default host import budget is 8149 MiB, and larger heaps fall back to copies.
Warm shader cache. All captures come from one session, with no driver reset.
Three arms:
- u: main 8499ea5, before fix(agc): store linear compute writes behind their dispatch #6948;
- v: main 777bdbb, with fix(agc): store linear compute writes behind their dispatch #6948;
- w: 777bdbb with APS5_NO_LABEL_READBACK_STORE=1.
One discarded warm-up run per arm. Then four rounds in rotated order: uvw, wuv, vwu, uwv.

Run	Round	Position	Arm	Commit	Window from present	Frame p50 / p90 / p99 (ms)	GPU busy per present (ms)
1	1	1st	u	`8499ea52e`	2611	173.1 / 181.4 / 186.5	151.3
2	1	2nd	v	`777bdbb4f8`	1475	226.3 / 232.9 / 234.6	187.4
3	1	3rd	w	`777bdbb4f8`	3010	179.6 / 190.2 / 195.7	164.0
4	2	1st	w	`777bdbb4f8`	2323	174.3 / 187.5 / 191.9	160.6
5	2	2nd	u	`8499ea52e`	2664	175.3 / 184.5 / 191.4	152.7
6	2	3rd	v	`777bdbb4f8`	1516	220.4 / 224.9 / 226.6	182.1
7	3	1st	v	`777bdbb4f8`	1526	221.4 / 225.3 / 227.5	192.3
8	3	2nd	w	`777bdbb4f8`	2337	172.6 / 179.1 / 180.5	156.6
9	3	3rd	u	`8499ea52e`	2648	185.8 / 193.5 / 196.6	158.5
10	4	1st	u	`8499ea52e`	2740	170.5 / 180.2 / 182.9	149.5
11	4	2nd	w	`777bdbb4f8`	2348	169.7 / 180.9 / 187.7	154.0
12	4	3rd	v	`777bdbb4f8`	1492	218.8 / 224.4 / 225.4	179.6

Every window starts 150 s after launch; the present it starts from differs by arm because the arms run at different speeds.

Medians of the four rounds:

frame p50: u 174.2, v 220.9, w 173.5 ms;
GPU busy per present: u 152.0, v 184.8, w 158.6 ms.

Per round:

v − w, frame p50: +46.7, +46.1, +48.7 and +49.1 ms; GPU busy: +23.5, +21.4, +35.7 and +25.6 ms;
w − u, frame p50: +6.4, −1.0, −13.1 and −0.8 ms; the medians differ by −0.8 ms.

Reading (AI-assisted)

The store costs about 47 ms of frame per present here, in all four rounds and in every position.
With the store turned off, 777bdbb is back at the frame of 8499ea5.
GPU busy per present stays 6.6 ms higher with the store off (medians 158.6 against 152.0 ms). That part is not the store. It is not attributed to any PR here, because it has not been measured.
The store fixes a real case:
- Kena's occlusion results and The Smurfs' sky light, as the PR describes;
- agc_driver_linear_readback_label_off shows the stale read without it.
What costs here is how often it runs. A FlushPending over every pending linear or small storage image runs before every label write and every end-of-pipe interrupt, since any of them may be one the CPU waits on, so the cost grows with how many of them a frame has.
An idea, not tested: keep the store, but run it only before labels the CPU actually observes, or behind a per-title setting.
I can open a pull request for that once my open pull request limit allows it.

Confirmation without redirection

Two more runs in the same session, launched with stdout and stderr in the game's console window instead of files, one per arm of the store:

v (777bdbb4f8): window from present 1420, frame p50 238.7 ms, GPU busy 215.0 ms per present;
w (777bdbb4f8 with APS5_NO_LABEL_READBACK_STORE=1): window from present 2475, frame p50 172.4 ms, GPU busy 155.1 ms per present.

Between these two runs the store costs 66.3 ms of frame, in the same direction as in the four rounds above. They are single runs, so the four rounds give the size. A first store-off run started later in the scene (present 4327) and was redone, as for the windows of the table.

Summary lines of the two confirmation runs

{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":1420,"ms":5022.216},"presents":21,"frame_ms":{"p50":238.725,"p90":251.169,"p99":263.099,"max":263.099},"gpu_busy_ms_per_present":214.959,"worker_busy_pct":{"queue worker 0x0":99.179,"queue worker 0x48":95.437,"queue worker 0x40":97.084,"queue worker 0x46":6.996},"top_phases_ms_per_frame":{"Driver.Packet":713.110,"Driver.Packet.memory_wait":412.216,"Driver.Packet.draw":112.172,"Driver.Draw":111.247,"Driver.Packet.dispatch":90.800,"Graphics.Draw":87.720,"Driver.Dispatch":74.541,"Graphics.Draw.draw_and_resource_release":69.866},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-24416.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_NO_LABEL_READBACK_STORE":"1","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2475,"ms":5103.352},"presents":30,"frame_ms":{"p50":172.450,"p90":180.279,"p99":188.498,"max":188.498},"gpu_busy_ms_per_present":155.082,"worker_busy_pct":{"queue worker 0x0":98.922,"queue worker 0x48":94.536,"queue worker 0x40":97.806,"queue worker 0x46":9.819},"top_phases_ms_per_frame":{"Driver.Packet":511.698,"Driver.Packet.memory_wait":292.965,"Driver.Packet.draw":81.951,"Driver.Draw":81.123,"Graphics.Draw":78.857,"Driver.Packet.prepare_memory":63.955,"Graphics.Draw.draw_and_resource_release":62.787,"Driver.Packet.dispatch":51.645},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-7416.json.gz"}

Summary lines

Summary lines, in run order

{"commit":"8499ea52e571","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2611,"ms":5015.901},"presents":29,"frame_ms":{"p50":173.147,"p90":181.373,"p99":186.519,"max":186.519},"gpu_busy_ms_per_present":151.347,"worker_busy_pct":{"queue worker 0x0":98.839,"queue worker 0x40":97.548,"queue worker 0x48":94.123,"queue worker 0x46":8.428},"top_phases_ms_per_frame":{"Driver.Packet":516.652,"Driver.Packet.memory_wait":298.262,"Driver.Packet.draw":90.309,"Driver.Draw":89.216,"Graphics.Draw":80.815,"Graphics.Draw.draw_and_resource_release":64.445,"Driver.Packet.prepare_memory":53.686,"Driver.Packet.dispatch":53.488},"trace_dropped":false,"trace":"aps5-trace-8499ea52e571-2948.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":1475,"ms":5197.119},"presents":23,"frame_ms":{"p50":226.296,"p90":232.880,"p99":234.640,"max":234.640},"gpu_busy_ms_per_present":187.450,"worker_busy_pct":{"queue worker 0x0":99.190,"queue worker 0x40":97.325,"queue worker 0x48":95.909,"queue worker 0x46":6.362},"top_phases_ms_per_frame":{"Driver.Packet":673.520,"Driver.Packet.memory_wait":389.958,"Driver.Packet.draw":100.619,"Driver.Draw":99.800,"Driver.Packet.dispatch":90.922,"Graphics.Draw":82.755,"Driver.Dispatch":71.122,"Graphics.Draw.draw_and_resource_release":65.923},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-17776.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_NO_LABEL_READBACK_STORE":"1","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":3010,"ms":5017.114},"presents":28,"frame_ms":{"p50":179.596,"p90":190.217,"p99":195.744,"max":195.744},"gpu_busy_ms_per_present":163.979,"worker_busy_pct":{"queue worker 0x0":98.999,"queue worker 0x40":97.533,"queue worker 0x48":94.075,"queue worker 0x46":10.182},"top_phases_ms_per_frame":{"Driver.Packet":538.517,"Driver.Packet.memory_wait":308.846,"Driver.Packet.draw":84.810,"Driver.Draw":83.983,"Graphics.Draw":83.010,"Driver.Packet.prepare_memory":71.773,"Graphics.Draw.draw_and_resource_release":66.116,"Recorder.WaitSerial":58.790},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-23972.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_NO_LABEL_READBACK_STORE":"1","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2323,"ms":5062.514},"presents":29,"frame_ms":{"p50":174.307,"p90":187.489,"p99":191.882,"max":191.882},"gpu_busy_ms_per_present":160.625,"worker_busy_pct":{"queue worker 0x0":98.995,"queue worker 0x40":97.597,"queue worker 0x48":94.506,"queue worker 0x46":7.728},"top_phases_ms_per_frame":{"Driver.Packet":521.154,"Driver.Packet.memory_wait":296.916,"Driver.Packet.draw":84.194,"Driver.Draw":83.361,"Graphics.Draw":80.184,"Graphics.Draw.draw_and_resource_release":63.343,"Driver.Packet.prepare_memory":61.495,"Driver.Packet.dispatch":56.760},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-16892.json.gz"}
{"commit":"8499ea52e571","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2664,"ms":5056.578},"presents":29,"frame_ms":{"p50":175.344,"p90":184.545,"p99":191.420,"max":191.420},"gpu_busy_ms_per_present":152.720,"worker_busy_pct":{"queue worker 0x0":98.853,"queue worker 0x48":94.134,"queue worker 0x40":98.081,"queue worker 0x46":10.864},"top_phases_ms_per_frame":{"Driver.Packet":526.070,"Driver.Packet.memory_wait":298.519,"Driver.Packet.draw":92.461,"Driver.Draw":91.344,"Graphics.Draw":82.121,"Graphics.Draw.draw_and_resource_release":65.645,"Driver.Packet.dispatch":57.175,"Driver.Packet.prepare_memory":56.659},"trace_dropped":false,"trace":"aps5-trace-8499ea52e571-25732.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":1516,"ms":5013.833},"presents":23,"frame_ms":{"p50":220.370,"p90":224.877,"p99":226.604,"max":226.604},"gpu_busy_ms_per_present":182.074,"worker_busy_pct":{"queue worker 0x0":99.213,"queue worker 0x40":97.721,"queue worker 0x48":95.720,"queue worker 0x46":6.078},"top_phases_ms_per_frame":{"Driver.Packet":650.255,"Driver.Packet.memory_wait":374.183,"Driver.Packet.draw":102.274,"Driver.Draw":101.459,"Driver.Packet.dispatch":89.549,"Graphics.Draw":79.504,"Driver.Dispatch":70.984,"Graphics.Draw.draw_and_resource_release":63.419},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-19404.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":1526,"ms":5044.540},"presents":23,"frame_ms":{"p50":221.365,"p90":225.279,"p99":227.497,"max":227.497},"gpu_busy_ms_per_present":192.251,"worker_busy_pct":{"queue worker 0x0":99.222,"queue worker 0x40":97.808,"queue worker 0x48":95.729,"queue worker 0x46":5.961},"top_phases_ms_per_frame":{"Driver.Packet":653.407,"Driver.Packet.memory_wait":374.531,"Driver.Packet.draw":98.166,"Driver.Draw":97.374,"Driver.Packet.dispatch":89.721,"Graphics.Draw":78.301,"Driver.Dispatch":71.563,"Graphics.Draw.draw_and_resource_release":62.337},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-29620.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_NO_LABEL_READBACK_STORE":"1","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2337,"ms":5129.506},"presents":30,"frame_ms":{"p50":172.646,"p90":179.053,"p99":180.541,"max":180.541},"gpu_busy_ms_per_present":156.592,"worker_busy_pct":{"queue worker 0x0":98.974,"queue worker 0x40":98.098,"queue worker 0x48":94.143,"queue worker 0x46":8.756},"top_phases_ms_per_frame":{"Driver.Packet":512.513,"Driver.Packet.memory_wait":294.924,"Driver.Packet.draw":80.717,"Driver.Draw":79.918,"Graphics.Draw":79.241,"Graphics.Draw.draw_and_resource_release":63.125,"Driver.Packet.prepare_memory":61.754,"Driver.Packet.dispatch":54.386},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-30000.json.gz"}
{"commit":"8499ea52e571","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2648,"ms":5125.625},"presents":28,"frame_ms":{"p50":185.789,"p90":193.517,"p99":196.563,"max":196.563},"gpu_busy_ms_per_present":158.488,"worker_busy_pct":{"queue worker 0x0":98.812,"queue worker 0x40":97.455,"queue worker 0x48":94.175,"queue worker 0x46":10.421},"top_phases_ms_per_frame":{"Driver.Packet":550.324,"Driver.Packet.memory_wait":315.726,"Driver.Packet.draw":95.194,"Driver.Draw":94.021,"Graphics.Draw":87.416,"Graphics.Draw.draw_and_resource_release":69.588,"Driver.Packet.prepare_memory":60.228,"Driver.Packet.dispatch":57.225},"trace_dropped":false,"trace":"aps5-trace-8499ea52e571-9252.json.gz"}
{"commit":"8499ea52e571","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2740,"ms":5104.085},"presents":30,"frame_ms":{"p50":170.504,"p90":180.225,"p99":182.853,"max":182.853},"gpu_busy_ms_per_present":149.548,"worker_busy_pct":{"queue worker 0x0":98.829,"queue worker 0x40":98.095,"queue worker 0x48":94.097,"queue worker 0x46":9.152},"top_phases_ms_per_frame":{"Driver.Packet":510.294,"Driver.Packet.memory_wait":290.369,"Driver.Packet.draw":92.094,"Driver.Draw":91.045,"Graphics.Draw":80.181,"Graphics.Draw.draw_and_resource_release":63.794,"Driver.Packet.prepare_memory":53.748,"Driver.Packet.dispatch":53.543},"trace_dropped":false,"trace":"aps5-trace-8499ea52e571-26348.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_NO_LABEL_READBACK_STORE":"1","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":2348,"ms":5137.774},"presents":30,"frame_ms":{"p50":169.685,"p90":180.911,"p99":187.736,"max":187.736},"gpu_busy_ms_per_present":154.000,"worker_busy_pct":{"queue worker 0x0":98.963,"queue worker 0x40":97.893,"queue worker 0x48":94.419,"queue worker 0x46":11.877},"top_phases_ms_per_frame":{"Driver.Packet":518.583,"Driver.Packet.memory_wait":294.634,"Driver.Packet.draw":84.076,"Driver.Draw":83.246,"Graphics.Draw":79.948,"Graphics.Draw.draw_and_resource_release":63.510,"Driver.Packet.dispatch":61.458,"Driver.Dispatch":58.987},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-22764.json.gz"}
{"commit":"777bdbb4f80b","dirty":false,"env":{"APS5_HOST_IMPORT_MIB":"13312","APS5_TRACE_DIR":"<path>","APS5_TRACE_SECONDS":"150:5"},"gpu":"NVIDIA GeForce RTX 4070 Ti SUPER","driver":"NVIDIA 616.64","os":"Windows 10.0.26200","cpu":"11th Gen Intel(R) Core(TM) i7-11700K @ 3.60GHz","cpu_threads":16,"memory_mib":32599,"title_id":"PPSA21567","title":"ASTRO BOT","content_version":"01.019.000","resolution":"3840x2160","window":{"spec":"seconds 150:5","first_present":1492,"ms":5003.134},"presents":23,"frame_ms":{"p50":218.825,"p90":224.425,"p99":225.379,"max":225.379},"gpu_busy_ms_per_present":179.584,"worker_busy_pct":{"queue worker 0x0":99.178,"queue worker 0x48":95.798,"queue worker 0x40":97.256,"queue worker 0x46":5.078},"top_phases_ms_per_frame":{"Driver.Packet":645.372,"Driver.Packet.memory_wait":375.514,"Driver.Packet.draw":96.481,"Driver.Draw":95.614,"Driver.Packet.dispatch":88.517,"Graphics.Draw":80.971,"Driver.Dispatch":69.968,"Graphics.Draw.draw_and_resource_release":64.168},"trace_dropped":false,"trace":"aps5-trace-777bdbb4f80b-31296.json.gz"}

Traces

In the next comment: one zip per round with that round's three traces and their summary lines, and one zip with the two confirmation runs.

Digest

trace_digest.py, first line of each trace, in run order, then the two confirmation runs

aps5-trace-8499ea52e571-2948.json.gz: **seconds 150:5** from present 2611: 29 presents, frame p50 173.1 / p90 181.4 / p99 186.5 / max 186.5 ms, GPU busy 151.3 ms per present
aps5-trace-777bdbb4f80b-17776.json.gz: **seconds 150:5** from present 1475: 23 presents, frame p50 226.3 / p90 232.9 / p99 234.6 / max 234.6 ms, GPU busy 187.4 ms per present
aps5-trace-777bdbb4f80b-23972.json.gz: **seconds 150:5** from present 3010: 28 presents, frame p50 179.6 / p90 190.2 / p99 195.7 / max 195.7 ms, GPU busy 164.0 ms per present
aps5-trace-777bdbb4f80b-16892.json.gz: **seconds 150:5** from present 2323: 29 presents, frame p50 174.3 / p90 187.5 / p99 191.9 / max 191.9 ms, GPU busy 160.6 ms per present
aps5-trace-8499ea52e571-25732.json.gz: **seconds 150:5** from present 2664: 29 presents, frame p50 175.3 / p90 184.5 / p99 191.4 / max 191.4 ms, GPU busy 152.7 ms per present
aps5-trace-777bdbb4f80b-19404.json.gz: **seconds 150:5** from present 1516: 23 presents, frame p50 220.4 / p90 224.9 / p99 226.6 / max 226.6 ms, GPU busy 182.1 ms per present
aps5-trace-777bdbb4f80b-29620.json.gz: **seconds 150:5** from present 1526: 23 presents, frame p50 221.4 / p90 225.3 / p99 227.5 / max 227.5 ms, GPU busy 192.3 ms per present
aps5-trace-777bdbb4f80b-30000.json.gz: **seconds 150:5** from present 2337: 30 presents, frame p50 172.6 / p90 179.1 / p99 180.5 / max 180.5 ms, GPU busy 156.6 ms per present
aps5-trace-8499ea52e571-9252.json.gz: **seconds 150:5** from present 2648: 28 presents, frame p50 185.8 / p90 193.5 / p99 196.6 / max 196.6 ms, GPU busy 158.5 ms per present
aps5-trace-8499ea52e571-26348.json.gz: **seconds 150:5** from present 2740: 30 presents, frame p50 170.5 / p90 180.2 / p99 182.9 / max 182.9 ms, GPU busy 149.5 ms per present
aps5-trace-777bdbb4f80b-22764.json.gz: **seconds 150:5** from present 2348: 30 presents, frame p50 169.7 / p90 180.9 / p99 187.7 / max 187.7 ms, GPU busy 154.0 ms per present
aps5-trace-777bdbb4f80b-31296.json.gz: **seconds 150:5** from present 1492: 23 presents, frame p50 218.8 / p90 224.4 / p99 225.4 / max 225.4 ms, GPU busy 179.6 ms per present
aps5-trace-777bdbb4f80b-24416.json.gz: **seconds 150:5** from present 1420: 21 presents, frame p50 238.7 / p90 251.2 / p99 263.1 / max 263.1 ms, GPU busy 215.0 ms per present
aps5-trace-777bdbb4f80b-7416.json.gz: **seconds 150:5** from present 2475: 30 presents, frame p50 172.4 / p90 180.3 / p99 188.5 / max 188.5 ms, GPU busy 155.1 ms per present

Capture

The caches were warm (the scene ran once and the title was restarted)
No other APS5_TRACE_* or APS5_PROFILE_* switch was set and the log was not redirected: no other such switch was set, but stdout and stderr went to files through the launcher (Start-Process -RedirectStandardOutput), the same for every run in the table; two confirmation runs without redirection are under Confirmation without redirection
Captures compared here come from the same machine, scene and settings

Traces for the report above: one zip per round with that round's three traces and their aps5-summary.jsonl lines, in the order of the table, and one zip with the two confirmation runs.

astrobot-crashsite-6948-round1.zip
astrobot-crashsite-6948-round2.zip
astrobot-crashsite-6948-round3.zip
astrobot-crashsite-6948-round4.zip
astrobot-crashsite-6948-confirmation.zip

I confirmed on current main that VulkanDevice::WriteLabelOnGpu calls StorageTexture::StoreReadbackBeforeLabel("readback before label") on each label path, before the recorder and argument checks, so the reported cost path is present in source. The A/B data also shows that simply disabling the store is not a valid fix because it restores the stale-read failures this change addressed.

One constraint for a follow-up: a per-title switch would conflict with the project rule to implement generic behavior rather than title-specific workarounds. A generic way to defer publication until a CPU read or wait actually observes the label could avoid the per-label sweep, but it needs to preserve ordering for both the Kena occlusion and Smurfs light cases and be tested against them.

Thanks, agreed on both points: switching the store off is not a fix, and a per-title setting is out. The generic route you describe is the one I would take in the pull request: defer the store until the CPU actually observes the result, through a read or wait on the label or through an access to the image's own pages, keeping the Kena (linear) and Smurfs (small tiled) ordering. It would come with tests for both cases next to agc_driver_linear_readback_label, and I will open it once my open pull request limit allows.

A data point for narrowing it, from a title that depends on the store: Gang Beasts (CUSA04865, PS4, Unity 2017.2 with Enlighten), the case I confirmed on #6948.

There the store is what keeps the realtime lightmaps right. Enlighten copies its albedo and emissive meta-pass textures into a linear scratch image, writes an end-of-pipe label and reads the scratch on the CPU after it; without the store every static surface of the menu is white.

What the store does in that title (Windows 11, RTX 2080, driver 617.14; main menu, APS5_PROFILE_DRAW=1, 150 s):

133 stores before labels in the whole run, 0x200–0x9000 bytes each, all of them during loading; none at end-of-pipe interrupts and none once the menu runs.
Presents per 10 s, two 95 s runs each way: store on 328–350, APS5_NO_LABEL_READBACK_STORE=1 335–354, GPU busy 22–24 ms per frame both ways.

So any narrowing should still cover a linear image a dispatch or a GPU copy wrote before a label the CPU then polls; those are the images Gang Beasts needs, and they are few and small. Stores at every label in a busy frame, as on Crash Site, are what that title never does.

These numbers are from a local branch (main of 2026-10-22 plus the PS4 stack), not from current main. I can rerun Gang Beasts on a branch with the narrowed store and post the lightmap check and presents, if that helps.

🤖 Generated with Claude Code

The same regression on AMD, found independently with a bisect over all the merges between two main commits.

Setup: Windows 11 (10.0.26200), AMD Radeon RX 9070 XT, AMD driver 26.10.1, Ryzen 7 5800X3D, 64 GB. PPSA21567 Crash Site, no input, warm shader cache. Besides a shared shader cache directory, only the measurement switches are set (APS5_PROFILE_DRAW=1, APS5_TRACE_SUMMARY_EVERY=10, APS5_NO_PAD_INPUT=1). Each run lasts 300 s and uses the 10 s windows from 120 s on: FPS and the µs figures are means, frame p50 and GPU busy are medians.

Bisect: git bisect --first-parent from 1631964 (fast) to 938812d (slow), 109 merges. The first slow merge is a7d342e (#6948).

Its parent 8948f1c: GPU busy 61.3 ms per present, 5.3 µs wait per draw for room in the draw queue.
a7d342e itself: 83.0 ms, 9.5 µs.
Across the 7 steps, every slow step was 83.0–88.6 ms and 9.5–10.0 µs, and every fast one was 60.6–65.7 ms and 4.9–5.3 µs.

On main 1e1c355, alternating runs in one session:

Run	`APS5_NO_LABEL_READBACK_STORE`	FPS	Frame p50 (ms)	GPU busy per present (ms)	µs per draw commit
1	1	8.29	120.3	65.8	28.1
2	unset	6.83	145.3	89.6	36.3
3	1	8.12	119.2	66.5	29.6
4	unset	5.81	182.4	88.6	43.3

So the cost is not specific to NVIDIA.

@MarcZX10

@MarcZX10, before I write the fix for this, a question about the first step. There are now two routes, and I'd rather not duplicate work.

Data, store on as by default

Our run: upstream main 5d3ab77, ASTRO BOT (PPSA21567) 01.019.000 in the Crash Site hub (-lvl hub_crashsite). Windows 11, Intel Core i7-11700K, NVIDIA GeForce RTX 4070 Ti SUPER, driver 616.64.
- Defaults plus APS5_HOST_IMPORT_MIB=13312, with APS5_PROFILE_DRAW=1, which adds its own cost.
- One run of 200 s; eight 10 s windows once the level had settled, 45-47 presents per 10 s.
- Write-backs: the [storage] lines report 1,335-1,592 write-backs with the reason readback before label per window, 1,428 on average. That is 5,909-6,443 MiB per 10 s, 6,141 MiB (6.0 GiB) on average, so about 134 MiB per present.
@danielradosa's light hub numbers (#357), on an RTX 4060 with his build:
- 169-171 presents per 10 s with the store;
- 249-259 with APS5_NO_LABEL_READBACK_STORE=1;
- 223-235 with his 1 MiB limit on linear images (9391d551b7, APS5_LABEL_STORE_MAX_KIB).
An internal run of ours with the store off points to the same order of magnitude. I'm not posting it as a number, since that configuration is not a fix.

The two routes (AI-assisted)

Size limit, danielradosa's commit.
- It is small and already measured. It keeps the reads this store was added for: Kena's occlusion image (about 127 KiB per store in fix(agc): store linear compute writes behind their dispatch #6948) and the Smurfs' 1x1 image are well under 1 MiB, and ntamas94 describes the Gang Beasts scratch images as few and small.
- It is a size cut-off, though. A title that reads a linear image over 1 MiB on the CPU after a label would read stale data again.
Asynchronous store. The image copies are recorded into the open batch ahead of the label.
- A label the GPU stores in that batch already follows everything recorded before it (Recorder::RecordStore), and a label stored by a completion at the reap follows the batch that holds the copies.
- So the guest still sees the label only after the data, but the CPU no longer waits for the GPU at a label: today FlushPending syncs the recorder (Sync or FinishUpTo) whenever a pending image's writer is still open.
- The copies themselves stay, about 134 MiB per present in our run; only the CPU wait goes.
- It covers every pending image, so it also takes off the CPU's path the 2,057 small images (326 MiB) per 10 s that, by his count, the limit still stores.
- This is a different shape from what I wrote on 23 October: deferring until the CPU reads would need access faults on the game's threads, which main is removing (fix(libc): stop write-protecting resident runs on Windows #9181).

Which would you take as the first step:

the limit now, opened by danielradosa if he wants to;
the asynchronous store;
or the limit first, with the asynchronous store on top later?

Whichever it is, the tests would cover the linear and small tiled cases next to agc_driver_linear_readback_label, and ntamas94 offered to check Gang Beasts on the narrowed store.

AI-assisted: yes

I’d take the asynchronous store as the first step. The size limit is smaller, but it knowingly restores stale CPU reads for any linear image above the threshold; the issue does not establish that all supported title readbacks stay below 1 MiB. Recording the image copies before the corresponding label preserves the existing coverage while targeting the measured CPU wait.

For the regression, I’d check that a CPU waiter which observes the label also observes the preceding image contents, for both linear and small tiled images, including label writes and end-of-pipe completion paths. The reported ~134 MiB per present means the copy bandwidth remains a separate cost to measure, but it doesn’t undermine the evidence that removing the synchronous wait is the behavior-preserving first experiment.

@panicDa3m0n

Thanks for the report and the bisect, @panicDa3m0n and @BunnyFl. I agree with the asynchronous store as the first step.

The Kena case it has to keep: Kena: Bridge of Spirits (PPSA01802, UE4). A compute dispatch copies the 256x256 HZB occlusion result into a linear 256 KiB image, and the CPU reads that image after a label. Without the store, terrain and characters pop in and out. On my runs (Linux, RX 9070 XT, RADV) the store did about 740 write-backs per 10 s, 55 MiB in total, so Kena never showed the per-label cost you see on Crash Site.

When your PR is open I can run Kena on it, with and without APS5_NO_LABEL_READBACK_STORE=1, and check the popping. Plain main currently doesn't get Kena past the menus because the host import budget collapses (#8091), so that test would be main + #8091 + your PR.

AI-assisted: yes (Claude Code)

@panicDa3m0n

@panicDa3m0n, another AMD data point, with amdvlk on Windows, and an offer: I can A/B the async store on this machine as soon as it is up.

Host: Windows 11 (26300), Ryzen 7 5700X, 32 GB RAM, Radeon RX 9060 XT, AMD driver 26.10.1, WinLibs GCC 15.2.0 r7, Release.
Runs: ASTRO BOT PPSA21564 01.007.000, -lvl hub_crashsite, no input, 300 s per run, two alternating rounds after warm-up. APS5_HOST_IMPORT_MIB=14336 and APS5_TRACE_SUMMARY_EVERY=10, windows from 120 s on. Build: main 5d3ab77 with perf(agc): keep draw snapshots in resizable BAR memory #9712.

`APS5_NO_LABEL_READBACK_STORE`	FPS	frame p50	GPU busy / present
unset	6.37, 6.43	156.5, 155.3 ms	99.5, 98.8 ms
1	7.62, 7.43	128.0, 134.1 ms	74.0, 76.3 ms

The store costs about 25 ms of frame and 24 ms of GPU busy per present here, in line with the RTX 4070 Ti SUPER and RX 9070 XT numbers above.
With APS5_SAMPLE_COMMITTER, StorageTexture::StoreReadbackBeforeLabel is 9.8 % of the draw committer's samples (inclusive, under Driver::commitLabel → VulkanDevice::WriteLabelOnGpu). On this scene the committer is the thread that bounds the frame: the queue 0 worker spends 25–30 % of its samples in DrawPipeline::Enqueue, waiting for it (25 % on this build, 29–30 % on the perf(shader): reuse an evicted result's storage for the next patched result #10757 A/B builds).

AI-assisted: yes (Claude Code). The runs were made on my machine.

@QDarkRex

@QDarkRex, thank you for the AMD data and for the offer: yes, please. The pull request for the asynchronous store waits on CONTRIBUTING's limit of one open pull request per author until one of theirs is merged; mine is #9712. When it is up, I will name you in its "How to help" section and ask you there for the A/B.

@alfalfa-star, the same for the Kena check you offered: I will name you in that section too, with main + #8091 as you describe, and ask when the pull request is open.

AI-assisted: yes

Where the time of the label-time store goes, as input for the asynchronous store planned above. Windows / AMD, ASTRO BOT intro, measured with local timers.

Setup

PPSA21567 01.019.000, New Game into the opening level (intro_next), played by hand, 7-minute runs; guest 3840x2160.
Windows 11, Ryzen 7 5800X3D, Radeon RX 9070 XT, AMD driver 26.10.1.
Timer runs: main 9605300 plus local-only timers around the steps of WriteLabelOnGpu, StoreReadbackBeforeLabel and FlushPending (not for merging), with APS5_PROFILE_DRAW=1. These files are the same at 0c1c001.
The timers split queue 0x0 from all other queues (mostly 0x40/0x48).

Share of the label write. Over one run, StoreReadbackBeforeLabel was 33.9 s of the about 35 s spent inside WriteLabelOnGpu, 77.9 µs per call on average. All of it runs under the GPU mutex, at whichever packet's lock records the labels. On the dispatch path of the other queues, the profiled labels phase is about 110 µs per dispatch in the intro (median of the 10 s windows).

The store itself. About 12 % of the other queues' label writes and 3 % of queue 0x0's find a pending linear or small image. One run's FlushPending calls that store one, averaged over all of them:

	calls	µs each	GPU sync part (`Reap` + `Sync`/`FinishUpTo`)	write-back recording	image bytes per call (upper bound)
other queues	57,726	690	461 µs (74 % of the calls sync)	223 µs	about 5.1 MiB
queue `0x0`	105,249	505	375 µs (28 % of the calls sync)	126 µs	about 4.1 MiB

That is about 39.8 s and 53.2 s of queue-worker time under the GPU mutex in one 7-minute run.
FlushDepthPlanes, the pending scan, nothingToStore and the shadow publish take about 2 µs or less each.
With a host import, the write-back records the copy, detile and import copy into the open batch. Its CPU cost is that recording plus the block bookkeeping (CollectWritesUncached, ChangedBlocks).

Which syncs. A counter on upstream main 0c1c001 looked at the first 160,000 label-time flushes:

71,557 of them would sync;
in 48,171 (67 %), the only pending writer over the range is the image's own earlier store. That is the case open fix(agc): do not wait for a storage image's own stamped writes before flushing it #12070 targets (not waiting for the image's own earlier stores).

A local two-line variant of that alone (own store notes for every image, not only drawn targets; build 24358bcbd9) gave 832 presents against 819 on main 0c1c001, in one pair of APS5_TRACE_SECONDS=240:60 captures. That is +1.6 %, within the noise of one pair, and the windows began at different presents because the play was by hand.

Which images. One run with APS5_TRACE_FLUSH=1 (build 24358bcbd9, 7 minutes, 5,752 presents) logged about 156,300 readback before label stores:

58 images (address and size): 32 of 64 KiB or less, 26 larger;
15 of them stored more than 4,600 times each, 0.8 times per present or more;
the most frequent: 1.34 MiB 33,528 times, 3.96 MiB 11,384, 64 KiB 9,336, 6.25 MiB about 8,300, 25 MiB 8,298, and three of 16.88 MiB about 5,766 times each.

With APS5_NO_LABEL_READBACK_STORE=1 (same timer build), the other queues' labels phase is about 3 µs per dispatch, against about 110 with the store.

Reading.

Removing the wait takes about two thirds to three quarters of the label-time FlushPending time off the queue workers.
On this scene, removing most own-store syncs (the variant above) did not change presents beyond noise. So the frame-rate gain may also need fewer or cheaper write-backs.

AI-assisted: yes (Claude Code)

Navigation Menu

Repository navigation

perf: ASTRO BOT's Crash Site is about 47 ms slower per frame since #6948's label readback store #10364

Title and scene

What is slow or what changed

Confirmation without redirection

Summary lines

Traces

Digest

Capture

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

perf: ASTRO BOT's Crash Site is about 47 ms slower per frame since #6948's label readback store #10364

Description

Title and scene

What is slow or what changed

Confirmation without redirection

Summary lines

Traces

Digest

Capture

Activity

panicDa3m0n commented on Oct 23, 2026

MarcZX10 commented on Oct 23, 2026

panicDa3m0n commented on Oct 23, 2026

ntamas94 commented on Oct 23, 2026

BunnyFl commented on Oct 24, 2026

panicDa3m0n commented on Oct 24, 2026

MarcZX10 commented on Oct 24, 2026

alfalfa-star commented on Oct 25, 2026

QDarkRex commented on Oct 26, 2026

panicDa3m0n commented on Oct 26, 2026

BunnyFl commented on Oct 31, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions