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)
Core
Layout
Tracking
()
RESOLVED
FIXED
mozilla57
People
(Reporter: intermittent-bug-filer, Assigned: tschneider)
References
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])
Attachments
(1 file, 3 obsolete files)
Filed by: rvandermeulen [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=103600280&repo=autoland https://queue.taskcluster.net/v1/task/T0GfXPS0TEGJRXvmKg6TQw/runs/0/artifacts/public/logs/live_backing.log
Updated•7 years ago
|
Flags: needinfo?(tschneider)
Updated•7 years ago
|
Blocks: intersection-observer-impl
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•7 years ago
|
Assignee: nobody → tschneider
Flags: needinfo?(tschneider)
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 4•7 years ago
|
||
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]
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 8•7 years ago
|
||
Looks like the issue hear was simply a typo in the original web platform tests.
Assignee | ||
Comment 9•7 years ago
|
||
Assignee | ||
Comment 10•7 years ago
|
||
Try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=eb445c6640c9dabb12f48ec0fab7529c458b7055
Comment 11•7 years ago
|
||
(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.
Comment hidden (Intermittent Failures Robot) |
Comment 13•7 years ago
|
||
:tobytailor, any updates on getting this fixed upstream?
Flags: needinfo?(tschneider)
Assignee | ||
Comment 14•7 years ago
|
||
See https://github.com/w3c/web-platform-tests/pull/6563
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•7 years ago
|
Flags: needinfo?(tschneider)
Comment hidden (Intermittent Failures Robot) |
Comment 17•7 years ago
|
||
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)
Comment hidden (Intermittent Failures Robot) |
Comment 19•7 years ago
|
||
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)
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 22•7 years ago
|
||
Attachment #8883826 -
Attachment is obsolete: true
Assignee | ||
Comment 23•7 years ago
|
||
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.
Assignee | ||
Updated•7 years ago
|
Attachment #8891480 -
Flags: review?(james)
Comment hidden (Intermittent Failures Robot) |
Comment 25•7 years ago
|
||
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+
Assignee | ||
Comment 26•7 years ago
|
||
> 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.
Comment 27•7 years ago
|
||
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
Comment 28•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/8bf8ee2bd98c
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox56:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
I'm still seeing failures like this happening on autoland.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Assignee | ||
Comment 30•7 years ago
|
||
Can you point me to some please? Need to analyze what gets logged.
Assignee | ||
Comment 31•7 years ago
|
||
Sorry, this bug was supposed to stay open till made sure the issue is fixed.
Failures like: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=120481524&lineNumber=10892 https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=120484268&lineNumber=7238 https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=120525120&lineNumber=10867 You can see the recently classified failures at the bottom of https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1369360
Comment 33•7 years ago
|
||
(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.
Assignee | ||
Updated•7 years ago
|
Keywords: leave-open
Comment 34•7 years ago
|
||
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
Comment 35•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/91622c96ce5a
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 37•7 years ago
|
||
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.
Comment 38•7 years ago
|
||
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
Comment 39•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/ae2abae54245
Assignee | ||
Comment 40•7 years ago
|
||
Attachment #8891480 -
Attachment is obsolete: true
Assignee | ||
Comment 41•7 years ago
|
||
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 42•7 years ago
|
||
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+
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 44•7 years ago
|
||
Added comment to explain why an epsilon of 16ms was chosen.
Attachment #8895544 -
Attachment is obsolete: true
Assignee | ||
Comment 45•7 years ago
|
||
Try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=834798df90c842d8e1f1ce055b3e4efca5c096d1
Assignee | ||
Comment 46•7 years ago
|
||
Or better: https://treeherder.mozilla.org/#/jobs?repo=try&revision=87a187f11f17d33988d110ba7e54abb9e5ec659f
Comment 47•7 years ago
|
||
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
Comment 48•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/bd7c4f03106e
Assignee | ||
Updated•7 years ago
|
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
Comment hidden (Intermittent Failures Robot) |
Updated•7 years ago
|
status-firefox57:
--- → fixed
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell fixed]
Target Milestone: mozilla56 → mozilla57
Comment 50•7 years ago
|
||
bugherder uplift |
https://hg.mozilla.org/releases/mozilla-beta/rev/f94caff3f542
Flags: in-testsuite+
You need to log in
before you can comment on or make changes to this bug.
Description
•