Closed Bug 1369360 Opened 7 years ago Closed 7 years ago

Intermittent intersection-observer/timestamp.html | Generate notifications. - assert_greater_than: Time ranges for top and iframe windows are disjoint. expected a number greater than 1014.825 but got 464.015

Categories

(Core :: Layout, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla57
Tracking Status
firefox56 --- fixed
firefox57 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: tschneider)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])

Attachments

(1 file, 3 obsolete files)

Flags: needinfo?(tschneider)
Assignee: nobody → tschneider
Flags: needinfo?(tschneider)
this has increased in frequency since about June 17th on pretty much all platforms, debug only.

here is a link to a linux64 log:
https://treeherder.mozilla.org/logviewer.html#?repo=try&job_id=108984668&lineNumber=9138

and related text:
[task 2017-06-21T20:15:39.393960Z] 20:15:39     INFO - TEST-START | /intersection-observer/timestamp.html
[task 2017-06-21T20:15:39.394878Z] 20:15:39     INFO - Clearing pref dom.webcomponents.enabled
[task 2017-06-21T20:15:39.415421Z] 20:15:39     INFO - Clearing pref dom.IntersectionObserver.enabled
[task 2017-06-21T20:15:39.456809Z] 20:15:39     INFO - Setting pref dom.IntersectionObserver.enabled (true)
[task 2017-06-21T20:15:39.599044Z] 20:15:39     INFO - PID 4406 | ++DOCSHELL 0x7fc3320f3800 == 6 [pid = 4454] [id = {b7dfe158-2fa0-4f43-a9a7-ae85ad3a6699}]
[task 2017-06-21T20:15:39.599438Z] 20:15:39     INFO - PID 4406 | ++DOMWINDOW == 56 (0x7fc3320f8800) [pid = 4454] [serial = 56] [outer = (nil)]
[task 2017-06-21T20:15:39.615455Z] 20:15:39     INFO - PID 4406 | [Parent 4406] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser.
[task 2017-06-21T20:15:39.615808Z] 20:15:39     INFO - PID 4406 | : file /home/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 794
[task 2017-06-21T20:15:39.658580Z] 20:15:39     INFO - PID 4406 | ++DOMWINDOW == 57 (0x7fc332289800) [pid = 4454] [serial = 57] [outer = 0x7fc3320f8800]
[task 2017-06-21T20:15:39.679726Z] 20:15:39     INFO - PID 4406 | 1498076139676	Marionette	DEBUG	loaded listener.js
[task 2017-06-21T20:15:39.744261Z] 20:15:39     INFO - PID 4406 | ++DOMWINDOW == 58 (0x7fc332299000) [pid = 4454] [serial = 58] [outer = 0x7fc3320f8800]
[task 2017-06-21T20:15:40.285166Z] 20:15:40     INFO - PID 4406 | ++DOCSHELL 0x7fc333078000 == 7 [pid = 4454] [id = {2231ff3a-3c4e-439d-809f-5bcf3f9a9dc5}]
[task 2017-06-21T20:15:40.285505Z] 20:15:40     INFO - PID 4406 | ++DOMWINDOW == 59 (0x7fc33307e000) [pid = 4454] [serial = 59] [outer = (nil)]
[task 2017-06-21T20:15:40.285829Z] 20:15:40     INFO - PID 4406 | ++DOMWINDOW == 60 (0x7fc333488800) [pid = 4454] [serial = 60] [outer = 0x7fc33307e000]
[task 2017-06-21T20:15:40.685008Z] 20:15:40     INFO - PID 4406 | --DOCSHELL 0x7fc33119b000 == 6 [pid = 4454] [id = {58d4abcf-ec90-4bcd-9055-56ee49a90589}]
[task 2017-06-21T20:15:40.685396Z] 20:15:40     INFO - PID 4406 | --DOCSHELL 0x7fc3317db800 == 5 [pid = 4454] [id = {f79f228a-f8e9-496a-814a-f412e4cc4094}]
[task 2017-06-21T20:15:40.685763Z] 20:15:40     INFO - PID 4406 | --DOCSHELL 0x7fc33307c800 == 4 [pid = 4454] [id = {0290b176-c4a0-4431-9f36-d592ec490666}]
[task 2017-06-21T20:15:40.948517Z] 20:15:40     INFO - 
[task 2017-06-21T20:15:40.948859Z] 20:15:40     INFO - TEST-PASS | /intersection-observer/timestamp.html | Check that timestamps correspond to the to execution context that created the observer. 
[task 2017-06-21T20:15:40.949117Z] 20:15:40     INFO - TEST-PASS | /intersection-observer/timestamp.html | First rAF after iframe is loaded. 
[task 2017-06-21T20:15:40.949544Z] 20:15:40     INFO - TEST-UNEXPECTED-FAIL | /intersection-observer/timestamp.html | Generate notifications. - assert_greater_than: Time ranges for top and iframe windows are disjoint. expected a number greater than 621.08 but got 618.87
[task 2017-06-21T20:15:40.950023Z] 20:15:40     INFO - step2@http://web-platform.test:8000/intersection-observer/timestamp.html:81:3
[task 2017-06-21T20:15:40.950518Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.951182Z] 20:15:40     INFO - Test.prototype.step_func_done/<@http://web-platform.test:8000/resources/testharness.js:1445:17
[task 2017-06-21T20:15:40.951617Z] 20:15:40     INFO - Test.prototype.step_timeout/<@http://web-platform.test:8000/resources/testharness.js:1463:20
[task 2017-06-21T20:15:40.952013Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.952415Z] 20:15:40     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1429:20
[task 2017-06-21T20:15:40.952848Z] 20:15:40     INFO - setTimeout handler*Test.prototype.step_timeout@http://web-platform.test:8000/resources/testharness.js:1462:16
[task 2017-06-21T20:15:40.953374Z] 20:15:40     INFO - waitForNotification/</<@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:25:33
[task 2017-06-21T20:15:40.953868Z] 20:15:40     INFO - Test.prototype.step_timeout/<@http://web-platform.test:8000/resources/testharness.js:1463:20
[task 2017-06-21T20:15:40.954358Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.954885Z] 20:15:40     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1429:20
[task 2017-06-21T20:15:40.955382Z] 20:15:40     INFO - setTimeout handler*Test.prototype.step_timeout@http://web-platform.test:8000/resources/testharness.js:1462:16
[task 2017-06-21T20:15:40.955890Z] 20:15:40     INFO - waitForNotification/<@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:25:5
[task 2017-06-21T20:15:40.956382Z] 20:15:40     INFO - FrameRequestCallback*waitForNotification@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:24:3
[task 2017-06-21T20:15:40.956791Z] 20:15:40     INFO - runTestCycle/<@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:40:5
[task 2017-06-21T20:15:40.957212Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.957595Z] 20:15:40     INFO - async_test@http://web-platform.test:8000/resources/testharness.js:514:13
[task 2017-06-21T20:15:40.958001Z] 20:15:40     INFO - runTestCycle@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:39:3
[task 2017-06-21T20:15:40.958394Z] 20:15:40     INFO - step1@http://web-platform.test:8000/intersection-observer/timestamp.html:69:3
[task 2017-06-21T20:15:40.958793Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.959192Z] 20:15:40     INFO - Test.prototype.step_func_done/<@http://web-platform.test:8000/resources/testharness.js:1445:17
[task 2017-06-21T20:15:40.959586Z] 20:15:40     INFO - Test.prototype.step_timeout/<@http://web-platform.test:8000/resources/testharness.js:1463:20
[task 2017-06-21T20:15:40.960096Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.960493Z] 20:15:40     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1429:20
[task 2017-06-21T20:15:40.960893Z] 20:15:40     INFO - setTimeout handler*Test.prototype.step_timeout@http://web-platform.test:8000/resources/testharness.js:1462:16
[task 2017-06-21T20:15:40.961323Z] 20:15:40     INFO - waitForNotification/</<@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:25:33
[task 2017-06-21T20:15:40.961726Z] 20:15:40     INFO - Test.prototype.step_timeout/<@http://web-platform.test:8000/resources/testharness.js:1463:20
[task 2017-06-21T20:15:40.965109Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.965395Z] 20:15:40     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1429:20
[task 2017-06-21T20:15:40.966180Z] 20:15:40     INFO - setTimeout handler*Test.prototype.step_timeout@http://web-platform.test:8000/resources/testharness.js:1462:16
[task 2017-06-21T20:15:40.966771Z] 20:15:40     INFO - waitForNotification/<@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:25:5
[task 2017-06-21T20:15:40.967068Z] 20:15:40     INFO - FrameRequestCallback*waitForNotification@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:24:3
[task 2017-06-21T20:15:40.967728Z] 20:15:40     INFO - runTestCycle/<@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:40:5
[task 2017-06-21T20:15:40.968088Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.968585Z] 20:15:40     INFO - async_test@http://web-platform.test:8000/resources/testharness.js:514:13
[task 2017-06-21T20:15:40.969192Z] 20:15:40     INFO - runTestCycle@http://web-platform.test:8000/intersection-observer/resources/intersection-observer-test-utils.js:39:3
[task 2017-06-21T20:15:40.969606Z] 20:15:40     INFO - targetIframe.onload@http://web-platform.test:8000/intersection-observer/timestamp.html:58:7
[task 2017-06-21T20:15:40.970003Z] 20:15:40     INFO - EventHandlerNonNull*@http://web-platform.test:8000/intersection-observer/timestamp.html:41:5
[task 2017-06-21T20:15:40.970398Z] 20:15:40     INFO - Test.prototype.step_timeout/<@http://web-platform.test:8000/resources/testharness.js:1463:20
[task 2017-06-21T20:15:40.970822Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.971211Z] 20:15:40     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1429:20
[task 2017-06-21T20:15:40.971610Z] 20:15:40     INFO - setTimeout handler*Test.prototype.step_timeout@http://web-platform.test:8000/resources/testharness.js:1462:16
[task 2017-06-21T20:15:40.972043Z] 20:15:40     INFO - @http://web-platform.test:8000/intersection-observer/timestamp.html:34:3
[task 2017-06-21T20:15:40.972459Z] 20:15:40     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1405:20
[task 2017-06-21T20:15:40.972841Z] 20:15:40     INFO - async_test@http://web-platform.test:8000/resources/testharness.js:514:13
[task 2017-06-21T20:15:40.973240Z] 20:15:40     INFO - @http://web-platform.test:8000/intersection-observer/timestamp.html:30:1
[task 2017-06-21T20:15:40.973781Z] 20:15:40     INFO - TEST-OK | /intersection-observer/timestamp.html | took 1556ms


this is a web-platform-test and here is the source (in-tree):
https://dxr.mozilla.org/mozilla-central/source/testing/web-platform/tests/intersection-observer/timestamp.html


:jet, I see you are the triage owner for core::layout, this is trending higher and it would be good to get this in a queue  of someone on the layout team to look at in the near future
Flags: needinfo?(bugs)
Whiteboard: [stockwell needswork]
I'm gonna work on this today.
Flags: needinfo?(bugs)
Looks like the issue hear was simply a typo in the original web platform tests.
Attached patch Cleanup and typo fix (obsolete) — Splinter Review
(In reply to Tobias Schneider [:tobytailor] from comment #9)
> Created attachment 8883826 [details] [diff] [review]
> Cleanup and typo fix

Probably best to fix this in upstream WPT (and get the r+ there) before landing this one.
:tobytailor, any updates on getting this fixed upstream?
Flags: needinfo?(tschneider)
Flags: needinfo?(tschneider)
I see a great conversation in the pull request- but I don't see this getting closer to fixed anytime soon- I am not sure what to do when we have a fix for a flaky test that isn't getting accepted upstream.  :jgraham, do you have other thoughts here?
Flags: needinfo?(james)
From the conversation in the PR it sounds like there's the possibility of a fix that will make everyone happy. I've commented there, because I think fixing the test is the right thing to do here, rather than disabling it.
Flags: needinfo?(james)
Attachment #8883826 - Attachment is obsolete: true
Updated the patch to reflect what was discussed so far in the GitHub thread, which was btw the same solution we came up with internally. Would like to have this in the tree for a while to see if it reduces or eliminates the intermittends.
Attachment #8891480 - Flags: review?(james)
Comment on attachment 8891480 [details] [diff] [review]
Calculate timeSkew more reliable for low frame rates

Review of attachment 8891480 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/web-platform/tests/intersection-observer/timestamp.html
@@ +31,5 @@
> +  if (numFrames <= 0) {
> +    callback();
> +    return;
> +  }
> +  window.requestAnimationFrame(waitFor.bind(null, numFrames - 1, callback));

I would probably just have written 

window.requestAnimationFrame(() => waitFor(numFrames - 1, callback));

But sure, your way works too.
Attachment #8891480 - Flags: review?(james) → review+
> I would probably just have written 
> 
> window.requestAnimationFrame(() => waitFor(numFrames - 1, callback));
> 
> But sure, your way works too.

Agree, but tried to match the style of surrounding code.
Pushed by tschneider@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8bf8ee2bd98c
(Intermittent intersection-observer/timestamp.html) Calculate timeSkew more reliable for low frame rates. r=jgraham
https://hg.mozilla.org/mozilla-central/rev/8bf8ee2bd98c
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
I'm still seeing failures like this happening on autoland.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Can you point me to some please? Need to analyze what gets logged.
Sorry, this bug was supposed to stay open till made sure the issue is fixed.
(In reply to Tobias Schneider [:tobytailor] from comment #26)
> > I would probably just have written 
> > 
> > window.requestAnimationFrame(() => waitFor(numFrames - 1, callback));
> > 
> > But sure, your way works too.
> 
> Agree, but tried to match the style of surrounding code.

I can't see the part where timeSkew is actually used to calculate the elapsed time.
Keywords: leave-open
Pushed by tschneider@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/91622c96ce5a
(Intermittent intersection-observer/timestamp.html) Log time values. m=me,test-only
Collected exact time values for failing tests for a couple of days, read about my findings and proposed solution in https://github.com/w3c/web-platform-tests/pull/6563#issuecomment-320776160.
Pushed by tschneider@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ae2abae54245
(Intermittent intersection-observer/timestamp.html) Log time deltas. m=me,test-only
Attachment #8891480 - Attachment is obsolete: true
Comment on attachment 8895544 [details] [diff] [review]
Make testing for expected time origins more reliable.

James, based on discussions in the GitHub PR and timings collected over the past 2 weeks, this seams to be the most reliable solution. Please have a quick review to get this landed and hopefully not seeing any failures anymore.
Attachment #8895544 - Flags: review?(james)
Comment on attachment 8895544 [details] [diff] [review]
Make testing for expected time origins more reliable.

Review of attachment 8895544 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/web-platform/tests/intersection-observer/timestamp.html
@@ +73,4 @@
>    var topWindowTimeAfterNotification = performance.now();
>    var iframeWindowTimeAfterNotification = targetIframe.contentWindow.performance.now();
>  
> +  assert_approx_equals(

This seems slightly odd. Do you really intend to check that the two differences are equal to each other within 16ms? If so a comment explaining why you are taking this approach would be helpful.
Attachment #8895544 - Flags: review?(james) → review+
Added comment to explain why an epsilon of 16ms was chosen.
Attachment #8895544 - Attachment is obsolete: true
Pushed by tschneider@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/bd7c4f03106e
(Intermittent intersection-observer/timestamp.html) Make testing for expected time origins more reliable. r=jgraham
Status: REOPENED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → FIXED
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell fixed]
Target Milestone: mozilla56 → mozilla57
You need to log in before you can comment on or make changes to this bug.