Navigation Timing: performance.timing.requestStart before performance.timing.navigationStart
|Reported by aaron.co...@gmail.com, May 10 2012||Back to list|
Chrome Version : 18.0.1025.168 also tested on : 19.0.1084.41 beta-m (Windows XP) OS Version: 6.1 (Windows 7, Windows Server 2008 R2) What steps will reproduce the problem? 1. Open Chrome and open the dev tools (F12) 2. Add a watch expression for "performance.timing.requestStart - performance.timing.navigationStart;" 3. Enter the URL www.google.com to go to google 4. Once the page has loaded enter the URL www.yahoo.com to go to yahoo 5. Once the page has loaded, navigate quickly forward and back a few times. 6. Observe the watch expression take a negative value What is the expected result? According to the W3C navigation timing api spec, navigationStart should take place before request start and not after. What happens instead? navigationStart through to connectEnd all take the same value X. requestStart has value Y and Y < X. From request start onwards the marks have normal increasing values. Please provide any additional information below. Attach a screenshot if possible. I tried to rule out the possibility that this was related to Issue 104788 (cross-renderer navigation), by disabling prerender (both from the omnibar and navigation predicition) through the UI settings and using command-line flags. I also tried restricting to one renderer by using the command-line flag --renderer-process-limit=1. The issue was still observed. I tried to rule out the possibility that this was related to Issue 83981 (caching behavior), by testing on a server setting no-cache http headers: Cache-control: no-cache Cache-control: no-store Pragma: no-cache Expires: 0 These headers were observed in the chrome dev tools, but the issue was still observed. No other relevant existing issues could be found. UserAgentString: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.168 Safari/535.19
Sep 11 2012,
I was doing some experimenting with Chrome on Windows, and it appears to me that Chrome violates the monotonic clock requirement of Navigation Timing specification. I did a control of this with Firefox and IE, and both of those Honor the monotonic clock (indicating that my code should be correct) From the w3 spec: Navigation Timing's Monotonic Clock Requirement The data kinda speaks for itself. In this example notice that fetchStart occurs 1ms before unloadEnd. then response end is 2ms before response start timing value diff actuall high res clock value. unloadTime: 1ms :1347373793229ms unloadEnd: 0ms :1347373793229ms redirectStart: 0ms :0ms redirectEnd: 0ms :0ms fetchStart: -1ms :1347373793228ms dnsStart: 0ms :1347373793228ms dnsEnd: 0ms :1347373793228ms connectStart: 0ms :1347373793228ms connectEnd: 0ms :1347373793228ms sslConnect: 0ms :0ms requestStart: 7ms :1347373793235ms responseStart: 0ms :1347373793235ms responseEnd: -2ms :1347373793233ms domLoad: -1ms :1347373793232ms domInteractive: 4ms :1347373793236ms domContentLoadStart: 0ms :1347373793236ms domContentLoadEnd: 0ms :1347373793236ms comComplete: 0ms :1347373793236ms loadEventStart: 0ms :1347373793236ms loadEventEnd: 0ms :0ms totalTime: 8ms :1347373793228ms I can add some source code, but it is easy to reproduce with just a simple html page, and a simple js file. You may have to load it twice as the first time it will not hit the condition.
Sep 11 2012,
just adding a link back to the spec for reference http://goo.gl/MOzEz This discusses the Monotonic clock requirement.
Sep 13 2012,
unload is asynchronous, so it can happen anywhere in the timeline. That's why we drew it separately in the diagram. The one that's concerning is the responseEnd coming before responseStart. Which version did you see this on? There was a recent fix on Windows that's probably only in Chrome 23+.
Sep 13 2012,
As per the details of the initial report, I was using: 18.0.1025.168 and also tested on: 19.0.1084.41 beta-m
Jan 8 2013,
Hi, I'm using this js: https://github.com/JackuB/errfield/blob/master/website/index.php#L30 to capture performance.timing and save it to db. In my db I found occurences, where responseEnd is occuring BEFORE requestStart. It happens in Chrome 23. Also 1 occurence where requestStart occured before navigationStart. No such data coming from Firefox (and 2 occurences alas different in IE9). So maybe this still remains unsolved bug?
Jan 8 2013,
Thanks. I'm thinking these might different issues than what I fixed in 23. responseEnd is off by hundreds of seconds, which is different than the 1-2ms issue I fixed earlier. I'm guessing these are rare and not easily reproduced? If I could reproduce it, it'd be easy to fix.
Jan 11 2013,
I ran some more tests: and from 1263 Chrome entries this behavior occured 17 times. No pattern: different requested URL, resolution, OS... No time coincidence. I'm tracking only when "performance.navigation.type == 0", so no failed reloads etc. are counted. Also 100% server uptime was reported during that period. Rest of results is OK and +/- match synthetic tests (when using median value)
Mar 10 2013,
Dec 7 2013,
Jan 6 2014,
Unable to repro the issue on win8 chrome version 31.0.1650.63 and 34.0.1769.2 canary Followed the steps mentioned in issue and observed watch expression takes a positive value. simonjam@ : Please let me know if I am missing something here.
Aug 4 2015,
Manually move Cr-Blink-Performance-APIs to Cr-Blink-PermissionsAPI
Aug 5 2015,
Sep 3 2015,
We are seeing responseEnd values with smaller values than requestStart in our performance timing logs of our visitors as well.
Feb 10 2016,
aaron.coble@Could you please check the issue on latest stable 48.0.2564.109 and let us know if issue still persists or not?
Apr 1 2016,
@aaron.coble -- Could you please verify the issue on Latest Stable@ 49.0.2623.110 and update the issue which would help us triage further. Thanks in Advance.
May 25 2016,
Closing the issue as there is no user update on this for long. Requesting to file a new issue if this or any similar issue is still seen on the latest chrome versions.
Feb 9 2017,
We're still seeing this issue in the wild as of Chrome 56. Here are two examples from SOASTA's RUM data: 1. requestStart < navigationStart, responseStart < fetchStart Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36 navigation.type 0 // navigation redirectStart 0 redirectEnd 0 requestStart 1486557564194 // incorrect: before navigationStart navigationStart 1486557564438 responseStart 1486557564438 // incorrect: before fetchStart fetchStart 1486557564611 domainLookupStart 1486557564611 domainLookupEnd 1486557564611 connectStart 1486557564611 connectEnd 1486557564611 responseEnd 1486557564613 domLoading 1486557564617 domInteractive 1486557565447 domContentLoadedEventStart 1486557565447 domContentLoadedEventEnd 1486557565451 domComplete 1486557626337 loadEventStart 1486557626337 2. requestStart and responseStart < fetchStart Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36 navigation.type 0 // navigation navigationStart 1486556030159 redirectStart 1486556030315 requestStart 1486556030626 // incorrect: before fetchStart responseStart 1486556030682 // incorrect: before fetchStart redirectEnd 1486556030696 fetchStart 1486556030696 domainLookupStart 1486556030696 domainLookupEnd 1486556030696 connectStart 1486556030696 connectEnd 1486556030696 domLoading 1486556030755 responseEnd 1486556030913 domInteractive 1486556035030 domContentLoadedEventStart 1486556035030 domContentLoadedEventEnd 1486556035035 domComplete 1486556035039 loadEventStart 1486556035039
Mar 28 2017,
Simple reproduction is with double redirection. Opening new issue as requested: https://bugs.chromium.org/p/chromium/issues/detail?id=705892
Sign in to add a comment