Closed Bug 1079837 Opened 11 years ago Closed 11 years ago

Intermittent test_resource_timing.html | PerformanceEntry has correct name, initiatorType, http://web-platform.test:8000http://.../resource_timing_test0.css")

Categories

(Testing :: web-platform-tests, defect)

Product:
Testing
Component:
web-platform-tests
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox37 wontfix, firefox38 fixed, firefox39 fixed, firefox-esr31 unaffected, b2g-v2.2 fixed, b2g-master fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla39
Tracking Flags:
Tracking Status
firefox37 --- wontfix
firefox38 --- fixed
firefox39 --- fixed
firefox-esr31 --- unaffected
b2g-v2.2 --- fixed
b2g-master --- fixed

People

(Reporter: cbook, Assigned: valentin)

References

(
URL
)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

patch
837 bytes, patch
Details | Diff | Splinter Review
Ubuntu VM 12.04 x64 mozilla-inbound opt test web-platform-tests-4 https://treeherder.mozilla.org/ui/logviewer.html#?job_id=2844689&repo=mozilla-inbound 03:27:36 WARNING - TEST-UNEXPECTED-FAIL | /resource-timing/test_resource_timing.html | PerformanceEntry has correct name, initiatorType, http://web-platform.test:8000http://.../resource_timing_test0.css") has correct order of timing attributes.<br/>domainLookupStart >= fetchStart: 295.044557 >= 245.711159<br/>domainLookupEnd >= domainLookupStart: 295.31798999999995 >= 295.044557<br/>connectStart >= domainLookupEnd: 295.345206 >= 295.31798999999995<br/>connectEnd >= connectStart: 295.839596 >= 295.345206<br/>requestStart >= connectEnd: 294.075085 >= 295.839596<br/>responseStart >= requestStart: 294.099261 >= 294.075085<br/>responseEnd >= responseStart: 331.402045 >= 294.099261<br/> - assert_true: PerformanceEntry has correct name, initiatorType, http://web-platform.test:8000http://.../resource_timing_test0.css") has correct order of timing attributes.<br/>domainLookupStart >= fetchStart: 295.044557 >= 245.711159<br/>domainLookupEnd >= domainLookupStart: 295.31798999999995 >= 295.044557<br/>connectStart >= domainLookupEnd: 295.345206 >= 295.31798999999995<br/>connectEnd >= connectStart: 295.839596 >= 295.345206<br/>requestStart >= connectEnd: 294.075085 >= 295.839596<br/>responseStart >= requestStart: 294.099261 >= 294.075085<br/>responseEnd >= responseStart: 331.402045 >= 294.099261<br/> expected true got false
So the last comment here is slightly different; it's for the new version of the test. Valentin: could you look at the <link> test and decide whether I screwed up the test so it's unstable or whether the implementation is itself unstable?
Flags: needinfo?(valentin.gosu)
Hi James, we do have a couple of bugs left in the implementation, that deal with caching: Bug 1009360 and bug 1021221. My guess is this is a similar issue, dealing with link. I'll investigate.
Assignee: nobody → valentin.gosu
Flags: needinfo?(valentin.gosu)
Finding: for some unknown reason, it seems that http://w3c-test.org/resource-timing/test_resource_timing.html and our web-platform-tests always fail in the same way (link), but if I run the tests from the git repo, ( python server.py ; access http://web-platform.test:8000/resource-timing/test_resource_timing.html ) it always seems to pass. Looking into the reason for it.
Attached patch patch — — Splinter Review
Hi James, It seems that the problem was it the async loading of resources. The 100ms timeout isn't enough. On w3c-test.org I even see 600ms-700ms, for those resources.
Flags: needinfo?(james)
So wait, what? Is the stylesheet ending up in document.styleSheets before it's finished loading? I was trying to entirely avoid a race condition here and was told that stylesheets didn't appear in document.styleSheets until they had loaded, so the intent was to poll for that. So the 100ms wasn't supposed to be an upper limit. If my assumption is wrong, do we have any way of telling whether the stylesheet *has* loaded?
Flags: needinfo?(james)
Flags: needinfo?(valentin.gosu)
Clearing needinfo per IRC chat. For some reason the entry is not available just after the stylesheed has been added. A timeout might be needed. I'll try to determine if we have a bug in the implementation.
Flags: needinfo?(valentin.gosu)
I am going to land a fix for this in the next wpt upgrade, which requires a test + expectations setting cycle.
This is officially the #1 orange by almost a 2:1 margin. What can we do to mitigate this now?
Flags: needinfo?(james)
Well, disabling the test works, of course. The upgrade is in progress, but is still a little slow.
Flags: needinfo?(james)
Thanks. FWIW it's possible to just "disable" the one subtest that's failing so it's result is ignored rather than disabling the whole file, but that probably doesn't matter here, not least because I have an actual fix forthcoming.
I have nowhere near enough experience to do things that fine-grained for this test suite.
Sure, just mentioning it so that if next time we have a single unstable test in a file containing 1000 tests, we don't disable the 999 stable tests as collateral damage.
Sorry I haven't been able to fix the test myself, James. I got caught up with a bunch of other things.
This looks like a different bug now. I'm not sure how I'm supposed to deal with that, but I guess it could be an actual regression?
Flags: needinfo?(valentin.gosu)
There seems to be an issue with the test. InvalidAccessError at test_resource_timing.js, line 118 (in logs) I can also reproduce it by loading http://w3c-test.org/resource-timing/test_resource_timing.html and it seems to throw InvalidAccessError for sheet.cssRules.length.
Flags: needinfo?(valentin.gosu)
https://critic.hoppipolla.co.uk/r/3272 Valentin: I see you don't have your email address on critic ;) Mind fixing that and reviewing the above patch?
Flags: needinfo?(valentin.gosu)
I reviewed the patch. Thanks for taking this on James.
Flags: needinfo?(valentin.gosu)
I've been digging into this a bit more and I see two problems: 1) the startTime reported by resource-timing is not always close to the time that the thing in script causes the load. Obviously this can be true simply due to things taking an unexpectedly long time, but I want to check that we are implementing what the spec says and setting startTime to the time at which the fetch algorithm is invoked (i.e. from a spec point of view setting startTime happens as a consequence of things that are entirely synchronous from the load being initiated). 2) We sometimes get a requestStart time that is smaller than the connectEnd time. I don't think that the spec explicitly states this is an invariant, but the test assumes it is. Do we consider failing to enforce this a bug in our implementation (I lean towards yes, since the alternative seems potentially confusing to people trying to use the API, but I know nothing about what's actually going on at the networking layer here)?
Sorry forgot to add the needinfo. See above.
Flags: needinfo?(valentin.gosu)
(In reply to James Graham [:jgraham] from comment #455) > I've been digging into this a bit more and I see two problems: > > 1) the startTime reported by resource-timing is not always close to the time > that the thing in script causes the load. Obviously this can be true simply > due to things taking an unexpectedly long time, but I want to check that we > are implementing what the spec says and setting startTime to the time at > which the fetch algorithm is invoked (i.e. from a spec point of view setting > startTime happens as a consequence of things that are entirely synchronous > from the load being initiated). I am inclined to think that this is not a bug. The debug version fails this test constantly, simply because it's slower than the optimized build. There may still be something off here, so I'll look into it. > > 2) We sometimes get a requestStart time that is smaller than the connectEnd > time. I don't think that the spec explicitly states this is an invariant, > but the test assumes it is. Do we consider failing to enforce this a bug in > our implementation (I lean towards yes, since the alternative seems > potentially confusing to people trying to use the API, but I know nothing > about what's actually going on at the networking layer here)? I think it's really possible there's a bug in our implementation. A breakpoint in nsPerfomance::AddEntry seems to show that requestStart is 0 and in that case it returns the value for FetchStart (even though the spec doesn't say that) Thanks for pointing this out.
Thanks! I've submitted a PR to make the first issue much less strict by just checking that the startTime is some time after the action that caused the resource to start loading. It's strictly hard to justify any more than that anyway. I also added some more text to the debug messages so it's clear where the tests are failing.
This was fixed by the patches in Bug 1123920, and the tests were enabled. (changeset f1fc4df52d3e) James, Ryan and tree-sheriffs, thanks for your help!
Status: NEW → RESOLVED
Closed: 11 years ago
Flags: needinfo?(valentin.gosu)
Resolution: --- → FIXED
Whiteboard: [test disabled][leave open]
status-firefox37: --- → affected
status-firefox38: --- → affected
status-firefox39: --- → fixed
status-firefox-esr31: --- → unaffected
Target Milestone: --- → mozilla39
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: