Open Bug 972883 Opened 7 years ago Updated 6 years ago

Navigation Timing values sometimes out of order on github.com

Categories

(Core :: DOM: Navigation, defect)

27 Branch
x86
macOS
defect
Not set
normal

Tracking

()

UNCONFIRMED

People

(Reporter: adam, Unassigned)

Details

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_1) AppleWebKit/537.73.11 (KHTML, like Gecko) Version/7.0.1 Safari/537.73.11

Steps to reproduce:

I'm an engineer at GitHub. We collect performance.timing data from users to monitor github.com's performance. We're seeing out-of-order timing data from many Firefox users. We've seen it from Firefox v17 through v27, and on Mac, Windows, and Linux.


Actual results:

Here's an example out-of-order timing from earlier today on the github.com homepage:

            0 redirectEnd
            0 redirectStart
1392382677848 navigationStart
1392382677934 domLoading
1392382678270 domInteractive
1392382678272 domContentLoadedEventStart
1392382678273 domContentLoadedEventEnd
1392387080157 connectEnd
1392387080157 connectStart
1392387080157 domainLookupEnd
1392387080157 domainLookupStart
1392387080157 fetchStart
1392387080730 requestStart
1392387080978 responseStart
1392387081009 responseEnd
1392387081013 unloadEventStart
1392387081014 unloadEventEnd
1392387086569 domComplete
1392387086569 loadEventStart
1392387086570 loadEventEnd

domLoading, domInteractive, domContentLoadedEventStart, and domContentLoadedEventEnd are getting marked before responseStart, and even before connectStart. That seems impossible, and also wrong according to the W3C test suite http://w3c-test.org/web-platform-tests/master/navigation-timing/test_timing_attributes_order.html

Note also that there is a gap of 73 minutes between navigationStart and domainLookupStart. Is it possible these timing values are coming from two different navigations?
We're also seeing bug 919391 on github.com, but it's not obvious that that bug has the same cause as this one.
> Is it possible these timing values are coming from two different navigations?

Seems more possible than anything else...

Are there any document.open() or document.write() after DOMContentLoaded involved by any chance?  At what point during the page's lifetime are you reading those values?  Any idea where URIs I could look at to see the issue?
> Are there any document.open() or document.write() after DOMContentLoaded involved by any chance?

I'm not sure. I'll look into it.

> At what point during the page's lifetime are you reading those values?

We do a setTimeout(readPerformanceValues, 0) when the load event is fired.

> Any idea where URIs I could look at to see the issue?

Here are the 5 most recent URLs where we've seen it happen according to our logs:

https://github.com/PrestaShop/PrestaShop/commits/1.6
https://github.com/
https://github.com/h5bp/html5-boilerplate/blob/v4.3.0/doc/crossdomain.md
https://github.com/chriseppstein/compass/wiki
https://github.com/telefonicaid/fiware-livedemoapp

Given the range of URLs we're seeing, it seems likely not to be specific to a particular part of the site.
Honza, are you familiar with this stuff?
Flags: needinfo?(honzab.moz)
Let me know if there's any more data (anonymous, of course) that would be useful to collect from github.com visitors.
(In reply to Boris Zbarsky [:bz] from comment #4)
> Honza, are you familiar with this stuff?

Not directly, but if there is no one else to look at this, I can do it.
Flags: needinfo?(honzab.moz)
If you could, that would be great.  I'm pretty swamped for the foreseeable future.  :(
Flags: needinfo?(honzab.moz)
Me too... at least with the new HTTP cache and some other stuff I want to finish no later then in some 3 weeks.

So, no promises on quick progress here.


Loose assignment to me.
Assignee: nobody → honzab.moz
Flags: needinfo?(honzab.moz)
Adam, what would be most helpful is finding some way to reproduce this.  I realize that's a tall order.  :(
No time to work on this any time soon.
Assignee: honzab.moz → nobody
You need to log in before you can comment on or make changes to this bug.