New issue
Advanced search Search tips

Issue 811760 link

Starred by 4 users

Issue metadata

Status: Available
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , Windows
Pri: 3
Type: Bug



Sign in to add a comment

It seems that parallel async xmlhttprequests are actually sent one after one

Reported by lego1223...@gmail.com, Feb 13 2018

Issue description

UserAgent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0

Steps to reproduce the problem:
1. run server-side app that reply with 4seconds delay on /test/get_timeout uri and with index.ex.html on / uri
2. open this app in a browser tab with opened js-console

What is the expected behavior?
Last time printed in js-console must be greater than previous time in js-console by about 4seconds.

What went wrong?
Last time printed in js-console actually greater than previous time in js-console by 12seconds.

Did this work before? N/A 

Does this work in other browsers? N/A

Chrome version: 66.0.3346.0  Channel: n/a
OS Version: 7
Flash Version:
 
index.ex.html
662 bytes View Download
Does this work in other browsers?

firefox 52 - works
Does this work in other browsers?

IE 11 - works
Labels: Needs-Triage-M66
Components: -Blink>Network Internals>Network Blink>Network>XHR
Labels: OS-Linux
Status: Untriaged (was: Unconfirmed)
Confirmed on 64.0.3282.140 on Linux.
This is probably because the disk cache serializes the requests to the same URL.

Test case (Fail on Chromium, pass on Firefox):
https://chromium-review.googlesource.com/c/chromium/src/+/917016

net/ people, could you triage this?
Cc: shivanisha@chromium.org
Components: -Internals>Network Internals>Network>Cache
Cc: morlovich@chromium.org
Labels: Needs-Feedback
@reporter: Could you please provide net internal logs when the issue is coming on Chrome release 64. Here are the steps to get the logs:
https://sites.google.com/a/chromium.org/dev/for-testers/providing-network-details
I have only version 66. Log is attached.
chrome-net-export-log.66.json
103 KB View Download

Comment 9 by mge...@chromium.org, Feb 22 2018

Labels: -Needs-Feedback
Does seem to be lock-related:

876: URL_REQUEST
http://192.168.10.12:8000/test/get_timeout
Start Time: 2018-02-22 10:16:42.858
t=1106 [st=   0] +REQUEST_ALIVE  [dt=4006]
                  --> priority = "MEDIUM"
                  --> url = "http://192.168.10.12:8000/test/get_timeout"
t=1106 [st=   0]    URL_REQUEST_DELEGATE  [dt=0]
t=1106 [st=   0]   +URL_REQUEST_START_JOB  [dt=4006]
                    --> load_flags = 33024 (MAYBE_USER_GESTURE | VERIFY_EV_CERT)
                    --> method = "GET"
                    --> url = "http://192.168.10.12:8000/test/get_timeout"
t=1106 [st=   0]      URL_REQUEST_DELEGATE  [dt=0]
t=1106 [st=   0]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=1106 [st=   0]      HTTP_CACHE_OPEN_ENTRY  [dt=1]
t=1107 [st=   1]      HTTP_CACHE_ADD_TO_ENTRY  [dt=0]



877: URL_REQUEST
http://192.168.10.12:8000/test/get_timeout
Start Time: 2018-02-22 10:16:42.859
t=1107 [st=   0] +REQUEST_ALIVE  [dt=8006]
                  --> priority = "MEDIUM"
                  --> url = "http://192.168.10.12:8000/test/get_timeout"
t=1107 [st=   0]    URL_REQUEST_DELEGATE  [dt=0]
t=1107 [st=   0]   +URL_REQUEST_START_JOB  [dt=8006]
                    --> load_flags = 33024 (MAYBE_USER_GESTURE | VERIFY_EV_CERT)
                    --> method = "GET"
                    --> url = "http://192.168.10.12:8000/test/get_timeout"
t=1107 [st=   0]      URL_REQUEST_DELEGATE  [dt=0]
t=1107 [st=   0]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=1107 [st=   0]      HTTP_CACHE_OPEN_ENTRY  [dt=0]
t=1107 [st=   0]      HTTP_CACHE_ADD_TO_ENTRY  [dt=4005]
t=5112 [st=4005]      HTTP_CACHE_READ_INFO  [dt=0]

879: URL_REQUEST
http://192.168.10.12:8000/test/get_timeout
Start Time: 2018-02-22 10:16:42.859
t= 1107 [st=    0] +REQUEST_ALIVE  [dt=12014]
                    --> priority = "MEDIUM"
                    --> url = "http://192.168.10.12:8000/test/get_timeout"
t= 1108 [st=    1]    URL_REQUEST_DELEGATE  [dt=0]
t= 1108 [st=    1]   +URL_REQUEST_START_JOB  [dt=12013]
                      --> load_flags = 33024 (MAYBE_USER_GESTURE | VERIFY_EV_CERT)
                      --> method = "GET"
                      --> url = "http://192.168.10.12:8000/test/get_timeout"
t= 1108 [st=    1]      URL_REQUEST_DELEGATE  [dt=0]
t= 1108 [st=    1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t= 1108 [st=    1]      HTTP_CACHE_OPEN_ENTRY  [dt=0]
t= 1108 [st=    1]      HTTP_CACHE_ADD_TO_ENTRY  [dt=8005]
t= 9113 [st= 8006]      HTTP_CACHE_READ_INFO  [dt=0]
What's happening is actually expected behavior. Multiple transactions for the same cache entry do not execute in parallel in the headers phase, only in the response body phase. As we see, the first transaction is taking time during the headers phase as shown below:
876: URL_REQUEST
http://192.168.10.12:8000/test/get_timeout
t=1109 [st=   3]        HTTP_STREAM_PARSER_READ_HEADERS  [dt=3987]
t=5096 [st=3990]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                        --> HTTP/1.1 200 ok
                            Cache-Control: no-cache
                            Content-Length: 8
                            Content-Type: text/plain
                            Date: Thu, 22 Feb 2018 15:15:59 GMT
                            Expires: 01 Dec 1980 00:00:00 +0400
                            Server: MochiWeb/1.0 (Any of you quaids got a smint?)
t=5096 [st=3990]     -HTTP_TRANSACTION_READ_HEADERS
t=5096 [st=3990]      HTTP_CACHE_WRITE_INFO  [dt=16]
t=5112 [st=4006]      HTTP_CACHE_WRITE_DATA  [dt=0]
t=5112 [st=4006]      HTTP_CACHE_WRITE_INFO  [dt=0]

Only when this transaction writes the headers in the cache, will the next transaction get to proceed.

Note that this is not a regression but has been Chrome's behavior always.
The time taking event is HTTP_STREAM_PARSER_READ_HEADERS. Is it because of server processing delay in sending the headers?
Is Cache-Control: no-cache important here? Would the 2nd transaction be able to proceed and share the request once the headers come in if it were not there?

Hmm, I feel like I am missing some big-picture stuff: as far as I can see, HttpCache queues up 2nd transaction's open, which then gets the failure from the 1st one; 
then both try creates, and 2nd one gets a failure synthesized here:
https://cs.chromium.org/chromium/src/net/http/http_cache.cc?rcl=4e122060522ea22c5e886c2e20b83460624cdbd8&l=1369
so it just gives up on how cache thing and goes straight to network here:
https://cs.chromium.org/chromium/src/net/http/http_cache_transaction.cc?rcl=4e122060522ea22c5e886c2e20b83460624cdbd8&l=1242

... So how does this fit in with the "headers phase" requirement you mentioned above? Is the lack of atomic disk_cache::OpenOrCreateEntry what's causing that limitation, or is there more at play? (I could look into implementing it, perhaps, though not sure what it would require in blockfile...)




The "single transaction executes in the header phase" invariant is true irrespective of the cache control header.
As discussed offline, the netlog does not show the errors mentioned in comment 13, so they don't seem to be the issues here but the delay introduced in HTTP_STREAM_PARSER_READ_HEADERS. which I think is the server processing delay.

Comment 15 by ricea@chromium.org, Mar 12 2018

Labels: -Pri-2 Pri-3
Status: Available (was: Untriaged)
As a workaround, you can add a Cache-Control: no-cache header to the *request* headers.

So when using XMLHttpRequest you need to call         

xhr.setRequestHeader("Cache-Control", "no-cache");

in-between open() and send().
Thanks. I'll try it.
We should think if we could improve behavior here, to match other browsers.  If other browsers had the same behavior, this would be fine, but as they don't, this could give rise to Chrome-only perf issues.  Of course, fixing it may be more effort than its worth.

Sign in to add a comment