Navigation Timing 'requestStart' and 'responseStart' often before 'fetchStart'
Reported by
timotij...@gmail.com,
Feb 20 2018
|
||||||||
Issue descriptionUserAgent: 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".
,
Feb 21 2018
,
Feb 21 2018
I can reproduce this in stable too, version 64.0.3282.167 (Official Build) on Mac OS X 10.13.3.
,
Feb 21 2018
Timo went through our RUM metrics and it looks like this was introduced around September 27 last year if that helps.
,
Feb 21 2018
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.
,
Feb 21 2018
Yes that's likely PlzNavigate related. I'm adding arthursonzogni who worked on the plumbing of load timings for PlzNavigate to the bug.
,
Feb 21 2018
I can reproduce. On every website I tried I got: performance.timing.requestStart >= performance.timing.fetchstart This should be the opposite.
,
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.
,
Mar 22 2018
(Working on a patch)
,
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
,
Mar 23 2018
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/d1f7e47f4a973d06561ea995130980b69890075a commit d1f7e47f4a973d06561ea995130980b69890075a Author: Kinuko Yasuda <kinuko@chromium.org> Date: Fri Mar 23 02:02:12 2018 Use base::TimeTicks in Blink for updating navigation timing Now we can directly use base::Time*. R=ksakamoto Bug: 813889 Change-Id: I4409f9547200f1ef4cc35b94b15524d74a95ea5a Reviewed-on: https://chromium-review.googlesource.com/975061 Reviewed-by: Kunihiko Sakamoto <ksakamoto@chromium.org> Commit-Queue: Kinuko Yasuda <kinuko@chromium.org> Cr-Commit-Position: refs/heads/master@{#545340} [modify] https://crrev.com/d1f7e47f4a973d06561ea995130980b69890075a/content/renderer/render_frame_impl.cc [modify] https://crrev.com/d1f7e47f4a973d06561ea995130980b69890075a/third_party/WebKit/Source/core/exported/WebDocumentLoaderImpl.cpp [modify] https://crrev.com/d1f7e47f4a973d06561ea995130980b69890075a/third_party/WebKit/Source/core/exported/WebDocumentLoaderImpl.h [modify] https://crrev.com/d1f7e47f4a973d06561ea995130980b69890075a/third_party/WebKit/public/web/WebDocumentLoader.h
,
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
,
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
,
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
,
Apr 4 2018
,
Apr 6 2018
@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?
,
Apr 6 2018
Also note that the issue merged by c#15 mentioned service workers so issue 782958 may be related.
,
Apr 6 2018
,
Apr 26 2018
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 |
||||||||
Comment 1 by ebra...@gnu.org
, Feb 20 2018