NavigationTiming API returns wrong values
Reported by
sscha...@gmail.com,
Nov 8
|
||||||||
Issue description
UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36
Steps to reproduce the problem:
Unfortunately I don't know exactly how to reproduce it.
What I know so far:
I am working on a synthetic tool that uses the NavigationTiming API to get the navtimings in the page itself, but we also have a Chrome Extension running, which uses the chrome.webNavigation API to listen to navigation events.
Here is what I could see in our logs that uses the chrome api:
2018-10-30 03:17:59,241+0000 [INFO ] [WAITPAGE] Navigation 1.OnBeforeNavigate details= <url removed>
2018-10-30 03:18:17,043+0000 [INFO ] [WAITPAGE] Navigation 2.OnCommitted for url=<url removed>
2018-10-30 03:18:17,662+0000 [INFO ] [WAITPAGE] Navigation 3.OnDOMContentLoaded url=<url removed>
2018-10-30 03:18:18,371+0000 [INFO ] [WAITPAGE] Navigation 4.OnCompleted url=<url removed>
So basically there is a 18 second gap between navigationstart and it actually retrieving some data.
Here is what the navtiming api returned(this is how we store it, so the -1 is a default value and the rest of the values are stored relative to the navigationStartJavaScriptTime/navigationStartServerTime):
{
"redirectStart": -1,
"redirectEnd": -1,
"fetchStart": 17610,
"domainLookupStart": 17610,
"domainLookupEnd": 17610,
"connectStart": 17610,
"connectEnd": 17610,
"secureConnectionStart": -1,
"requestStart": 17621,
"responseStart": 17778,
"responseEnd": 17783,
"transferSize": 2693,
"encodedBodySize": 2224,
"decodedBodySize": 6085,
"navigationType": "NAVIGATE",
"navigationStartJavaScriptTime": 1540869479236,
"navigationStartServerTime": 1540869479278,
"domLoading": 17793,
"domInteractive": 18411,
"domContentLoadedEventStart": 18411,
"domContentLoadedEventEnd": 18411,
"domComplete": 19127,
"loadEventStart": 19129,
"loadEventEnd": 19131
}
What is the expected behavior?
What went wrong?
NavigationTiming API values seem to be wrong and not reflecting what was going on.
Or is there an explanation why navigation has started and then chrome did not do anything for almost 18 seconds until it actually started to connect?
Did this work before? N/A
Does this work in other browsers? Yes
Chrome version: 70.0.3538.77 Channel: stable
OS Version: 10.0
Flash Version:
,
Nov 8
Yoav, have you ever seen anything like this?
,
Nov 8
,
Nov 12
As per comment #0, the reporter is unsure about the steps to reproduce the issue. As test team need a sample repro with steps to reproduce to test the issue, hence adding label TE-NeedsTriageHelp to push the issue out of the TE-triaging bucket and further investigation from dev team. Thanks...!!
,
Nov 12
Is this a problem on a specific website? Can you provide the URL?
,
Nov 13
Unfortunately this page requires a login and I am not at liberty to give out the credentials, because this is a customers of ours, I am just reporting the issue on behalf of them. I can contact them to ask if they can provide credentials. Is there a way to provide you with credentials without posting them in a public issuetracker?
,
Nov 13
We could make this bug restricted to Googlers only and afterwards you could include the information. Or you can email me the information to npm@chromium.org, referencing this bug.
,
Nov 14
Is this a consistent problem or if not how often does it happen? I'm unable to reproduce it. Do you need to have the extension running to get the weird values? NavTiming can be obtained from JS just calling performance.getEntriesByType('navigation')[0] (you can try it out on console).
,
Nov 14
Unfortunately it is not consistent and I can't really say how often it happens(we are running tests against that page 24/7 every 5 minutes and it occurs only sometimes)
We are actually using performance['timing'] for backwards compatibility with older browsers, but I am guessing it will return the same object in chrome if i call this or performance.getEntriesByType('navigation')[0]?
,
Nov 14
Ok and could you clarify what is navigationStartJavaScriptTime/navigationStartServerTime? Those are not members of performance['timing'].
,
Nov 26
,
Nov 26
you can forget about them. Basically we get the navstart time on the javascript side(=navigationStartJavaScriptTime) and then we are sending it to the server and translate it into the server side time(=navigationStartServerTime). The rest of the values are relative to the navStart time.
,
Nov 26
Thank you for providing more feedback. Adding the requester to the cc list. For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Nov 26
Well I'll forget about them but we need a reference point to say that the timings are incorrect. It seems plausible that the Nav Timing timestamps and the other ones have different reference points, so they should not be compared. Have you looked at the timestamps relative to performance.timeOrigin (ie substract performance.timeOrigin from the timestamps)?
,
Nov 26
all of them are relative to navigationStart, which is 1540869479236 in our case, so we can reduce transfer size of the data, but all are relative to the same timestamp.
,
Nov 26
I understand that these are computed with respect to the same timestamp, but that's not what I mean. And I thought you said they are relative to navigationStartJavaScriptTime? If it is relative to that, then the fact that they are >18 seconds does not say much if we don't know how navigationStartJavaScriptTime is computed. There already is performance['timing'].navigationStart, so why not compare with that one? Is it the case that when computing differences with that one you get very large values too?
,
Nov 26
performance['timing'].navigationStart is the same as navigationStartJavaScriptTime. Since every user has his own timezone and some delay, we are also transforming this time to UTC time, which is then stored as navigationStartServerTime.
To make it easier for you, this is how it looks in Chrome:
{
"redirectStart": -1,
"redirectEnd": -1,
"fetchStart": 17610,
"domainLookupStart": 17610,
"domainLookupEnd": 17610,
"connectStart": 17610,
"connectEnd": 17610,
"secureConnectionStart": -1,
"requestStart": 17621,
"responseStart": 17778,
"responseEnd": 17783,
"transferSize": 2693,
"encodedBodySize": 2224,
"decodedBodySize": 6085,
"navigationType": "NAVIGATE",
"navigationStart": 1540869479236,
"domLoading": 17793,
"domInteractive": 18411,
"domContentLoadedEventStart": 18411,
"domContentLoadedEventEnd": 18411,
"domComplete": 19127,
"loadEventStart": 19129,
"loadEventEnd": 19131
}
,
Nov 26
Ok, if the differences are wrt navigationStart then I agree that the numbers look very odd. BTW navigationStart is shown as 1540869479236 but should really be 0 (if we're subtracting from itself). Setting this bug as Available. I have a test case but haven't been able to reproduce the problem with it.
,
Dec 3
The customer asked me to share this with you: http://104.196.252.132/result/181201_ZN_7c3dbbb741457ee0e72d15fa868fa3ea/5/details/#waterfall_view_step1 After looking at the test, everything looks pretty normal during the test, but run 5 has a very long redirect duration. Seems like the problem is caused by 2 different domains and this is the expected behavior, because the timing allow algorithm determines that navtiming should not provide this data. The first request is to https://signin.infusionsoft.com/login?service=https://infusionsoft.app and then the 302 response redirects to https://infusionsoft.app/?<querystring> Can you please confirm?
,
Dec 3
Yes, without Timing Allow Origin headers, redirectStart and redirectEnd will be reported as 0. Not sure why that is translating into a long redirect in your calculations. Closing this bug. |
||||||||
►
Sign in to add a comment |
||||||||
Comment 1 by sscha...@gmail.com
, Nov 8