request stalled for a long time occasionally in chrome

Question

Ajax request occasionally stalled for a long time in chrome.

I finally managed to reproduced it and save all related data necessary to post here if anyone could help me out.

The timeline from Chrome Dev Tool shows the request stalled for 42.62s as the following screen capture shows:

and within the chrome://net-internals/#events (for the events log please head to the end) page I found the most time is cost by two events:

• +HTTP_TRANSACTION_READ_HEADERS [dt=21301]
• +HTTP_TRANSACTION_READ_HEADERS [dt=21304]

both get ERR_CONNECTION_RESET.

I think the error is the reason why the request stalled for so long.

Any one could explain the errors?

FOLLOWING IS THE EVENTS LOG FOR THE REQUEST, I also export the full events as json you can get from here then restore within the Chrome chrome://net-internals/#events page. note the request url is internal so maybe cant access from public network:

193486: URL_REQUEST
http://qa.tieba.baidu.com/release/getReleaseHistory?projectId=fum1.0.593
Start Time: 2015-01-02 17:51:05.323

t=    1 [st=    0] +REQUEST_ALIVE  [dt=42741]
t=    1 [st=    0]    URL_REQUEST_DELEGATE  [dt=0]
t=    1 [st=    0]   +URL_REQUEST_START_JOB  [dt=42740]
                      --> load_flags = 339804160 (BYPASS_DATA_REDUCTION_PROXY | MAYBE_USER_GESTURE | REPORT_RAW_HEADERS | VERIFY_EV_CERT)
                      --> method = "GET"
                      --> priority = "LOW"
                      --> url = "http://qa.tieba.baidu.com/release/getReleaseHistory?projectId=fum1.0.593"
t=    2 [st=    1]      URL_REQUEST_DELEGATE  [dt=0]
t=    2 [st=    1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=    2 [st=    1]      HTTP_CACHE_OPEN_ENTRY  [dt=0]
t=    2 [st=    1]      HTTP_CACHE_ADD_TO_ENTRY  [dt=0]
t=    2 [st=    1]      HTTP_CACHE_READ_INFO  [dt=0]
t=    2 [st=    1]      URL_REQUEST_DELEGATE  [dt=0]
t=    2 [st=    1]     +HTTP_STREAM_REQUEST  [dt=2]
t=    4 [st=    3]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                          --> source_dependency = 193488 (HTTP_STREAM_JOB)
t=    4 [st=    3]     -HTTP_STREAM_REQUEST
t=    4 [st=    3]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=0]
t=    4 [st=    3]        HTTP_TRANSACTION_SEND_REQUEST_HEADERS
                          --> GET /release/getReleaseHistory?projectId=fum1.0.593 HTTP/1.1
                              Host: qa.tieba.baidu.com
                              Connection: keep-alive
                              Accept: application/json, text/plain, */*
                              User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36
                              Referer: http://qa.tieba.baidu.com/project/
                              Accept-Encoding: gzip, deflate, sdch
                              Accept-Language: en-US,en;q=0.8
                              Cookie: [268 bytes were stripped]
t=    4 [st=    3]     -HTTP_TRANSACTION_SEND_REQUEST
t=    4 [st=    3]     +HTTP_TRANSACTION_READ_HEADERS  [dt=21301]
t=    4 [st=    3]        HTTP_STREAM_PARSER_READ_HEADERS  [dt=21301]
                          --> net_error = -101 (ERR_CONNECTION_RESET)
t=21305 [st=21304]        HTTP_TRANSACTION_RESTART_AFTER_ERROR
                          --> net_error = -101 (ERR_CONNECTION_RESET)
t=21305 [st=21304]     -HTTP_TRANSACTION_READ_HEADERS
t=21305 [st=21304]     +HTTP_STREAM_REQUEST  [dt=3]
t=21307 [st=21306]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                          --> source_dependency = 193494 (HTTP_STREAM_JOB)
t=21308 [st=21307]     -HTTP_STREAM_REQUEST
t=21308 [st=21307]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=3]
t=21308 [st=21307]        HTTP_TRANSACTION_SEND_REQUEST_HEADERS
                          --> GET /release/getReleaseHistory?projectId=fum1.0.593 HTTP/1.1
                              Host: qa.tieba.baidu.com
                              Connection: keep-alive
                              Accept: application/json, text/plain, */*
                              User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36
                              Referer: http://qa.tieba.baidu.com/project/
                              Accept-Encoding: gzip, deflate, sdch
                              Accept-Language: en-US,en;q=0.8
                              Cookie: [268 bytes were stripped]
t=21311 [st=21310]     -HTTP_TRANSACTION_SEND_REQUEST
t=21311 [st=21310]     +HTTP_TRANSACTION_READ_HEADERS  [dt=21304]
t=21311 [st=21310]        HTTP_STREAM_PARSER_READ_HEADERS  [dt=21304]
                          --> net_error = -101 (ERR_CONNECTION_RESET)
t=42615 [st=42614]        HTTP_TRANSACTION_RESTART_AFTER_ERROR
                          --> net_error = -101 (ERR_CONNECTION_RESET)
t=42615 [st=42614]     -HTTP_TRANSACTION_READ_HEADERS
t=42615 [st=42614]     +HTTP_STREAM_REQUEST  [dt=12]
t=42627 [st=42626]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                          --> source_dependency = 193498 (HTTP_STREAM_JOB)
t=42627 [st=42626]     -HTTP_STREAM_REQUEST
t=42627 [st=42626]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=2]
t=42627 [st=42626]        HTTP_TRANSACTION_SEND_REQUEST_HEADERS
                          --> GET /release/getReleaseHistory?projectId=fum1.0.593 HTTP/1.1
                              Host: qa.tieba.baidu.com
                              Connection: keep-alive
                              Accept: application/json, text/plain, */*
                              User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36
                              Referer: http://qa.tieba.baidu.com/project/
                              Accept-Encoding: gzip, deflate, sdch
                              Accept-Language: en-US,en;q=0.8
                              Cookie: [268 bytes were stripped]
t=42629 [st=42628]     -HTTP_TRANSACTION_SEND_REQUEST
t=42629 [st=42628]     +HTTP_TRANSACTION_READ_HEADERS  [dt=112]
t=42629 [st=42628]        HTTP_STREAM_PARSER_READ_HEADERS  [dt=112]
t=42741 [st=42740]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                          --> HTTP/1.1 200 OK
                              Date: Fri, 02 Jan 2015 09:51:48 GMT
                              Content-Type: application/json; charset=UTF-8
                              Transfer-Encoding: chunked
                              Connection: keep-alive
                              Cache-Control: no-cache
                              tracecode: 31079600320335034634010217
                              tracecode: 31079600320537995786010217
                              Server: Apache
t=42741 [st=42740]     -HTTP_TRANSACTION_READ_HEADERS
t=42741 [st=42740]      HTTP_CACHE_WRITE_INFO  [dt=0]
t=42741 [st=42740]      HTTP_CACHE_WRITE_DATA  [dt=0]
t=42741 [st=42740]      HTTP_CACHE_WRITE_INFO  [dt=0]
t=42741 [st=42740]      URL_REQUEST_DELEGATE  [dt=0]
t=42741 [st=42740]   -URL_REQUEST_START_JOB
t=42741 [st=42740]    URL_REQUEST_DELEGATE  [dt=0]
t=42741 [st=42740]    HTTP_TRANSACTION_READ_BODY  [dt=0]
t=42741 [st=42740]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=42741 [st=42740]    HTTP_TRANSACTION_READ_BODY  [dt=0]
t=42741 [st=42740]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=42742 [st=42741] -REQUEST_ALIVE

EDIT:related issue Issue 447463: Chrome-network: Long delay before RST message on stale sockets results in slow page loads.

Answer 1

I once encountered a similar problem. The cause of the problem is that every browser has a limit to the maximum number of TCP connections to a server. For chrome, the limit is six. The problem is more prominent when you are using a proxy server, because all the requests go the same server (the proxy server).

Chrome doesn't allow you to change this limit. It shouldn't in fact. If you want to know more about why this limit exists, and what are the limits for other browsers, you can read this article.

The reason why this limit is rarely a problem is because multiple HTTP requests to the same host are mostly sent consecutively, rather than parallely, preferably over the same TCP connection.

If this problem occurs to you frequently, then the reason might be:

1. Server doesn't support persistent TCP connection: If the problem occurs only when accessing a particular server, the reason might be that chrome is fetching multiple resources (like images, CSS files, etc) on parallel connections. Since, in your case, the server is on your local network, you might want to ask the server's administrator to add support for persistent TCP connections.

2. Multiple persistent connections are open: If you are working behind a proxy server, then downloading multiple files simultaneously or opening sites which keep a TCP connection open might be the cause of your problem.To get rid of it, all you can do is to not download many things simultaneously (or download in a different browser, if you have to).

PS: The error net_error = -101 (ERR_CONNECTION_RESET) is not due to invalid headers, it is because of the timeout, waiting for some previous connection to the server to close.

Answer 2

Similar issue here and it appears that after a while, approx 3 minutes a socket chrome is trying to use is closed (I assume) by the OS.

This is listed as a bug in the chromium forum as well. I'm guessing lack of some sort of "keep-alive" mechanism.: https://code.google.com/p/chromium/issues/detail?id=447463

My error message is slightly different but it could be due to my application making the calls over SSL. Here's what I see in chrome://net-internals:

First chrome finds an existing socket and the request is associated with it (HTTP_STREAM_JOB):

    t=1572 [st=0]    HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION
                     --> source_dependency = 1347215 (HTTP2_SESSION)
    t=1572 [st=0]    HTTP_STREAM_JOB_BOUND_TO_REQUEST
                     --> source_dependency = 1348612 (URL_REQUEST)
    t=1572 [st=0] -HTTP_STREAM_JOB

Then back in (URL_REQUEST) you will see it time out, note the 10 seconds lapse in time from t=1572 to t=11573:

    t= 1572 [st=    0]  HTTP2_SESSION_SEND_DATA
                        --> fin = true
                        --> size = 48
                        --> stream_id = 3
    t= 1572 [st=    0]  HTTP2_SESSION_UPDATE_SEND_WINDOW
                        --> delta = -48
                        --> window_size = 2147483551
    t=11573 [st=10001]  HTTP2_SESSION_CLOSE
                        --> description = "Failed ping."
                        --> net_error = -352 (ERR_SPDY_PING_FAILED)

Clearly there is a timeout when chrome attempts to adjust the window size on the existing socket. I assume this is due to inactivity on the socket.

I'm going to try to implement some sort of heartbeat request at perhaps 60 sec interval to see if the issue still persists. I'll post an update with results.

UPDATE:

Added the following code to javascript that's loaded on every page. This is retrieving an empty html doc from the public root:

    $(document).ready(function() {
        $.keepalive =     
                setInterval(function() {
                   $.ajax({
                      url: '/ping.html',
                      cache: false
                   });         
                }, 60000);    
    });

This appears to have helped keep the socket open even with the sample below showing approx 6 minutes between "real" calls:

At 570B per call in 60 sec intervals the ping call would add around 800kb of bandwidth usage per 24 hrs (per browser session). I'm not sure how much CPU overhead on the server this would cause.

For comparison, the BEFORE:

There has to be a better solution but i haven't been able to locate one yet.

Answer 3

I've encountered similar issues and fixed!

my problem is that small files upload is ok, but with large files it stalled for very long time, and from the net-log viewer I found that the full size of the file data actually uploaded but somehow the the tcp connection automatically closed afterwards,

then from https://netlog-viewer.appspot.com/#sockets I found that the http request has to go through a proxy sever,

so I tested again using firefox with no-proxy setting to bypass, but still unsuccessful, then from the firefox about:networking#dns I found that actually the domain not resolved to the web server directly but resolved to a bunch of ip addresses, it turned out they the WAF,

finally I changed the hosts setting point the domain to the web server ip address directly, then the problem gone! so I identified the root cause is the proxy server and waf! they may have some kind of default timeout