Bug 207153 - Timestamps should be the same for all rendering update steps
Summary: Timestamps should be the same for all rendering update steps
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: New Bugs (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Said Abou-Hallawa
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2020-02-03 15:08 PST by Jason Lawrence
Modified: 2020-06-24 12:48 PDT (History)
10 users (show)

See Also:


Attachments
Update Test Expectations (1.40 KB, patch)
2020-02-03 15:14 PST, Jason Lawrence
no flags Details | Formatted Diff | Diff
Patch (3.69 KB, patch)
2020-04-21 13:42 PDT, Said Abou-Hallawa
no flags Details | Formatted Diff | Diff
Patch (17.47 KB, patch)
2020-04-23 01:09 PDT, Said Abou-Hallawa
no flags Details | Formatted Diff | Diff
Patch (17.49 KB, patch)
2020-04-23 01:25 PDT, Said Abou-Hallawa
no flags Details | Formatted Diff | Diff
Test for frozen performance.now() (1.71 KB, text/html)
2020-04-23 08:58 PDT, Simon Fraser (smfr)
no flags Details
Patch (22.46 KB, patch)
2020-04-23 22:17 PDT, Said Abou-Hallawa
no flags Details | Formatted Diff | Diff
Patch (21.12 KB, patch)
2020-04-24 01:45 PDT, Said Abou-Hallawa
no flags Details | Formatted Diff | Diff
Patch (21.10 KB, patch)
2020-04-27 12:38 PDT, Said Abou-Hallawa
no flags Details | Formatted Diff | Diff
Patch (22.73 KB, patch)
2020-04-27 15:34 PDT, Said Abou-Hallawa
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Jason Lawrence 2020-02-03 15:08:21 PST
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
Comment 1 Radar WebKit Bug Importer 2020-02-03 15:08:40 PST
<rdar://problem/59127682>
Comment 2 Jason Lawrence 2020-02-03 15:14:41 PST
Created attachment 389578 [details]
Update Test Expectations
Comment 3 Ryan Haddad 2020-02-03 15:31:45 PST
Comment on attachment 389578 [details]
Update Test Expectations

Clearing flags on attachment: 389578

Committed r255606: <https://trac.webkit.org/changeset/255606>
Comment 4 Ryan Haddad 2020-02-04 09:45:13 PST
I see an instance of this test failing on 11/10/2019 @ r252317.
Comment 5 Jacob Uphoff 2020-02-11 10:45:25 PST
This test is also failing on macOS.
Comment 6 Jacob Uphoff 2020-02-11 10:50:30 PST
Updated test expectations here:https: //trac.webkit.org/changeset/256319/webkit
Comment 7 Jason Lawrence 2020-02-11 12:55:37 PST
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:
Comment 8 Said Abou-Hallawa 2020-04-21 13:42:20 PDT
Created attachment 397116 [details]
Patch
Comment 9 Said Abou-Hallawa 2020-04-21 13:46:45 PDT
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.
Comment 10 Simon Fraser (smfr) 2020-04-21 20:08:50 PDT
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.
Comment 11 Said Abou-Hallawa 2020-04-23 01:09:21 PDT
Created attachment 397326 [details]
Patch
Comment 12 Said Abou-Hallawa 2020-04-23 01:25:55 PDT
Created attachment 397328 [details]
Patch
Comment 13 Antoine Quint 2020-04-23 01:33:32 PDT
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.
Comment 14 Simon Fraser (smfr) 2020-04-23 08:48:32 PDT
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?
Comment 15 Simon Fraser (smfr) 2020-04-23 08:58:47 PDT
Created attachment 397345 [details]
Test for frozen performance.now()
Comment 16 Antoine Quint 2020-04-23 10:16:39 PDT
Note that document.timeline.currentTime is frozen as well and matches the rAF timestamp.
Comment 17 Said Abou-Hallawa 2020-04-23 22:17:42 PDT
Created attachment 397428 [details]
Patch
Comment 18 Said Abou-Hallawa 2020-04-24 01:45:18 PDT
Created attachment 397439 [details]
Patch
Comment 19 Simon Fraser (smfr) 2020-04-24 09:51:02 PDT
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>
Comment 20 Said Abou-Hallawa 2020-04-27 12:38:14 PDT
Created attachment 397719 [details]
Patch
Comment 21 Said Abou-Hallawa 2020-04-27 12:48:52 PDT
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.
Comment 22 Simon Fraser (smfr) 2020-04-27 15:06:56 PDT
(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"
Comment 23 Said Abou-Hallawa 2020-04-27 15:34:42 PDT
Created attachment 397751 [details]
Patch

Unmark animation tests as failed in the TestExpectations files.
Comment 24 EWS 2020-04-27 17:22:55 PDT
Committed r260800: <https://trac.webkit.org/changeset/260800>

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