Frame generation 2x: frames reach the screen 5.7 / 11 ms apart instead of 8.3 (VRR flicker), with cause and a patch #1702
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
Due date
No due date set.
Dependencies
No dependencies set
Reference
MagicBeanDev/Hookshot#1702
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.0.12 (v2.0.13 changed none of this code; the patch applies to v2.0.13 and main
d8f0513)What kind of problem
Graphics (missing, black or wrong-coloured things, lighting, flicker)
What happened
With Frame generation 2x and Frame pacing on, frames reach the screen unevenly: alternately about 5.7 and 11 ms apart instead of every 8.33 ms, although the pacer hands them over evenly (its own log counts nearly all of them as "7-9 ms"). On a VRR display the refresh rate changes on every frame, which shows as flicker on an OLED (LG G6, 4K, 165 Hz, G-Sync). Expected: frames on screen every 8.33 ms.
Measured with Intel PresentMon 2.3.1 (
MsBetweenDisplayChange: when each frame reached the screen), 60 s of running and turning in Hyrule Field, the game at its 60 fps, DLSS Quality, 3840x2160:RX_VK_PRESENT_QUEUE=1(4 runs)RX_VK_FSR_FG=0, 60 s of normal playRX_VK_PRESENT_QUEUE=1alone, Reflex (on and Boost) and RTX HDR off did not change it (92-96% of frames shifting > 4 ms on v2.0.10).Cause. PresentMon's GPU time per present alternated about 11.7 / 1.1 ms.
present_imagesubmits its copy into the swapchain image on the replay queue (dev.queue, afterqueue_flush_locked()and the full barrier). When the game frame's turn comes, the next game frame's rendering (about 11 ms here) is already on that queue, so the copy and the present wait for it, while the made frame's go out at once. The pacer's times are right, but every other frame reaches the screen about 3 ms late.Patch (59 added lines in 3 files; applies to main
d8f0513, v2.0.12 and v2.0.13, which changed none of this code): for a set of two frames,display_mainsubmits both copies right away (withpresent_defer_intoset,present_imagestops aftervkQueueSubmit2), waits for the first copy's fence, and keeps onlyvkQueuePresentKHRon the pacer's times (present_commit).RX_VK_PRESENT_AHEAD=0turns it off.It needs
RX_VK_PRESENT_QUEUE=1to work fully: on the replay queue the present itself still waits behind the next frame (the "patch only" row). I know the separate present queue has been off by default since it black-screened some NVIDIA 621 setups (#1161). Here (RTX 5080, 617.42) it has run without a problem through all of today's tests and play. So this may need another way to keep the presents from queueing behind the next frame; the numbers above are there to compare against.present-ahead.patch
Related: #1005 (flicker tracker). Also, about #1635: with v2.0.12's default 2x, moving characters ghosted here too. FSR 3.1 frame interpolation gets only the camera's motion (as
vk_fsr3_inputs.hsays, until #1008), andRX_VK_FSR_FG=0(the renderer's own interpolation) looked clean.Found, patched and measured with the help of Claude (an AI assistant). The numbers are from real runs on this PC, and the game has been played with the patch since.
Where in the game
Everywhere with Frame generation 2x; measured in Hyrule Field (running and turning)
How often
Every time
Graphics card and driver version
RTX 5080, NVIDIA 617.42
CPU, RAM and operating system
Ryzen 7 7800X3D, 32 GB, Windows 11 Pro (26200)
Changes from the defaults
Frame generation 2x, Frame pacing on, NVIDIA DLSS (Quality, preset L), output 3840x2160, fullscreen. Display: LG G6 OLED, 3840x2160 at 165 Hz, G-Sync.
hookshot_env.txt for the fixed runs: RX_VK_PRESENT_QUEUE=1, RX_VK_FSR_FG=0 (last fixed row only), HOOKSHOT_NO_UPDATE_CHECK=1.
Running alongside: NVIDIA RTX HDR (driver, per program) and the NVIDIA App overlay; the uneven timing was the same with RTX HDR off. PresentMon only traces (ETW).
Other software hooked into the game
Yes (named under "Changes from the defaults")
hookshot_log.txt
[hos host] hookshot v2.0.12 (source 88587426)
Stock 2x (the pacer's view is even, yet PresentMon shows 5.7 / 11 ms on screen):
[hos host] vk: frame interpolation: 485 frames shown on time, 2 late (over 2 ms); shown apart: <7 ms 8, 7-9 469, 9-12 5, 12-17 2, 17-25 0, over 25 3
With the patch:
[hos host] vk: present ahead: a set's copies submitted at once, its presents on the line (RX_VK_PRESENT_AHEAD=0: off)
[hos host] vk: frame interpolation: 600 frames shown on time, 0 late (over 2 ms); shown apart: <7 ms 0, 7-9 599, 9-12 1, 12-17 0, 17-25 0, over 25 0
Screenshots or video
No response
Before you send it
Thank you for the PresentMon measurements and for tracking down the cause; that's exactly what this needed. Could you open the patch as a pull request against main, with
RX_VK_PRESENT_AHEAD=0as the off switch as you wrote it? That way it runs through CI and the fix carries your name. We'll A/B it here.One thing to keep in mind: the separate present queue stays opt-in (
RX_VK_PRESENT_QUEUE=1), because on NVIDIA's 621 drivers it lost the GPU at start (#1161). So the PR should help with the default single queue too, or keep any part that depends on the separate queue opt-in.Another frame generation 2x data point from Discord (RTX 4070, cap 240, v2.0.14, ghosting): the log shows FSR 3.1 frame interpolation made 0 of 600 frames ("without its inputs"), and 1027 of 1152 frames were late, mostly bunched less than 7 ms apart. So at 2x on that run the generated frames weren't coming from FSR 3.1 at all, and the presents were bunched as described here.
A data point on the "late, bunched under 7 ms" part. On this PC (v2.0.13 with present ahead, the own blend, an NVIDIA frame limit of 162 for the game, 165 Hz VRR), with the Frame rate cap at 81 the pacer reported about 800 of 810 frames late, all under 7 ms apart, only while 2x sat at that limit: in menus and on the title screen, where the game runs at the cap (game 81, GPU 2-3 ms, so 162 shown a second). In play, below the cap (game 67-76, 134-152 shown), it reported 0 late, and PresentMon at the same cap showed even delivery (0.1% of frames shifting more than 4 ms, median 6.8 ms).
So a cap of 240 at 2x may show "late, bunched" whenever twice the game's rate is above the refresh rate or a driver limit, with or without FSR 3.1.
Present ahead together with the separate present queue stops the picture for good on an RX 9070 XT; either one alone does not, in these runs.
Setup. RX 9070 XT (log:
AMD Radeon RX 9070 XT, Vulkan 1.4, driver 0x8001a0), Windows 11, 3840x2160 HDR, swapchain4 images, immediate, Frame generation 2x, Frame pacing on, Render resolution 100%. v2.1.0 built from source with a few local diagnostic changes; one of them is the log line quoted below (the frame slot's fence inpresent_imagewaited for in 2 s pieces instead of without end).RX_VK_PRESENT_QUEUE=1was our own setting (it is opt-in, as noted in #1702);RX_VK_WB_DIFF=1was set too.Runs. Each a fresh launch, 2x from the start, then standing and walking in the Market for up to 150 s. "Stopped" = no new frame until the process was ended: two of the four stops were ended by our watchdog about 8 s after they began, the other two were left alone for 80 s and 110 s without a frame, so only those two show that it lasts. Each arm was checked by its own log lines (
presents on a queue of their own,present ahead: a set's copies submitted at once,frame interpolation ready: 2x).RX_VK_PRESENT_QUEUE=1)RX_VK_PRESENT_AHEAD=0)(The last row is the 28 other runs of the same night with frame generation off: different tests, several minutes each, not a matched arm.) The four stops came at 565, 567, 4,813 and 6,098 presents: two between the logo movie and the title, two in play. The runs that did not stop reached 7,800 to 10,920 presents (two of them, one in each single-switch arm, were ended at 7,800 by our own memory guard, not by a stop). The last VRAM report before the two in-play stops was 9,195 and 9,739 MB used of 15,450 MB allowed, so this is not the memory case of #2180.
What the stop looks like, the same each time:
repeated up to 80 s and 110 s in the two runs that were left alone. No device lost, no failed submit, no acquire timeout. In the hang dump (
RX_VK_HANG_DUMP):mkw_vk display:display_main->present_image-> the driver's wait: the wait for the frame slot'sdonefence. By the return address it is the present-ahead loop's second call (k = 1), so the set's first image is acquired and copied and not yet presented.wait_recorded-> the driver's wait (the recordings' timeline):sead::MainThreadthroughn_nvnSyncWait->waitin the two start-up dumps, aModuleSystemWorkerthroughrx_nvn_invalidate->invalidatein the two in-play ones.The display thread's place is the same in all four dumps.
With 3 frame slots, the copy that never finishes is the previous set's first one (k = 0), the one
display_mainwaits at most 100 ms for before both of that set's presents go out. As far as we can read, the only semaphore wait on the main queue in the renderer is that copy's wait for its acquire semaphore, and the order of the calls is acyclic (every present after its copy, every acquire after the earlier copies). So the main queue looks parked on an acquire signal that never arrives, with the game's own submits behind it.A possible reason, not shown. The swapchain's
minImageCountcomment says "mailbox with frame interpolation: an image always free". AMD's Windows driver has no mailbox, so the swapchain is immediate; with two images held and the presents coming from the compute-family queue, the next acquire may return an image whose release still depends on a present that has not run. That part is inside the driver and we cannot see it.What would have avoided it here. Present ahead not taken while the presents have their own queue:
present_ahead_wanted(vk_framegen.cpp) gets one more condition,dev.present_queue == VK_NULL_HANDLE. A narrower or wider rule (only with mailbox, only on some drivers) is yours to judge; the default configuration (single queue) did not stop in 4 of 4 runs here.Limits: one card, one scene, 150 s a run, 4 runs an arm. Not tested: 3x and up, Frame pacing off, other areas. I can run more arms on this card if one would help, for example the first copy's fence waited for without the 100 ms limit.
Follow-up to my comment above: the Frame generation row on Auto takes the same path on this card (120 Hz display, log:
frame interpolation ready: Auto, a frame for each of the display's refreshes (120 Hz; up to 4 a game frame)), own present queue on in both runs:RX_VK_PRESENT_AHEAD=0: 1 run, 9,000 presents through two area changes, no stop (ended by our own memory guard).Totals now, with
RX_VK_PRESENT_QUEUE=1: present ahead on, 5 runs stopped of 6; present ahead off, 0 of 6 (five at 2x, one of them four minutes of area changes, and this Auto run).One correction to what I wrote about the hang dump: in this Auto dump the display thread sits in the same wait for the frame slot's
donefence, but it got there from the loop's directpresent_imagecall (a set that was not two frames), not from the present-ahead loop's second call. So the call that waits is simply the third present after the copy that never finishes; "the second call of the present-ahead loop" holds for the four 2x dumps only.Follow-up with a local change that makes the pair safe, tested on the same card (RX 9070 XT, 120 Hz display).
The change is one extra condition where present ahead is decided in vk_framegen.cpp: it is used only when presents do NOT go on a queue of their own. So
RX_VK_PRESENT_QUEUE=1wins and present ahead stays off, whateverRX_VK_PRESENT_AHEADsays.With both asked (
RX_VK_PRESENT_QUEUE=1,RX_VK_PRESENT_AHEAD=1):In the six new runs the log has
presents on a queue of their own, of compute family 1and nopresent ahead:line; each reached play and ran its 150 s play window (9,949 to 10,857 rows per run in the present trace). The five stopped runs before were at 565 to 6,098 presents.What this does not do: it avoids the pair, it does not explain it. Why the frame slot's
donefence never signals when the copies of a set are submitted at once while the presents go through the second queue is still open on our side. Both settings are opt-in here, so this may not matter to anyone else; the condition is there if you want it.Thanks for testing this so thoroughly. A data point from an NVIDIA card, in case it helps keep the pair where it works: on an RTX 5080 (driver 617.42, Windows 11, 4K 165 Hz VRR, swapchain
4 images, mailbox), present ahead withRX_VK_PRESENT_QUEUE=1ran about 2 hours of play and 10 test runs without a stop. Here that pair is what gives the even delivery: 0.1% of frames shifting more than 4 ms, against 6-28% with present ahead alone on the single queue and 88% with neither.Your 9070 XT log shows
4 images, immediate, so the difference may be AMD or immediate mode rather than the present queue as such. If a condition goes in, one limited to that case would keep the pair on cards where it works.Thanks, that is a useful data point, and you are right about the condition as I wrote it: it switches the pair off for everyone, which would take away the even delivery you measured on the RTX 5080.
What I can say from this side:
swapchain 3840x2160, 4 images, immediate. Going by the comment where the swapchain's mode is chosen invk_main.cpp, that is not a setting of ours: mailbox is taken when the driver offers it, and on Windows AMD's driver has none, so the game falls to immediate. On this card the two differences (AMD, immediate) come together.So if a condition goes in, one limited to the case seen here (a swapchain without mailbox, or the vendor) is the better form, as you say.
A correction to my last comment: I called both settings opt-in. Only the presents' own queue is (
RX_VK_PRESENT_QUEUE=1); present ahead is on by default. So leaving the code alone and noting the pair as unsafe on this card is also fine by me.Two runs would separate the two differences, if anyone has the time: the pair on an NVIDIA card with
RX_VK_IMMEDIATE=1(immediate without AMD), and the pair here withRX_VK_FIFO=1(AMD without immediate). I have not run the second one yet, and FIFO changes the pacing too, so a clean run there would only say the stop needs a mode other than FIFO.Thanks for the report. Reports of the same problem are now collected in #2510, which lists this one with your details and links back here, so one fix closes them together and the open list stays readable. Follow #2510 for the fix, and add new details there (or here). If this turns out to be a separate problem it will be reopened.