New issue
Advanced search Search tips

Issue 903097 link

Starred by 1 user

Issue metadata

Status: WontFix
Owner: ----
Closed: Dec 3
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 2
Type: Bug



Sign in to add a comment

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:
 
Just to clarify: This also happens for Real Users(and not only in our synthetic tool), but for them I can not provide such detailed information.
Cc: yoavweiss@chromium.org
Components: -Blink>PerformanceAPIs Blink>PerformanceAPIs>NavigationTiming
Yoav, have you ever seen anything like this?
Labels: Needs-Triage-M70
Labels: Triaged-ET TE-NeedsTriageHelp
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...!!
Is this a problem on a specific website? Can you provide the URL?
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?
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.
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).
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]?
Ok and could you clarify what is navigationStartJavaScriptTime/navigationStartServerTime? Those are not members of performance['timing'].
Labels: Needs-Feedback
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.
Project Member

Comment 13 by sheriffbot@chromium.org, Nov 26

Cc: npm@chromium.org
Labels: -Needs-Feedback
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
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)?
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.
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?
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
}

Status: Available (was: Unconfirmed)
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.
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?

Comment 20 Deleted

Status: WontFix (was: Available)
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