New issue
Advanced search Search tips

Issue 813889 link

Starred by 7 users

Issue metadata

Status: Fixed
Owner:
Closed: Apr 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , Windows , Mac
Pri: 1
Type: Bug-Regression

Blocking:
issue 463348



Sign in to add a comment

Navigation Timing 'requestStart' and 'responseStart' often before 'fetchStart'

Reported by timotij...@gmail.com, Feb 20 2018

Issue description

UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3350.0 Safari/537.36

Steps to reproduce the problem:
1. Open any page in Chrome/Chromium that includes a redirect, for example https://en.wikipedia.org which redirects to https://en.wikipedia.org/wiki/Main_Page
2. Inspect the Navigation Timing values, either via

 v1: performance.timing

or

 v2: performance.getEntriesByType('navigation')[0]

Note, these are not cross-origin redirects, and these observations are not from back-and-forward navigations, nor any other form of caching (as far as I I can see).

What is the expected behavior?
The order must adhere to navigationStart >= fetchStart >= requestStart, yet, in Chrome redirects seem to have started in the past, which causes data corruption or (if client has compliancy validation) under sampling of redirected navigations from Chrome.

What went wrong?
The 'requestStart' value is quite often before 'fetchStart', which violates expectations as defined by the specification at

https://www.w3.org/TR/navigation-timing/#processing-model
and

https://www.w3.org/TR/navigation-timing-2/#processing-model

Note that this bug report is *not* about timing values of redirectStart or redirectEnd. While those should arguably also follow the expected sequence, based on previous issues filed I understand that Chrome has difficulty keeping these in sequence.

This bug report is about 'fetchStart' and 'requestStart', which I do not think can in any way be justified as being out of order.

Two example timing collections attached below. It seems to happen only when a connection is being re-used as I was unable to reproduce it in a fresh Incognito window.

However, when using a url not previously used in Incognito it does still happen, so it doesn't seem related to HTTP caching, but  might be specific to TLS connection re-use. Which would mean the bug happens on all redirected navigations after the first view in a TLS session.

##
## Case 1: Warmed up Chrome profile, second view.
## Probable DNS cache hit, and likely TLS connection reuse
##

fetchStart: 632.8000000066822
domainLookupStart: 632.8000000066822
domainLookupEnd: 632.8000000066822
connectStart: 632.8000000066822
connectEnd: 632.8000000066822
# redirectStart: 0.4000000044470653
# redirectEnd: 632.8000000066822

requestStart: 251.79999999818392 # diff: -381ms (!)

responseStart: 629.6000000002095
responseEnd: 642.3999999969965
domInteractive: 1312.3999999952503
domComplete: 2538.799999994808
loadEventStart: 2538.799999994808
loadEventEnd: 2539.0000000043074

- stackGaps:
-- tcp<->request: -381.0000000084983 # (!)

##
## Case 2: Incognito, first view.
##

fetchStart: 12.400000006891787 # gap: 1.4ms
domainLookupStart: 13.800000000628643
domainLookupEnd: 33.900000009452924
connectStart: 33.900000009452924
secureConnectionStart: 49.10000000381842
connectEnd: 91.50000000954606
# redirectStart: 0
# redirectEnd: 0

requestStart: 91.70000000449363 # gap: 0.2ms

responseStart: 108.50000000209548
responseEnd: 114.90000000048894
domInteractive: 173.50000000442378
domComplete: 662.9000000102678
loadEventStart: 662.9000000102678
loadEventEnd: 663.1000000052154

- stackGaps
-- fetch<->dns: 1.3999999937368557 #
-- tcp<->request: 0.19999999494757503

Older bug reports about other Navigation Timing sequence issues:
* https://bugs.chromium.org/p/chromium/issues/detail?id=127644
* https://bugs.chromium.org/p/chromium/issues/detail?id=705892
* https://bugs.chromium.org/p/chromium/issues/detail?id=805831

Did this work before? Yes 

Does this work in other browsers? Yes

Chrome version: 66.0.3350.0  Channel: canary
OS Version: OS X 10.13.2
Flash Version: 

You may use the snippet at https://gist.github.com/Krinkle/3591c4abfc4b6efa9c5c36110dbff2e8 as a convenient way to inspect Navigation Timing values, including common delta computations and validation of the stack "adding up".
 

Comment 1 by ebra...@gnu.org, Feb 20 2018

Blocking: 463348

Comment 2 by ajha@chromium.org, Feb 21 2018

Labels: Needs-Bisect Needs-Triage-M66
I can reproduce this in stable too, version 64.0.3282.167 (Official Build) on Mac OS X 10.13.3.
Timo went through our RUM metrics and it looks like this was introduced around September 27 last year if that helps.
Cc: susan.boorgula@chromium.org
Labels: -Pri-2 -Needs-Bisect hasbisect-per-revision RegressedIn-63 M-66 FoundIn-65 FoundIn-64 FoundIn-66 Target-66 Target-65 Target-64 OS-Linux OS-Windows Pri-1
Owner: clamy@chromium.org
Status: Assigned (was: Unconfirmed)
timotijhof@ Thanks for the issue.

Tested this issue on Ubuntu 14.04, Mac OS 10.12.6 and Windows 10 on the Stable 64.0.3282.168 and Canary 66.0.3347.0 and able to reproduce the issue by following the steps mentioned above.

On navigating to the page  https://en.wikipedia.org and launched Devtools -> Console and executed 'v1: performance.timing' in console, can observe that the requestStart value is greater than the fetchStart value.
Attached are the screen shots for reference.

Bisect Information:
===================
Good Build: 63.0.3216.0 (Revision - 502108)
Bad Build : 63.0.3217.0 (Revision - 502454)

On executing the per-revision bisect script, below is the Changelog URL:

https://chromium.googlesource.com/chromium/src/+/0dbded05ad0ba1c3d8388fd649130509ab97f07a

From the above Changelog, suspecting the below change:
Reviewed-on: https://chromium-review.googlesource.com/581488

clamy@ Please check and confirm if this issue is related to your change, else help us in assigning to the right owner.

Thanks.
813889_bad.png
214 KB View Download
813889_good.png
200 KB View Download

Comment 6 by clamy@chromium.org, Feb 21 2018

Cc: arthurso...@chromium.org
Yes that's likely PlzNavigate related. I'm adding arthursonzogni who worked on the plumbing of load timings for PlzNavigate to the bug.
I can reproduce.
On every website I tried I got:
performance.timing.requestStart >= performance.timing.fetchstart
This should be the opposite.

Comment 8 by kinuko@chromium.org, Mar 22 2018

Okay I think I can see what's happening. I believe the cause is how we handle the redirects, they are propagated from the browser process and 'committed' in a batch loop in WebURLLoaderImpl::Context::OnReceivedResponse():

    for (size_t i = 0; i < stream_override_->redirect_responses.size(); ++i) {
      bool result = OnReceivedRedirect(...);
      if (!result)
        return;
    }

This eventually calls DocumentLoader::RedirectReceived, where we adjust the document's fetch_start to the current time.  Actually multiple more fields also need to be adjusted there, but at least we can start with fixing fetch_start.

Comment 9 by kinuko@chromium.org, Mar 22 2018

Cc: clamy@chromium.org ksakamoto@chromium.org
Owner: kinuko@chromium.org
(Working on a patch)
Project Member

Comment 10 by bugdroid1@chromium.org, Mar 23 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8b7c105d94786e672dfa43f0e67ee81002c23742

commit 8b7c105d94786e672dfa43f0e67ee81002c23742
Author: Kinuko Yasuda <kinuko@chromium.org>
Date: Fri Mar 23 01:15:09 2018

Document relationship with ResourceTiming in net::LoadingTimeInfo

Particularly |request_start| and |send_start| ones are confusing,
would like to have some helpful comments somewhere.

R=mmenke@chromium.org

Bug:  813889 
Change-Id: I5775dc66576cd20cacc324f524d18bd78d15a8ff
Reviewed-on: https://chromium-review.googlesource.com/974806
Reviewed-by: Matt Menke <mmenke@chromium.org>
Commit-Queue: Kinuko Yasuda <kinuko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#545322}
[modify] https://crrev.com/8b7c105d94786e672dfa43f0e67ee81002c23742/net/base/load_timing_info.h

Project Member

Comment 12 by bugdroid1@chromium.org, Mar 27 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/aeecb4f32ece14a8a294e4f9b80a5bb2278091c9

commit aeecb4f32ece14a8a294e4f9b80a5bb2278091c9
Author: Kinuko Yasuda <kinuko@chromium.org>
Date: Tue Mar 27 03:50:23 2018

Don't adjust the NavigationTimings on redirects

We adjust the timings in WebDocumentLoaderImpl::UpdateNavigation(),
shouldn't update in each AddRedirect() (which is called in a batch
way after all the redirects are handled in the browser process with PlzNavigate,
adjusting timings there with current timestamp is totally wrong)

R=ksakamoto,arthursonzogni

Bug:  813889 
Change-Id: I3a57d3fdf1833c300feb5ee61737b64cece0946b
Reviewed-on: https://chromium-review.googlesource.com/974673
Reviewed-by: Kunihiko Sakamoto <ksakamoto@chromium.org>
Commit-Queue: Kinuko Yasuda <kinuko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#546001}
[modify] https://crrev.com/aeecb4f32ece14a8a294e4f9b80a5bb2278091c9/third_party/WebKit/LayoutTests/external/wpt/navigation-timing/test_timing_server_redirect.html
[modify] https://crrev.com/aeecb4f32ece14a8a294e4f9b80a5bb2278091c9/third_party/WebKit/Source/core/loader/DocumentLoadTiming.cpp

Project Member

Comment 13 by bugdroid1@chromium.org, Mar 27 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/34d368d5f0543aa9bca5fceecd24835e796ce259

commit 34d368d5f0543aa9bca5fceecd24835e796ce259
Author: Ben Wells <benwells@chromium.org>
Date: Tue Mar 27 05:27:00 2018

Revert "Don't adjust the NavigationTimings on redirects"

This reverts commit aeecb4f32ece14a8a294e4f9b80a5bb2278091c9.

Reason for revert: Causing lots of failures on webkit bots, e.g.:
https://ci.chromium.org/buildbot/chromium.webkit/WebKit%20Linux%20Trusty/42143

Original change's description:
> Don't adjust the NavigationTimings on redirects
> 
> We adjust the timings in WebDocumentLoaderImpl::UpdateNavigation(),
> shouldn't update in each AddRedirect() (which is called in a batch
> way after all the redirects are handled in the browser process with PlzNavigate,
> adjusting timings there with current timestamp is totally wrong)
> 
> R=​ksakamoto,arthursonzogni
> 
> Bug:  813889 
> Change-Id: I3a57d3fdf1833c300feb5ee61737b64cece0946b
> Reviewed-on: https://chromium-review.googlesource.com/974673
> Reviewed-by: Kunihiko Sakamoto <ksakamoto@chromium.org>
> Commit-Queue: Kinuko Yasuda <kinuko@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#546001}

TBR=kinuko@chromium.org,ksakamoto@chromium.org,arthursonzogni@chromium.org

Change-Id: I467ed888084ea0eda06faa903d1797fabffc47da
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug:  813889 
Reviewed-on: https://chromium-review.googlesource.com/981912
Reviewed-by: Ben Wells <benwells@chromium.org>
Commit-Queue: Ben Wells <benwells@chromium.org>
Cr-Commit-Position: refs/heads/master@{#546025}
[modify] https://crrev.com/34d368d5f0543aa9bca5fceecd24835e796ce259/third_party/WebKit/LayoutTests/external/wpt/navigation-timing/test_timing_server_redirect.html
[modify] https://crrev.com/34d368d5f0543aa9bca5fceecd24835e796ce259/third_party/WebKit/Source/core/loader/DocumentLoadTiming.cpp

Project Member

Comment 14 by bugdroid1@chromium.org, Mar 28 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/44cc16cdbb7589055303042d621336578b818d95

commit 44cc16cdbb7589055303042d621336578b818d95
Author: Kinuko Yasuda <kinuko@chromium.org>
Date: Wed Mar 28 01:35:05 2018

Re-land: "Don't adjust the NavigationTimings on redirects"

The reason for revert was the new navigation timing test expectations
(that got commited right before the original change) had a FAIL
expectation for the particular event order that this change was fixing.

Original change's description:
> Don't adjust the NavigationTimings on redirects
>
> We adjust the timings in WebDocumentLoaderImpl::UpdateNavigation(),
> shouldn't update in each AddRedirect() (which is called in a batch
> way after all the redirects are handled in the browser process with PlzNavigate,
> adjusting timings there with current timestamp is totally wrong)
>
> R=​ksakamoto,arthursonzogni
>
> Bug:  813889 
> Change-Id: I3a57d3fdf1833c300feb5ee61737b64cece0946b
> Reviewed-on: https://chromium-review.googlesource.com/974673
> Reviewed-by: Kunihiko Sakamoto <ksakamoto@chromium.org>
> Commit-Queue: Kinuko Yasuda <kinuko@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#546001}

Bug:  813889 
Change-Id: I6f5c0ba1196fa1dd52225036820b29a95569ac21
Reviewed-on: https://chromium-review.googlesource.com/981913
Reviewed-by: Kunihiko Sakamoto <ksakamoto@chromium.org>
Commit-Queue: Kinuko Yasuda <kinuko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#546365}
[modify] https://crrev.com/44cc16cdbb7589055303042d621336578b818d95/third_party/WebKit/LayoutTests/external/wpt/navigation-timing/test_timing_server_redirect.html
[modify] https://crrev.com/44cc16cdbb7589055303042d621336578b818d95/third_party/WebKit/LayoutTests/external/wpt/service-workers/service-worker/navigation-timing.https-expected.txt
[modify] https://crrev.com/44cc16cdbb7589055303042d621336578b818d95/third_party/WebKit/Source/core/loader/DocumentLoadTiming.cpp

Cc: vamshi.kommuri@chromium.org
 Issue 827136  has been merged into this issue.
@vamshi: Indeed. The data reported in "Case 1" of my first comment also shows that both 'responseStart' and 'requestStart' get corrupted.

I believe the patch submitted Kinuko fixes the 'requestStart' metric, but I'm not entirely sure whether 'responseStart' is also fixed by that patch. I suspect not.

On second thought, re-reading comment 8, makes me think it's actually neither of these two metrics that's the problem. They look wrong because of 'fetchStart' being too late, but given we're making that earlier, I suspect that would make both 'requestStart' and 'responseStart' seem sensible again. Is that right?


Summary: Navigation Timing 'requestStart' and 'respondStart' often before 'fetchStart' (was: Navigation Timing 'requestStart' often before 'fetchStart')
Also note that the issue merged by c#15 mentioned service workers so issue 782958 may be related.
Summary: Navigation Timing 'requestStart' and 'responseStart' often before 'fetchStart' (was: Navigation Timing 'requestStart' and 'respondStart' often before 'fetchStart')
Status: Fixed (was: Assigned)
After my patch it looks both are working fine to me on ToT on my local env.  Let me close this but feel free to file a new issue if you're seeing the problem for responseStart.

Sign in to add a comment