Project: chromium Issues People Development process History Sign in
New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.
Issue 127644 Navigation Timing: performance.timing.requestStart before performance.timing.navigationStart
Starred by 12 users Reported by aaron.co...@gmail.com, May 10 2012 Back to list
Status: WontFix
Owner: ----
Closed: May 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 2
Type: Bug



Sign in to add a comment
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


 
chrome-navtiming-bug.png
112 KB View Download
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.


just adding a link back to the spec for reference http://goo.gl/MOzEz
This discusses the Monotonic clock requirement.

Cc: simonjam@chromium.org tonyg@chromium.org
Labels: -Area-Undefined Area-Internals
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+.
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
Comment 5 by Deleted ...@, 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?
minus2.PNG
54.4 KB View Download
minus.PNG
7.8 KB View Download
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.
Comment 7 by Deleted ...@, 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)
chrome.PNG
84.0 KB View Download
Project Member Comment 8 by bugdroid1@chromium.org, Mar 10 2013
Labels: -Area-Internals Cr-Internals
Comment 9 by tonyg@chromium.org, Dec 7 2013
Labels: Cr-Blink-Performance-APIs
Cc: tkonch...@chromium.org
Labels: Needs-Feedback
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.
Labels: -Cr-Blink-Performance-APIs Cr-Blink-PermissionsAPI
Manually move Cr-Blink-Performance-APIs to Cr-Blink-PermissionsAPI
Labels: -Cr-Blink-PermissionsAPI Cr-Blink-PerformanceAPIs
Comment 13 by Deleted ...@, Sep 3 2015
We are seeing responseEnd values with smaller values than requestStart in our performance timing logs of our visitors as well.
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?
@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.
Comment 16 by a...@chromium.org, May 25 2016
Labels: -Needs-Feedback
Status: WontFix
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.
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

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