Raf callbacks don't seem to be aligned to vsync at all |
|||||||||||||||||
Issue descriptionGoogle Chrome 60.0.3112.101 (Official Build) (64-bit) Revision 1f3c0cf4b3083dfbe4da434af1726820cf384ce3-refs/branch-heads/3112@{#723} OS Mac OS X JavaScript V8 6.0.286.54 This is on my Trash Can mac connected to a 4k display @ 24hz over hdmi. It's very strange that double raf would vary from running 5ms apart or 41ms apart. The tests are taken on an about:blank page, note that the times reported make no sense at all, sometimes raf is running 0.575ms later, sometimes it's much 20ms, and sometimes it's 40ms. requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 117 VM279:1 19.479999999995925 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 119 VM281:1 15.495000000009895 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 121 VM284:1 16.489999999990687 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 123 VM286:1 24.464999999996508 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 125 VM289:1 17.90000000000873 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 127 VM291:1 23.719999999986612 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 129 VM293:1 13.084999999991851 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 131 VM295:1 41.7899999999936 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 133 VM298:1 29.49000000000524 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 135 VM300:1 22.179999999993015 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 137 VM302:1 31.805000000007567 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 139 VM313:1 5.10999999998603 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 141 VM316:1 36.554999999993015 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 197 VM680:1 6.814999999944121 requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) 199 VM683:1 0.5749999999534339
,
Aug 30 2017
Works fine in Firefox too. This is definitely something wrong with Chrome 60 stable.
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
33
42.280000000000655
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
35
42.17499999999927
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
37
41.659999999999854
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
39
42.039999999999054
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
41
40.68000000000029
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
43
41.25
,
Aug 30 2017
I was able to repro in Chrome 62 on a Macbook Pro. Marking P1 since this seems pretty bad to me.
,
Aug 30 2017
,
Aug 30 2017
Also broken on Chrome OS. I also attached a trace from the devtools and a screenshot that shows that the raf callbacks really did fire 1ms apart.
Google Chrome 61.0.3163.51 (Official Build) beta (64-bit)
Revision 0
Platform 9765.31.0 (Official Build) beta-channel chell
Firmware Version Google_Chell.7820.253.0
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
24
(unknown) 13.565000000002328
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
26
(unknown) 1.6350000000093132
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
28
(unknown) 4.279999999998836
requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })
30
(unknown) 13.739999999990687
,
Aug 30 2017
This seems really serious that the rendering pipeline is no longer vsync aligned.
,
Aug 30 2017
The times reported to raf itself are spaced to vsync:
requestAnimationFrame((t) => { requestAnimationFrame((t2) => console.log(t2 - t)) })
requestAnimationFrame((t) => { requestAnimationFrame((t2) => console.log(t2 - t)) })
205
VM419:1 16.665999999531778
requestAnimationFrame((t) => { requestAnimationFrame((t2) => console.log(t2 - t)) })
207
VM421:1 16.665999999531778
requestAnimationFrame((t) => { requestAnimationFrame((t2) => console.log(t2 - t)) })
209
VM423:1 16.665999999531778
and if we cause sustained callbacks they do settle on vsync:
() => requestAnimationFrame(() => { let t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t) || f()) })
f()
1
VM465:1 6.450000000000728
VM465:1 16.715000000000146
VM465:1 16.575000000000728
VM465:1 17.18999999999869
VM465:1 16.579999999999927
VM465:1 17.1299999999992
VM465:1 16.36999999999898
VM465:1 16.81999999999789
So maybe this is begin-main-frame-before-activation?
,
Aug 30 2017
URGENT - PTAL. Your bug is labelled as Stable ReleaseBlock, pls make sure to land the fix and get it merged into the release branch ASAP. Thank you! Please note we're planning to cut M61 Stable RC this week on Thursday/Friday.
,
Aug 30 2017
+ suzyh@ & skyostil@. This bug was originally reported on M60 and we're planning to promote M61 to Stable next week.
,
Aug 30 2017
,
Aug 30 2017
Would you mind testing with --disable-main-frame-before-activation?
,
Aug 30 2017
When waking up from idle, the compositor generates a "MISSED" begin frame. The frame time is calculated based on the vsync offset and phase, but the begin frame is sent right away. Sustained begin frames should be fine. Removing these missed begin frames might regress input latency benchmarks. brianderson@ knows more about why this was added initially.
,
Aug 30 2017
I don't think this should be a release blocker as we've had this behavior for a long time.
,
Aug 30 2017
,
Aug 30 2017
The goal with the MISSED frames is to draw the first frame coming out of idle as soon as possible. The assumption being that it was likely initiated by an input event such as a tap or drag. This is especially important if the main thread gets frame-aligned input since delaying the rAF would always add an extra frame of latency. I was under the assumption the frame-aligned input effort was going to align input for the main thread in addition to the compositor. Tim, Dave, is that the plan? If we are going to deliver input events to the main thread unthrottled, the MISSED logic could be hurting us when the input events are unfortunately aligned.
,
Aug 31 2017
I'm a little bit confused. This isn't the first frame after idle but the second. I'm printing the time from the body of the raf callback to an immediately invoked second callback. What this shows is: Idle -> frame -> 1ms later -> frame -> vsync -> frame. I think the bug is that we're still generating the immediate frame even though we're in the middle of a frame?
,
Aug 31 2017
How much input are you sending before rAF; you say the times are aligned. We are processing input before we call the rAF callback. Have you tried with --disable-features=RafAlignedMouseInput ?
,
Sep 1 2017
There's no input, I'm running these experiments from the devtools console.
,
Sep 4 2017
Were the timestamps in #7 also recorded using the 24 Hz screen? If so, I find it strange that they'd be giving you a 16ms interval instead of a 42ms one. Even it we make the timestamps correct, we should also check that every frame is getting consistent input latency. Unfortunately I don't have a non-60 Hz screen to test with right now, but I might be able to borrow a TV from somewhere.
,
Nov 3 2017
+brianderson@ for triage.
,
Feb 26 2018
GPU triage: ping on P1 issue?
,
Apr 24 2018
Reducing priority since this isn't a bug or a regression but working-as-intended. Leaving it open though since there's a question of whether the intention is correct. 2 frames 1ms apart is definitely unexpected and we should consider improving or removing the MISSED frame logic.
,
Apr 28 2018
,
Aug 3
,
Aug 16
I've talked to Brian and we've concluded that it's working as intended. |
|||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||
Comment 1 by esprehn@chromium.org
, Aug 30 2017The same test run inside Safari reports totally reasonable times for the 4k display @ 24hz. It seems Chrome's vsync is totally broken here? > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 1 [Log] 42.59999999999491 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 3 [Log] 41.900000000001455 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 5 [Log] 40.599999999998545 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 7 [Log] 41.70000000000073 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 9 [Log] 40.89999999999782 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 11 [Log] 41.599999999998545 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 13 [Log] 41.29999999999927 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 15 [Log] 42.70000000000073 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) }) < 17 [Log] 42.19999999999709 > requestAnimationFrame(() => { t = performance.now(); requestAnimationFrame(() => console.log(performance.now() - t)) })