Bug 216122 – Consecutive requestAnimationFrame callbacks may be passed the same timestamp

• Component: Animations
• Status: RESOLVED FIXED

[Antoine Quint]

In some circumstances ScriptedAnimationController::serviceRequestAnimationFrameCallbacks() may be called more than once with the same timestamp which means that requestAnimationFrame() callbacks may end up being called twice for the same timestamp.

[Antoine Quint]

<rdar://problem/68269445>

[Antoine Quint]

Created attachment 407876 [details]
Patch

[Antoine Quint]

Created attachment 407878 [details]
Patch

[EWS]

Committed r266526: <https://trac.webkit.org/changeset/266526>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 407878 [details].

[Said Abou-Hallawa]

Comment on attachment 407878 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=407878&action=review

> Source/WebCore/dom/ScriptedAnimationController.cpp:101
> +    return timestamp <= m_lastAnimationFrameTimestamp || (isThrottledRelativeToPage() && (timestamp - m_lastAnimationFrameTimestamp < preferredScriptedAnimationInterval()));

How can this happen? timestamp should be always greater than m_lastAnimationFrameTimestamp. And assuming "timestamp < m_lastAnimationFrameTimestamp" can happen seems wrong. And rescheduling for the next rAF in this case looks wrong also. We already passed the timestamp the current rAF callbacks should be processed. What is the point in delaying processing them to the next rAF timestamp?

So I assume to meant to check "timestamp == m_lastAnimationFrameTimestamp". But this should not happen also. ScriptedAnimationController::serviceRequestAnimationFrameCallbacks() should be called only once for every document through Page::updateRendering(). If this happen either

1) we freezeNowTimestamp() more than we should. So multiple Page::updateRendering() get called with the same timestamp
2) or we call  ScriptedAnimationController::serviceRequestAnimationFrameCallbacks() multiple times from the same Page::updateRendering() while the timestamp is frozen.

And none of them should happen. So I would expect the bug is somewhere else unless I am confused. But the neither the bug description nor the ChangeLog explains the cause of this bug.

[Antoine Quint]

(In reply to Said Abou-Hallawa from comment #5)
> Comment on attachment 407878 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=407878&action=review
> 
> > Source/WebCore/dom/ScriptedAnimationController.cpp:101
> > +    return timestamp <= m_lastAnimationFrameTimestamp || (isThrottledRelativeToPage() && (timestamp - m_lastAnimationFrameTimestamp < preferredScriptedAnimationInterval()));
> 
> How can this happen?

I don't have the answer to this question yet, I'm still investigating. 

> timestamp should be always greater than
> m_lastAnimationFrameTimestamp. And assuming "timestamp <
> m_lastAnimationFrameTimestamp" can happen seems wrong. And rescheduling for
> the next rAF in this case looks wrong also. We already passed the timestamp
> the current rAF callbacks should be processed. What is the point in delaying
> processing them to the next rAF timestamp?

Triggering two rounds of callbacks with the same timestamp tripped up two WPT tests:

imported/w3c/web-platform-tests/css/css-animations/event-dispatch.tentative.html
imported/w3c/web-platform-tests/web-animations/interfaces/Animation/onremove.html

Those tests relied on the premise that a rAF callback being fired is indicative of "update the rendering" steps being ran.

> So I assume to meant to check "timestamp == m_lastAnimationFrameTimestamp".
> But this should not happen also.
> ScriptedAnimationController::serviceRequestAnimationFrameCallbacks() should
> be called only once for every document through Page::updateRendering(). If
> this happen either
> 
> 1) we freezeNowTimestamp() more than we should. So multiple
> Page::updateRendering() get called with the same timestamp
> 2) or we call 
> ScriptedAnimationController::serviceRequestAnimationFrameCallbacks()
> multiple times from the same Page::updateRendering() while the timestamp is
> frozen.
> 
> And none of them should happen. So I would expect the bug is somewhere else
> unless I am confused. But the neither the bug description nor the ChangeLog
> explains the cause of this bug.

Yes, I am investigating this still. However the codechange felt like a way to stabilize tests and address an obviously incorrect behavior while we look for the real culprit.

Once that's done, we can change this to ASSERT(timestamp > m_lastAnimationFrameTimestamp).

[Antoine Quint]

(In reply to Said Abou-Hallawa from comment #5)
> 1) we freezeNowTimestamp() more than we should. So multiple
> Page::updateRendering() get called with the same timestamp

This is not happening, the unfrozen timestamp returned by document.domWindow()->performance().now() is the same.

> 2) or we call 
> ScriptedAnimationController::serviceRequestAnimationFrameCallbacks()
> multiple times from the same Page::updateRendering() while the timestamp is
> frozen.

That is not happening either, m_renderingUpdateCount is increasing between calls to ScriptedAnimationController::serviceRequestAnimationFrameCallbacks() with the same timestamp.

[Antoine Quint]

Added some logging, here's a sequence of calls that eventually leads to a case where timestamp == m_lastAnimationFrameTimestamp.

02:26:37.313047-0700 TiledCoreAnimationDrawingArea::updateRenderingRunLoopCallback()
02:26:37.313127-0700 [0x10dcdcb00] Page::updateRendering(), updates = 0
02:26:37.313313-0700 [page 0x10dcdcb00, document 0x10dbe5780] now  = 4.000000s, updates = 0

02:26:37.327353-0700 TiledCoreAnimationDrawingArea::updateRenderingRunLoopCallback()
02:26:37.327383-0700 [0x10dcdcb00] Page::updateRendering(), updates = 1
02:26:37.327564-0700 [page 0x10dcdcb00, document 0x10dbe5780] now  = 18.000000s, updates = 1

02:26:37.327940-0700 TiledCoreAnimationDrawingArea::updateRenderingRunLoopCallback()
02:26:37.327960-0700 [0x10dcdcb00] Page::updateRendering(), updates = 2
02:26:37.327974-0700 [page 0x10dcdcb00, document 0x10dbe5780] now  = 19.000000s, updates = 2

02:26:37.333055-0700 TiledCoreAnimationDrawingArea::updateRenderingRunLoopCallback()
02:26:37.333077-0700 [0x10dcdcb00] Page::updateRendering(), updates = 3
02:26:37.333098-0700 [page 0x10dcdcb00, document 0x10dbe5780] now  = 24.000000s, updates = 3

02:26:37.352863-0700 TiledCoreAnimationDrawingArea::updateRenderingRunLoopCallback()
02:26:37.352893-0700 [0x10dcdcb00] Page::updateRendering(), updates = 4
02:26:37.352932-0700 [page 0x10dcdcb00, document 0x10dbe6430] now  = 17.000000s, updates = 4
02:26:37.352948-0700 serviceRequestAnimationFrameCallbacks(), timestamp = 0.017000s, m_lastAnimationFrameTimestamp = 0.000000s

02:26:37.353653-0700 TiledCoreAnimationDrawingArea::updateRenderingRunLoopCallback()
02:26:37.353676-0700 [0x10dcdcb00] Page::updateRendering(), updates = 5
02:26:37.353693-0700 [page 0x10dcdcb00, document 0x10dbe6430] now  = 17.000000s, updates = 5
02:26:37.353708-0700 serviceRequestAnimationFrameCallbacks(), timestamp = 0.017000s, m_lastAnimationFrameTimestamp = 0.017000s

All the calls come from TiledCoreAnimationDrawingArea::updateRenderingRunLoopCallback() and the two consecutive calls to that function come within 0.79ms (02:26:37.352863 and 02:26:37.353653) explaining why performance.now() returns the same value since I expect it's not expected to have more than 1ms-accuracy.

[Said Abou-Hallawa]

Okay I see.

RenderingUpdateScheduler can schedule a renderingUpdate at the next DisplayRefreshMonitor interval. This ensures there is a least 16ms between two consecutive renderingUpdates.

But RenderingUpdateScheduler also can schedule an immediate renderingUpdate which asks for a renderingUpdate at the next run-loop. See RenderingUpdateScheduler::scheduleRenderingUpdate().

So it seems what is happening with the flaky tests is we schedule an immediate renderingUpdate which is fast enough to hit the same timestamp we used in the previous renderingUpdate.

So I think the patch is okay. But maybe the right thing to do is to ensure rAF is served after at least 16ms

bool ScriptedAnimationController::shouldRescheduleRequestAnimationFrame(ReducedResolutionSeconds timestamp) const
{
<<    return timestamp <= m_lastAnimationFrameTimestamp || (isThrottledRelativeToPage() && (timestamp - m_lastAnimationFrameTimestamp < preferredScriptedAnimationInterval()));
>>    return timestamp - m_lastAnimationFrameTimestamp < preferredScriptedAnimationInterval());
}

I think, if the difference between timestamp and m_lastAnimationFrameTimestamp is 1ms for example, rAF should not be served. The reason for adding the immediate renderingUpdate scheduling is in some cases we want to update the page urgently and we can not wait for the next DisplayRefreshMonitor interval. But I think rAF never needs to be served in this case.

[Antoine Quint]

(In reply to Said Abou-Hallawa from comment #9)
> Okay I see.
> 
> RenderingUpdateScheduler can schedule a renderingUpdate at the next
> DisplayRefreshMonitor interval. This ensures there is a least 16ms between
> two consecutive renderingUpdates.
> 
> But RenderingUpdateScheduler also can schedule an immediate renderingUpdate
> which asks for a renderingUpdate at the next run-loop. See
> RenderingUpdateScheduler::scheduleRenderingUpdate().
> 
> So it seems what is happening with the flaky tests is we schedule an
> immediate renderingUpdate which is fast enough to hit the same timestamp we
> used in the previous renderingUpdate.
> 
> So I think the patch is okay. But maybe the right thing to do is to ensure
> rAF is served after at least 16ms
> 
> bool
> ScriptedAnimationController::
> shouldRescheduleRequestAnimationFrame(ReducedResolutionSeconds timestamp)
> const
> {
> <<    return timestamp <= m_lastAnimationFrameTimestamp ||
> (isThrottledRelativeToPage() && (timestamp - m_lastAnimationFrameTimestamp <
> preferredScriptedAnimationInterval()));
> >>    return timestamp - m_lastAnimationFrameTimestamp < preferredScriptedAnimationInterval());
> }
> 
> I think, if the difference between timestamp and
> m_lastAnimationFrameTimestamp is 1ms for example, rAF should not be served.
> The reason for adding the immediate renderingUpdate scheduling is in some
> cases we want to update the page urgently and we can not wait for the next
> DisplayRefreshMonitor interval. But I think rAF never needs to be served in
> this case.

I think we need to consider the other steps under Page::updateRendering(). This patch addressed requestAnimationFrame() callbacks but updating animations is another step that likely shouldn’t be performed until the next “real” frame. I guess we need to distinguish between the work required internally to update the rendering and what is Web-observable.