v2.1.0, RX 9070 XT, 4K HDR + frame generation: render targets remade ~3.6 times a frame, VRAM reaches the allowed limit, then the main and presentation threads stop (freeze on breaking a jar) #2180
Labels
No labels
accessibility
autorelease: pending
autorelease: tagged
bug
dependencies
documentation
duplicate
enhancement
github_actions
good first issue
help wanted
invalid
question
testing wanted
wontfix
No milestone
No assignees
1 participant
No due date set.
Dependencies
No dependencies set
Reference
MagicBeanDev/Hookshot#2180
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Hookshot version
v2.1.0 (source 10a10b90), built from source with make_game.py. Not a stock build: three local changes (the one-line RGB10A2 format-class workaround from #2038, a host-side sprint patch, and a hook that swaps one tone-map fragment stage for another SPIR-V module at load). I have not yet repeated this on the stock renderer, so please weigh it accordingly; I will post that result here.
What kind of problem
Freeze (picture stops, the process stays alive)
What happened
Two bad sessions out of two on v2.1.0, same PC that has run v2.0.9 and v2.0.13 for days:
Responding = True) until I ended it a minute later.What the log of the second session shows:
vk: write-back diff: VRAM 14706 of 14706 MB: the shadows given back (352 MB). Heap 2 readsused 230 of 230 MB. The fps reports go 50.3, 46.0, 43.8, 49.5, 45.3, 40.6, 19.2.sead::MainThreadandPresentation Threadlines onlyrmbl::VibrationThreadkeeps logging. Nodevice lost, nofailed (-4), nonot made (-13), no write-back timeout. This is the same signature as two comments in #996 (RX 6800 on v2.0.11, and RX 6650 XT on v2.0.12 after closing a menu).vk: render targets drawn over from another start, let go: 104529 so far (605746 MB)after 29,280 presents, about 3.6 a frame, and it speeds up through the session (3 early on, 8,727 a third of the way in, 49,137 at the half, 97,486 near the end).vk: render target images: 48212 reused from the pool, 57466 made new, 57153 destroyed from it.vk: texture slots registered again at another size: 2000000. Render-target image blocks peaked at36 blocks 4608 MB, 657 images 4165 MB. Textures reached 7,223 MB against the 6,144 MB budget.let go: 167 so far (717 MB)and289 so far (1335 MB),render target images: 46 reused from the pool, 281 made new, render-target blocks8 blocks 1024 MB.vk: memory: ... privategoes 18,769 MB, 29,662 MB, 32,459 MB, 33,428 MB on a 32 GB PC (commit nearly exhausted). v2.0.13 shows the same shape about 4.7 GB lower (14.1 GB to 25.6 GB), so this part looks like a higher plateau, not a steady leak.What I can not tell yet: the two v2.1.0 sessions differ from my v2.0.13 logs in three ways at once (the version, frame generation on, and free roaming instead of a fixed bench route). #2156 reports VRAM pressure in Kokiri Forest that is new in v2.1.0 on another card, which is why I am filing this now instead of after the A/B runs.
Where in the game
Kokiri Forest, free roaming; the freeze came on breaking a jar.
How often
2 bad sessions of 2 on v2.1.0 (one PC reset, one freeze).
Graphics card and driver version
AMD Radeon RX 9070 XT (16 GB), Vulkan 1.4, driver 0x8001a0 as the log reports it.
CPU, RAM and operating system
Intel Core i9-9900K, 32 GB DDR4, Windows 11 Pro 22631, 23.5 GB page file.
Changes from the defaults
HDR: an HDR10 surface (format 64), paper white 200 nits, peak 1000 nits), swapchain 3840x2097.quality_preset=0(Custom),resolution=1,upscaling=2,hdr=2,frame_generation=2(log:frame interpolation ready: Auto, a frame for each of the display's refreshes (120 Hz; up to 4 a game frame); the session that ended in the PC reset logged8x the game's frames).RX_VK_WB_DIFF=1,RX_VK_PRESENT_QUEUE=1,RX_VK_CHUNK=480,RX_VK_PREFETCH_CHUNKS=2,RX_VK_PARALLEL=4,HOOKSHOT_NO_UPDATE_CHECK=1.Other software hooked into the game
No overlays or injectors. Recording software was closed before the second session.
hookshot_log.txt
I can attach the full log of the freeze session (12 thousand lines). The last lines before the stop:
Questions
RX_VK_CHECKPOINTS=1, something else)?Next from my side
Same build with
frame_generation=0, then the stock renderer, thenRX_VK_VRAM_MB=4096for headroom. Results will go in this issue.Before you send it
Correction to point 1 of my report, from the person at the PC (I wrote it from the Windows event log alone, which was wrong):
The first session did not end in a spontaneous reset. The whole PC hung when the Graphics row "Frame pacing" was switched to Off in the settings menu, about 100 seconds after the long first-start preparation had finished (4,800 presents into play): the picture stopped and nothing else on the PC responded either, so it was powered off by hand. That forced power-off is what Windows recorded as Kernel-Power 41 (bugcheck code 0, no minidump, no LiveKernelEvent 141). The game log of that session simply ends, with no error line; a few lines before its end it has
frame interpolation ready: 8x the game's frames.So the two v2.1.0 sessions were:
Two things that differ from how this PC normally runs the game, so please read the report with them in mind:
frame interpolation ready: 8x the game's framesin the first;Auto ... up to 4 a game frameat the start of the second, and the options file saved 79 s before the freeze hasframe_generation=2). The player believes it was off, so the row may have been changed without meaning to; the usual install here runs with it off. In the second session the lastframe interpolation:report before the freeze has most frames shown 17-25 ms apart, so few or no made frames were being shown by then.resolution=1(100 % render) andframe_generation=2; the usual install runs at 75 % render. I do not know the render percentage of the first session.Everything else in the report stands. A/B runs under a safety stop have started (frame generation off first, then the freeze settings again, the stock renderer, and a smaller texture budget); the results will follow here.
Update from a night of runs under a safety stop, with three corrections to my report first.
Corrections
vk_texture.cppabout the market's per-frame scratch targets is in v2.0.13 too.frame interpolation:report against the game's fps gives 1.65 to 2.19 shown per game frame in every one of the last 16 reports, most of them 2.00 or 2.01 (for example 504 in a report at 50 fps). Over the whole run the row had been stepped Auto, Off, 2x, 4x, 8x (two reports at 8.1 per game frame, no hang), Off, Auto, 2x. The freeze came in steady 2x, 79 s after the last change. AMD FSR 3.1 was also the upscaler for part of the run (fsr3: 3840x2160 -> 3840x2160) and had been switched back to the game's own by then. #2185 (same card, FSR 3.1 + 2x, "toggling Fullscreen fixes it") may be the same stall; we did not know to try that.New: the render-target part happens at plain settings, no frame generation needed
Same build, market save, 3840x2160 output, render 75 %, the game's own upscaler, frame generation off, Custom preset (budget 6144 MB), 90 s standing then a scripted walk, 330 s in all. No freeze. From the log:
render target images: ... made newVRAM peaked at 11,738 of 14,581 MB allowed. Hyrule Field with the same settings and walk: 7,354 let go in 21,000 presents, blocks 1,152 MB.
What the blow-ups have in common: the cache is over its budget
In both runs the reports where the target blocks jump are the ones where the textures are over the budget, and no others:
textures 7201 MB (budget 6144 MB)and7223 MB, VRAM 92.3 %, blocks 13 -> 36 (1,664 -> 4,608 MB) in one report interval;textures 6683 MB (budget 6144 MB), the report with 3,968 MB of blocks.From there the freeze run retires 6,216-15,441 textures per 500 log lines, against 1,124-2,125 before.
Reading
texture_frame: withtotal_bytes > budgetthe pass is not a sweep, walks the textures oldest first and stops once the excess down to 7/8 of the budget is chosen. The targets another has drawn over are the youngest in that order, so the pass does not reach them: live textures unused for 60 presents go and are uploaded again, while the dead targets stay and keep the total over the budget. That is the behaviour #2198 describes and fixes for theRX_VK_COMPACThold; hereRX_VK_COMPACTwas off and it is the budget's own pass.Next from us (results will follow here, runs only): the market walk with
RX_VK_VRAM_MB=9000; the same walk with a local change that lets an over-budget pass take the dead targets first, A/B by a switch on one build; and a v2.0.13 run of the same market save if we can set up a v2.0.13 copy.Not shown by any of this: why the picture finally stops. The log's last lines are three compute-pipeline compiles of about 3 s each and VRAM at 14,706 of 14,706 MB, then nothing from the Presentation or main thread. A run with
RX_VK_HANG_DUMPset is part of the plan.A correction to my last comment, after one more run and a closer read of the same logs.
I wrote that what the target-block jumps have in common is that the cache is over its budget. That reads like a cause, and it is not one:
textures N MBfigure includes the render targets' images. Taking away theimage blocks (render targets): ... images M MBfigure of the same report leaves a flat rest: 2,876 and 3,058 MB in the freeze run's two over-budget reports, 3,135 MB in the market run's one. What went over is the target images themselves: 4,325 MB in 542 images, 4,165 MB in 657, 3,548 MB in 831, where the reports around them have about 210-230 images and 1.0-1.2 GB. So the over-budget report and the block jump are one event, a pile of target images 3 to 4 times the usual size.RX_VK_VRAM_MB=9000and nothing else changed: textures never over the budget (6,973 MB at most), and the target blocks still reached 3,456 MB (3,968 at 6144), with 84,307 targets let go (85,842) and 46,940 made new (48,480). A bigger budget does not stop the blocks growing. It kept about 0.9 GB more of other textures resident (median 4,031 against 3,159 MB), and at what looks like an area change at the end VRAM went to 12,201 of 14,581 MB.textures retired. Most of those are the let-go targets themselves: 86.0 % in the freeze run, 85.6 % in the 6144 market run, 97.7 % in the 9000 one. What is left over is larger at 6144 (12,549 retirements against 2,002, more than half of them in the one report interval after the over-budget report), which fits an over-budget pass taking other textures first, but with reports 600 presents apart that is a weak sign, not a result.So: the open question on the memory side is why the pile of drawn-over target images sometimes grows to 3 or 4 times its usual size before it is let go. Next from us are runs that let dead targets go sooner (
RX_VK_DEAD_MIN_UNUSED,RX_VK_DEAD_EVERY) and the A/B of the dead-targets-first change at a budget low enough to be over it. Still nothing here explains the picture stopping; that needs the run with frame generation 2x andRX_VK_HANG_DUMP.A second, separate cause of a stopped picture on this card, not memory: present ahead (Frame generation 2x) together with
RX_VK_PRESENT_QUEUE=1, which was our own opt-in setting. Runs, hang-dump frames and what avoids it are in #1702: #1702A separate memory factor on Windows, found while chasing a whole-PC hang: the start that builds the shader programs keeps much more RAM than a start that finds them, and keeps it in play.
Same PC (RX 9070 XT 16 GB, 32 GB RAM, Windows 11), v2.1.0 built from source with a few local changes (none of them in the shader build or the heap), same save, same spot.
At the title screen (one run each):
46604 program keys kept)0 program keys kept, thenprepared 38809 shader programs (46597 new, 70 failed ...))In play, standing at the same spot (last
vk: memory:line of each run; the kept runs are shorter, the built runs stood there 2.5 to 7 minutes):So the process that built the programs holds about 4.7 GB more of the PC's RAM in play, and a 32 GB PC is left with about 1 GB free. Neither of those runs hung. An earlier session that had started the same way did hang the whole PC right after 8x was picked, with nothing in Windows' logs; we could not reproduce that, so we do not claim this is its cause.
The game's log has no
malloc_trimline on Windows. In the source the trim after translation is inside#if defined(__linux__) && defined(__GLIBC__)(thevk: memory:block in vk_texture.cpp), and its comment describes this growth ("the heap's growth ... never going back"). Closing the game after the build and starting it again gives the first row of each table.What we tried as a Windows counterpart, in a local build: once, after
precompile_runof a start whoseprepare_runran,_heapmin(),HeapCompacton the process heap, thenSetProcessWorkingSetSize(GetCurrentProcess(), -1, -1). One run: working set 13,675 -> 6 MB at that moment, private 18,730 -> 18,724 MB (the heap calls gave back next to nothing, as expected of a fragmented heap); in play the working set settled at 9,273 MB, the PC kept 9.1 GB or more free, and fps and the slowest-frame lines were the same as without it (median of the run's fps lines 46.2 against 45.8; slowest frame per 600 after the load 26.4 to 64.9 ms against 26.5 to 63.2 ms). The private bytes stay (30.7 GB): what the build left is in the page file now, not in RAM.Is that worth having upstream, or is "restart once after the shader build" the intended answer on 32 GB? Happy to send the few lines if useful.
Follow-up to the comment above on the start that builds the shader programs. Two more measurements, same PC (RX 9070 XT 16 GB, 32 GB RAM, Windows 11, commit limit 56,240 MB), same local v2.1.0 build, frame generation off unless said.
1. Emptying the working set fixes the RAM, not the commit.
A save next to an area boundary, then walking across it and back in a loop (input script):
So a crossing costs about 5 GB of private bytes in either process (textures went 3,081 -> 6,046 MB in the same seconds; no
VRAM fullline; free RAM stayed above 7.8 GB in the built runs). The process that built the programs simply goes in about 2.5 GB higher, and on this PC that is the difference between 7.4 GB and under 6 GB of commit room. We did not let it run on, so how low it goes is not measured.2. "Restart once after the build", done by the game itself.
Tried in the local build: when
prepare_runbuilt the programs in this start (2,000 or more), then afterprecompile_runthe process saves the pipeline cache, starts its own command line again and ends. It setsHOS_RESTART_OFthe way the host's own restart (hos_relaunch.c) does, so the first log is kept ashookshot_log.1.txt. An environment mark stops the new process from doing it twice.One run, same save and walk as above:
0 program keys kept,prepared 38809 shader programs (46597 new, 70 failed ...) in 145.4 s, ended by itself 175 s after the start46604 program keys kept,precompile: 8390 programs, 10829 graphics and 933 compute pipelines ... in 5677 ms,start-up: the shaders took 6.1 sThose are the numbers of a start that found its programs (first row of the table). Cost: the start-up screen is shown twice on the one start that builds.
Not claimed: one run only; and none of this is shown to be the cause of the whole-PC hang this issue started with, which we still have not reproduced.
Happy to describe either change in more detail, or send the lines, if that is useful.
The room where the freeze of this issue happened now reproduces the memory side of it on demand, and the log says what the jump is made of. Same PC as above (RX 9070 XT 16 GB, 32 GB RAM, Windows 11), v2.1.0 built from source, 3840x2160, Frame generation Auto, default texture budget (6144 MB), all runs under a safety stop.
Where. Castle Town, the small guard room behind a door near the town gate (one guard, a wall torch, about 15 pots, crates). The player was in this room when the picture froze.
What happens (4 of 4 runs at these settings). Walking in through the door, and in the first run again while moving through the room, the game's video memory (Windows' per-process counter, read once a second) goes up by 1.9 to 2.7 GB within one second:
Outside the room the same stick movements make no jump. Breaking pots is not needed for it; the door is enough.
What the jump is made of (run 2, the
vk: VRAM:block before the door against the block at the peak):Pool counters over that stretch: made new +4,858, reused +4,681, destroyed +3,572; 9,505 textures retired. The eight biggest textures are the same before and after, so nothing big is new: it is about 1,300 mid-size targets. The
-> vklines in that stretch are mostly depth targets (NVN 0x34) at 384x384 and at square sizes whose side changes from frame to frame (404 ... 1515), next to the usual 3840x2160 / 1920x1080 / 960x540 ones. A walk across the drawbridge and market (frame generation 2x, same budget) has none of the 0x34 depth-target lines.The log of the session that froze (first post) ends with the same picture, about twice as large: 18,719 textures retired in its last 269 lines, 43.9 textures made a frame, the pool at 802 MB, then
VRAM 14706 of 14706 MB: the shadows given back.Why they pile up, as far as I can read
vk_texture.cpp.texture_framesits behindif (frame_no % 10) return;. A frame's scratch targets are dead after 3 unused frames, but then wait up to 9 more presents for the pass. With 23 to 44 textures made a frame (the frozen session's last blocks) that is several hundred images. (RX_VK_DEAD_EVERYbelow 10 has no effect because of that line.)pool_trimdestroys at most 16 images a present (64 only above 90 % of the allowance), so a pool at almost six times its bound drains slowly.What helped here (local experiment: one build, same route, one run switched off and two switched on). While a regular pass finds that the last ten presents let 64 or more shifted targets go, or made 64 or more target images new, run the dead-target sweep on the presents in between as well (sweep only: targets another has drawn over, never a live texture, no budget cut), and let
pool_trimtake 64 a present while the pool holds more than twice its bound.The switched-on runs stayed in the room for about 5 and about 9 minutes with pots picked up and thrown, camera turns and sword swings (the switched-off run was stopped 3 seconds after the door); in play neither has a gap of 100 ms or more between presents (biggest 66 and 81 ms). On the walk across the drawbridge and market the same build shows no cost against the build before it: gaps of 100 ms or more 58 against 58,
slow submitlines 73 against 73, mean 46.9 against 46.7 fps. It also changes nothing at that walk's peak (13,787 against 13,844 MB), which is not made of dead targets.A smaller texture budget also holds the room (
RX_VK_VRAM_MB=4096: peak 13,630 / 13,956 MB, one run), but the cache still overshoots it by up to 1.4 GB between two passes there.Not shown. The stopped picture itself has not come back in this room on our current build: our stop ended the first four runs before it could. Two runs with the change are two runs. One of the three starts with the change (the two room runs and the walk) had a quiet spell right after the save load, before play (0.7 fps over 12.9 s, the game read no controller for 14 s; about 6 s of that was our own tool writing a dump). The dump shows the submitting thread inside the driver under
submit_recordingand no thread invk_texture.cpp. The other two starts with the change loaded clean, and so did the four without it that I checked. Not understood. I have not found why this room makes the changing square targets (a guess: one small shadow map per object under the torch, sized by its size on screen).A side note on the pots. In one run, while pots were thrown and seeds shot in that room, two compute pipelines compiled in play (0.35 s and 3.4 s, on a worker, the dispatch left out meanwhile, so the picture went on); an earlier run with pots thrown had none, so what brings them is not pinned down. The frozen session's log has five (up to 26.9 s, also on a worker). The keys are added to the list of dispatched compute programs and built at the next start, so each costs once. The note in the source expects such a first dispatch to take milliseconds from the caches; here it did not, and I do not know why the caches were cold for them.
Happy to share the diff (one file,
vk_texture.cpp, two environment switches to turn it off) if it is of use.Follow-up to my comment above: one correction and two more runs (same PC, same settings, same room).
Correction: a smaller texture budget does not reliably hold the room. I wrote that
RX_VK_VRAM_MB=4096holds it (13,630 / 13,956 MB, one run). A second run at 4096, without the change, peaked at 14,511 / 14,930 MB while walking through the room after the door. That is as high as the runs at the default budget (14,511 to 14,832 MB). So please do not read the 4096 line above as a workaround.The change, third run, this time with the sword. The player tells me he was breaking the pots with the sword when the picture froze, so this run did only that on a fresh room (27 strings of sword swings). Peak 12,442 / 12,861 MB, reached at the entry; 12,084 MB during the sword part. Over three runs with the change: 12,615, 12,584 and 12,442 MB, against 14,511 to 14,832 MB over the four runs without it at the same budget. One-second rises still happen with the change (+2,178 MB at the entry in this run); what changes is where they top out. In play this run has two gaps of 100 ms or more between presents (234 and 143 ms) and none of 1 s; the save load was clean.
Compute pipelines and the sword. About a minute into the sword part (between 53 and 62 s after the first swing, after six strings of swings), four compute pipelines compiled in play within about 3 seconds: 234, 335, 285 and 3,375 ms, all on a worker, with 35
dispatch ... left outlines. The 234 ms gap between presents is at that moment. The run after it, same route, compiled none: the keys had been added to the list of dispatched compute programs. The same holds for the keys of the frozen session: its five are in that list on this install since that night, so no run of ours since has met them cold. The night of the freeze was the first evening on v2.1.0 here, with those compiles still to come in play.Still not shown: the stopped picture itself.
Thanks for the report. Reports of the same problem are now collected in #993, which lists this one with your details and links back here, so one fix closes them together and the open list stays readable. Follow #993 for the fix, and add new details there (or here). If this turns out to be a separate problem it will be reopened. Pull request #2484 works on this.