Bug 207153 – Timestamps should be the same for all rendering update steps

• Status: RESOLVED
• Resolution: FIXED
• Component: New Bugs

[Jason Lawrence]

animations/animation-callback-timestamp.html 

Description:
This test is flaky failing on iOS wk2.

History:
https://results.webkit.org/?limit=50000&platform=ios&suite=layout-tests&test=animations%2Fanimation-callback-timestamp.html

Diff:
--- /Volumes/Data/slave/ipados-simulator-13-debug-tests-wk2/build/layout-test-results/animations/animation-callback-timestamp-expected.txt
+++ /Volumes/Data/slave/ipados-simulator-13-debug-tests-wk2/build/layout-test-results/animations/animation-callback-timestamp-actual.txt
@@ -1,4 +1,5 @@
-PASS All the differences between requestAnimationFrame() callback timestamps and Performance.now() were within 3ms.
+requestAnimationFrame() timestamp = 634, window.performance.now() = 649
+FAIL Some of the requestAnimationFrame() callback timestamps were larger than Performance.now() by more than 3ms.
 PASS successfullyParsed is true
 
 TEST COMPLETE

[Radar WebKit Bug Importer]

<rdar://problem/59127682>

[Jason Lawrence]

Created attachment 389578 [details]
Update Test Expectations

[Ryan Haddad]

Comment on attachment 389578 [details]
Update Test Expectations

Clearing flags on attachment: 389578

Committed r255606: <https://trac.webkit.org/changeset/255606>

[Ryan Haddad]

I see an instance of this test failing on 11/10/2019 @ r252317.

[Jacob Uphoff]

This test is also failing on macOS.

[Jacob Uphoff]

Updated test expectations here:https: //trac.webkit.org/changeset/256319/webkit

[Jason Lawrence]

I am able to reproduce this issue on r256303 with the command below.
run-webkit-tests animations/animation-callback-timestamp.html --iterations 5000 -f --ios-simulator --debug --force --child-processes 1

[70/5000] animations/animation-callback-timestamp.html failed unexpectedly (WebKitTestRunnerApp crashed [pid=48974])
Retrying 1 unexpected failure ...
Running 1 WebKitTestRunnerApp.app
4999 tests ran as expected, 1 didn't:

[Said Abou-Hallawa]

Created attachment 397116 [details]
Patch

[Said Abou-Hallawa]

The test was checkin whether the difference between the rAF callback timestamp and the window.performance.now() is less than 3ms. This may fail on slow and busy hardware where calling the JavaScript callback and executing some of its code may take 3ms or more.

[Simon Fraser (smfr)]

Isn't this reflecting a bug in our implementation, where we don't freeze Performance.now() for the "update the rendering" steps? See https://html.spec.whatwg.org/multipage/webappapis.html#event-loop-processing-model step 9.

[Said Abou-Hallawa]

Created attachment 397326 [details]
Patch

[Said Abou-Hallawa]

Created attachment 397328 [details]
Patch

[Antoine Quint]

Comment on attachment 397328 [details]
Patch

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

> Source/WebCore/page/DOMWindow.cpp:752
> +

These names are pretty generic and do not suggest what is being frozen. I'm not sure what value having those methods on DOMWindow serves either, there is a single call site for either of those methods, feels like they could go through `performance()` directly.

[Simon Fraser (smfr)]

Comment on attachment 397328 [details]
Patch

Actually, reading the specs some more, I'm not sure that performance.now() should be frozen, but we do want the intersectionObserver part of the patch. Could you make a test that tests whether perf.now() is frozen in other browsers?

[Simon Fraser (smfr)]

Created attachment 397345 [details]
Test for frozen performance.now()

[Antoine Quint]

Note that document.timeline.currentTime is frozen as well and matches the rAF timestamp.

[Said Abou-Hallawa]

Created attachment 397428 [details]
Patch

[Said Abou-Hallawa]

Created attachment 397439 [details]
Patch

[Simon Fraser (smfr)]

Comment on attachment 397439 [details]
Patch

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

> Source/WebCore/page/DOMWindow.h:355
>      WEBCORE_EXPORT double nowTimestamp() const;
> +    void freezeNowTimestamp();
> +    void unfreezeNowTimestamp();
> +    double frozenNowTimestamp() const;

It should would be nice of nowTimestamp() and frozenNowTimestamp() returned Seconds.

> Source/WebCore/page/DOMWindow.h:475
> +    Optional<double> m_frozenNowTimestamp;

Seconds

> Source/WebCore/page/IntersectionObserver.cpp:258
> +        timestamp = std::round(1000 * window->frozenNowTimestamp());

We need a Seconds -> DOMHighResTimeStamp helper somewhere.

> Source/WebCore/page/Page.cpp:1330
> +    Vector<WeakPtr<Document>> initialDocuments;
> +    forEachDocument([&initialDocuments] (Document& document) {
> +        document.domWindow()->freezeNowTimestamp();
> +        initialDocuments.append(makeWeakPtr(&document));
> +    });

I think it's OK to do it like this for now, but longer term I'd like to see the frozen "now" time be generated in this function, and passed down into all the functions that need it. That would require having each document compute its own frozen now time based on its time origin, but it would be nicer than storing temporary state on DOMWindow.

> Source/WebCore/page/Page.cpp:1349
> -        DOMHighResTimeStamp timestamp = document.domWindow()->nowTimestamp();
> +        DOMHighResTimeStamp timestamp = document.domWindow()->frozenNowTimestamp();

Wait, do we need some seconds/milliseconds conversion here? The lack of types makes it hard to know.

> LayoutTests/intersection-observer/intersection-observer-callback-timestamp.html:1
> +<!DOCTYPE HTML>

This should be a WPT if there's no test that detected our buggy behavior.

> LayoutTests/intersection-observer/intersection-observer-callback-timestamp.html:6
> +<style>

<style> should go in the <head>

[Said Abou-Hallawa]

Created attachment 397719 [details]
Patch

[Said Abou-Hallawa]

Comment on attachment 397439 [details]
Patch

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

>> Source/WebCore/page/DOMWindow.h:355
>> +    double frozenNowTimestamp() const;
> 
> It should would be nice of nowTimestamp() and frozenNowTimestamp() returned Seconds.

Done in https://bugs.webkit.org/show_bug.cgi?id=210990.

>> Source/WebCore/page/DOMWindow.h:475
>> +    Optional<double> m_frozenNowTimestamp;
> 
> Seconds

Ditto.

>> Source/WebCore/page/IntersectionObserver.cpp:258
>> +        timestamp = std::round(1000 * window->frozenNowTimestamp());
> 
> We need a Seconds -> DOMHighResTimeStamp helper somewhere.

No need to convert Seconds -> DOMHighResTimeStamp since DOMWindow::frozenNowTimestamp() and IntersectionObserver::nowTimestamp() are now returning Seconds.

>> Source/WebCore/page/Page.cpp:1330
>> +    });
> 
> I think it's OK to do it like this for now, but longer term I'd like to see the frozen "now" time be generated in this function, and passed down into all the functions that need it. That would require having each document compute its own frozen now time based on its time origin, but it would be nicer than storing temporary state on DOMWindow.

I tried that but some of the IntersectionObserver test failed. The reason is an IntersectionObserver in a document can observe element in another document. So passing the frozenTimestamp of a document here to Document::updateIntersectionObservations() will not help if the element belongs to another document.

>> Source/WebCore/page/Page.cpp:1349
>> +        DOMHighResTimeStamp timestamp = document.domWindow()->frozenNowTimestamp();
> 
> Wait, do we need some seconds/milliseconds conversion here? The lack of types makes it hard to know.

We do need the conversion anymore since DOMWindow::frozenNowTimestamp() now returns ReducedResolutionSeconds and Document::serviceRequestAnimationFrameCallbacks() and DocumentTimelinesController::updateAnimationsAndSendEvents() both take ReducedResolutionSeconds.

>> LayoutTests/intersection-observer/intersection-observer-callback-timestamp.html:1
>> +<!DOCTYPE HTML>
> 
> This should be a WPT if there's no test that detected our buggy behavior.

Will do.

>> LayoutTests/intersection-observer/intersection-observer-callback-timestamp.html:6
>> +<style>
> 
> <style> should go in the <head>

Done.

[Simon Fraser (smfr)]

(In reply to Said Abou-Hallawa from comment #21)
> Comment on attachment 397439 [details]

> > I think it's OK to do it like this for now, but longer term I'd like to see the frozen "now" time be generated in this function, and passed down into all the functions that need it. That would require having each document compute its own frozen now time based on its time origin, but it would be nicer than storing temporary state on DOMWindow.
> 
> I tried that but some of the IntersectionObserver test failed. The reason is
> an IntersectionObserver in a document can observe element in another
> document. So passing the frozenTimestamp of a document here to
> Document::updateIntersectionObservations() will not help if the element
> belongs to another document.

That was exactly my point with 'That would require having each document compute its own frozen now time based on its time origin"

[Said Abou-Hallawa]

Created attachment 397751 [details]
Patch

Unmark animation tests as failed in the TestExpectations files.

[EWS]

Committed r260800: <https://trac.webkit.org/changeset/260800>

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