New issue
Advanced search Search tips
Starred by 4 users

Issue metadata

Status: Fixed
Owner:
Closed: Jul 2
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 1
Type: Bug-Regression



Sign in to add a comment

ResourceTiming is affected by page activity

Reported by nicjan...@gmail.com, Mar 21

Issue description

UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.162 Safari/537.36

Steps to reproduce the problem:
1. Load the test page, or browse to http://dev.nicj.net/resourcetiming-page-busy.html
2. The page fetches a single XHR that is delayed by the server for 1,000ms and returns a single byte
3. About 100ms after the xhr.send(), the page does a busy loop for 5,000ms
4. Inspect the ResourceTiming entry for the XHR (details are also output into the HTML) or view in Chrome Developer Tools

What is the expected behavior?
* The ResourceTiming duration should be around 1,000ms.
* Chrome Developer Tools should report around 1,000ms TTFB then a very short Content Download time.

What went wrong?
In Chrome 65 and 67, we see that the ResourceTiming duration is over 5,000ms:

e.g.:

{
    "name": "http://dev.nicj.net/delay.php?t=1",
    "entryType": "resource",
    "startTime": 55.90000003576279,
    "duration": 5103.899999987334,
    "initiatorType": "xmlhttprequest",
    "nextHopProtocol": "http/1.1",
    "workerStart": 0,
    "redirectStart": 0,
    "redirectEnd": 0,
    "fetchStart": 55.90000003576279,
    "domainLookupStart": 55.90000003576279,
    "domainLookupEnd": 55.90000003576279,
    "connectStart": 55.90000003576279,
    "connectEnd": 55.90000003576279,
    "secureConnectionStart": 0,
    "requestStart": 57.00000002980232,
    "responseStart": 1097.3000000230968,
    "responseEnd": 5159.800000023097,
    "transferSize": 426,
    "encodedBodySize": 21,
    "decodedBodySize": 1,
    "serverTiming": []
}

With the majority of the time (4,062ms) allocated between responseStart and responseEnd (when the busy loop was executing).  The server is just returning a single byte response, so it should not be taking this long to download.

The same duration (> 5,000ms) is also reported in the Network panel in Chrome dev tools (see attached screenshot chrome-67-resourcetiming-devtools.png): 1.04s TTFB with Content Download of 4.06s.

We do not expect page JavaScript to have such a direct impact on the timing data of ResourceTiming.  Previous versions of Chrome, and other current browsers, are not affected by the page's JavaScript.

Test results on various browsers.

Browsers affected by page busy:
* Chrome 65 (Windows, Android, Mac): >5000ms
* Chrome 67 (Windows, Android, Mac): >5000ms
* Internet Explorer 10 Windows: >5000ms
* Internet Explorer 11 Windows: >5000ms

Browsers not affected by page busy:
* Chrome 59 Windows: ~1000ms
* Edge 42 Windows: ~1000ms
* Firefox 58 Windows: ~1000ms
* Safari 11 Mac: ~1000ms

Notably, Chrome 59.0.3071.0 does not exhibit this behavior.  We have not yet tested versions in between 59 and 65 to determine which version this behavior change was introduced.

We noticed this initially when analyzing ResourceTiming data in Akamai mPulse -- some pages were exhibiting a large number (30+) of concurrent resources all in the "download" phase, all for the same domain (see dev-tools-real-site.png).  Due to concurrent connection limits, we believe this isn't what was really happening on the network stack, just a ResourceTiming reporting bug.  We're seeing this behavior frequently on "heavy" sites with a lot of downloads/page activity.

Our concern is that ResourceTiming data is a lot less useful if it does not accurately reflect the network timings and can be significantly affected by other activity on the page.

Did this work before? Yes 59.0.3071.0

Does this work in other browsers? Yes

Chrome version: 65.0.3325.162  Channel: stable
OS Version: 10.0
Flash Version:
 
resourcetiming-page-busy.html
1.0 KB View Download
chrome-67-repro-devtools.png
43.6 KB View Download
dev-tools-real-site.png
702 KB View Download

Comment 1 by y...@yoav.ws, Mar 21

Cc: leon....@intel.com yhirano@chromium.org
Labels: RegressedIn-59
It seems like this is a regression that happened in one of the CLs in https://chromium.googlesource.com/chromium/src/+log/488d6999c101d4a2a6b7cb3ad5b0336d7bb54069..91088a195969f5af61f404c9f02edc622cbe373a

The ones that seems potentially related are https://chromium.googlesource.com/chromium/src/+/91088a195969f5af61f404c9f02edc622cbe373a and https://chromium.googlesource.com/chromium/src/+/2ffd4b3b6bc3e571d2fee28955ba9bae10289a28

Adding those patch authors for opinions
Components: -Blink>PerformanceAPIs Blink>PerformanceAPIs>ResourceTiming
Status: Available (was: Unconfirmed)
Seems my CL https://chromium.googlesource.com/chromium/src/+/2ffd4b3b6bc3e571d2fee28955ba9bae10289a28 is innocent :) It does not touch anywhere related with resource loading, but just exports a C++ class's member as an attribute of the corresponding JavaScript object.
My change changed the behavior (It's easier to understand the change by looking at https://chromium-review.googlesource.com/c/chromium/src/+/821796/23/content/renderer/loader/resource_dispatcher.cc).
Owner: tdres...@chromium.org
Status: Assigned (was: Available)
Originally we recorded the timestamp on renderer's IO thread which is not blocked by JavaScript. We cannot do that with Mojo (without regressing the performance). We could record the timestamp on the browser process instead, but I'm not sure if that's the right thing to do from ResourceTiming PoV. tdresser@, what do you think?
Cc: kinuko@chromium.org
kinuko@ - at this point, I don't have any context on how we manage timestamps across the browser and renderer process. I assume we should record the timestamp in the browser, and then transform it somehow into the appropriate time base in the renderer?

Can you (or someone else in TOK) point us to an example?
We actually already record something similar to this in the browser process too (URLLoaderCompletionStatus's completion_time is the one), but we std::max it with the response_start time that's recorded in the renderer process (probably in order to make things consistent) and that's where we get the additional 5 sec.

https://cs.chromium.org/chromium/src/content/renderer/loader/resource_dispatcher.cc?q=std::max%5C(browser_completion_time&sq=package:chromium&l=542

By the way the request_info->response_start is not really used for |responseStart| in the resource timing but used for inter-process time conversion.

https://cs.chromium.org/chromium/src/content/common/inter_process_time_ticks_converter.h?gsn=InterProcessTimeTicksConverter&l=54

And... looking at the ResourceTiming's processing model again (https://w3c.github.io/resource-timing/#processing-model) I think one of the thing we can probably do is to use a different time as the renderer-side lower bound (than the request_info->response_start) for completion_time, this can just bound by the value of load_timing->receive_headers_end (which corresponds to |responseStart|) that is converted by InterProcessTimeTicksConverter.
If tests pass something like https://chromium-review.googlesource.com/c/chromium/src/+/979906 could probably work. I haven't done the thorough investigation what impact this could have in the entire inter-process conversion scheme.
Cc: -kinuko@chromium.org npm@chromium.org tdres...@chromium.org
Labels: -Pri-2 Pri-1
Owner: kinuko@chromium.org
Assigning to kinuko@ until I have some idea of what's going on. Happy to have myself or npm@ take this over once we're clear on the general approach.
Cc: kinuko@chromium.org
Owner: ----
Status: Available (was: Assigned)
I'm not actively pursuing this for now, so unassigning me.
Owner: yhirano@chromium.org
Status: Assigned (was: Available)
Project Member

Comment 12 by bugdroid1@chromium.org, May 11

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

commit 560e1ab54b7397d97533fd08a047ca7f54071bcf
Author: Yutaka Hirano <yhirano@chromium.org>
Date: Fri May 11 07:43:46 2018

Reset ResourceDispatcher::PendingRequest::request_start on redirect

net::URLRequest clears its request_start on redirect, so we should do
the same in the renderer.

Bug:  824155 ,  835502 
Change-Id: I74252d62d98aae0e26e4ee30ad21eeefb5fda267
Reviewed-on: https://chromium-review.googlesource.com/1054907
Commit-Queue: Yutaka Hirano <yhirano@chromium.org>
Reviewed-by: Matt Menke <mmenke@chromium.org>
Cr-Commit-Position: refs/heads/master@{#557810}
[modify] https://crrev.com/560e1ab54b7397d97533fd08a047ca7f54071bcf/content/renderer/loader/resource_dispatcher.cc

Labels: Needs-Feedback
Tested the issue on latest chrome version 68.0.3430.0 using Windows 10 with steps mentioned below:
1) Launched chrome reported version and navigated to URL: http://dev.nicj.net/resourcetiming-page-busy.html
2) Shows response as Total: 5858.000000007451, Download Time: 4567.500000004657
3) Opened Devtools > Network, record the reload, for delay request it shows, Waiting(TTFB): 1.22s and Content Download: 3.88 sec

@Yutaka Hirano: Please find the attached screencast for your reference and help us in confirming the fix.

Thanks!
824155.mp4
2.3 MB View Download
Project Member

Comment 14 by bugdroid1@chromium.org, May 17

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

commit 8004bde35ba57035a7de0e85ed80d34573bc365d
Author: Yutaka Hirano <yhirano@chromium.org>
Date: Thu May 17 14:37:31 2018

Fix inter-process completion timestamp conversion

We basically use request completion time recorded in the render
process to calculate responseEnd defined in Resource Timing API. This
is problematic because the renderer main thread can be blocked for a
long time, and that is confusing users of devtools and Resource
Timing API.

This CL changes how to calculate responseEnd. With this CL, it will be
calculated based on the completion time recorded in the browser
process.

Bug:  824155 ,  835502 ,  843440 
Change-Id: I990da586a86c420d21a8115d13e840f7c29d462e
Reviewed-on: https://chromium-review.googlesource.com/1053849
Reviewed-by: Timothy Dresser <tdresser@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Commit-Queue: Yutaka Hirano <yhirano@chromium.org>
Cr-Commit-Position: refs/heads/master@{#559530}
[modify] https://crrev.com/8004bde35ba57035a7de0e85ed80d34573bc365d/content/renderer/loader/resource_dispatcher.cc
[modify] https://crrev.com/8004bde35ba57035a7de0e85ed80d34573bc365d/content/renderer/loader/resource_dispatcher.h
[modify] https://crrev.com/8004bde35ba57035a7de0e85ed80d34573bc365d/content/renderer/loader/resource_dispatcher_unittest.cc
[modify] https://crrev.com/8004bde35ba57035a7de0e85ed80d34573bc365d/content/renderer/loader/test_request_peer.cc
[modify] https://crrev.com/8004bde35ba57035a7de0e85ed80d34573bc365d/content/renderer/loader/test_request_peer.h

Project Member

Comment 15 by bugdroid1@chromium.org, May 22

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

commit b3e41e67541fcb9e13bde7db301402f675f38e92
Author: Yutaka Hirano <yhirano@chromium.org>
Date: Tue May 22 08:24:56 2018

InterProcessTimeTicksConverter miscellaneous refactorings and bug fixes

This CL consists of bunch of cleanups and bug fixes:

 - LocalTimeTicks and RemoteTimeTicks are rewritten. They are now
   typedefs of SiteSpecificTimeDelta<SiteSpecificTimeLocalTag> and
   SiteSpecificTimeDelta<SiteSpecificTimeRemoteTag>, respectively, and
   have consistent methods each other.
 - Same for LocalTimeDelta and RemoteTimeDelta. Now they hold int64_t
   (via base::TimeDelta) rather than int32_t, which is good because
   int32_t lasts less than one hour.
 - This CL removes many integer operations and replaces them with
   base::TimeTicks and base::TimeDelta operations. This CL also removes
   many ToInternalValue and FromInternalValue calls which are
   deprecated.
 - InterProcessTimeTicksConverter now holds a double value for
   interpolation rather than two int64_t values as using int64_t leads
   to overflow.

Bug:  824155 ,  835502 
Change-Id: I51ed657f0370d13b509c65324afc3af81b249e37
Reviewed-on: https://chromium-review.googlesource.com/1055171
Commit-Queue: Yutaka Hirano <yhirano@chromium.org>
Reviewed-by: Matt Menke <mmenke@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#560511}
[modify] https://crrev.com/b3e41e67541fcb9e13bde7db301402f675f38e92/content/common/inter_process_time_ticks_converter.cc
[modify] https://crrev.com/b3e41e67541fcb9e13bde7db301402f675f38e92/content/common/inter_process_time_ticks_converter.h
[modify] https://crrev.com/b3e41e67541fcb9e13bde7db301402f675f38e92/content/common/inter_process_time_ticks_converter_unittest.cc

Status: Fixed (was: Assigned)

Sign in to add a comment