Long XHR request waiting time for first time page loading

[Felix Halim]

Hi,

I'm writing a html page where near the end of the page, I call an XHR
request to the originating server for more data. I monitor the
resources tab in the Chrome's Developer Tool. The first time I load
the page, the XHR request has a very long waiting time, around 7+
seconds. Then, I tried reloading the page, now the XHR waiting time
become less than 1 second. Here is the snapshots:

http://felix-halim.net/xhr-waiting-chrome.png

This happens in Firefox too:

http://felix-halim.net/xhr-waiting-ff.png

Does anybody know what causes the long waiting time for XHR request?
it only happens when the page is not loaded recently. If it's just
recently loaded, then XHR waiting time is quite short. Shouldn't it be
short all the time?

FYI, the script that the XHR called in the server completes in less
than 1 second.

Thanks,

Felix Halim

[Eric Roman]

If you load up about:net-internals you can see whether it was network latency (and if so at what stage).

However it takes a bit of practice to make sense of those logs.

--
Chromium Developers mailing list: chromi...@chromium.org
View archives, change email options, or unsubscribe:
   http://groups.google.com/a/chromium.org/group/chromium-dev

[Felix Halim]

Hi Eric,

I looked into the about:net-internals page and this is the chunk of
the XHR request part:

http://felix-halim.net/net-internals.txt

It seemed that the bottleneck is between these two lines, which takes
near 14 seconds (the dt=13991):

t=1282623706059 [st= 2] HTTP_STREAM_PARSER_READ_HEADERS [dt=13991]
t=1282623720050 [st=13993] HTTP_TRANSACTION_READ_RESPONSE_HEADERS

By quick refreshing, those two lines becomes:

t=1282624401369 [st= 1] HTTP_STREAM_PARSER_READ_HEADERS [dt= 375]
t=1282624401744 [st= 376] HTTP_TRANSACTION_READ_RESPONSE_HEADERS

Here is the dump on the quick refresh:

http://felix-halim.net/net-internals-quick-refresh.txt

Any clue what those lines actually doing?

Another thing that different from those two dumps is the load_flags value.

First time loading, the load_flags value is:

--> load_flags = 129 (ENABLE_LOAD_TIMING | VALIDATE_CACHE)

After quick refresh it switches to:

--> load_flags = 0 (NORMAL)

Felix Halim

[Eric Roman]

On Mon, Aug 23, 2010 at 9:40 PM, Felix Halim <felix...@gmail.com> wrote:

Hi Eric,

I looked into the about:net-internals page and this is the chunk of
the XHR request part:

http://felix-halim.net/net-internals.txt

It seemed that the bottleneck is between these two lines, which takes
near 14 seconds (the dt=13991):

t=1282623706059 [st=    2]           HTTP_STREAM_PARSER_READ_HEADERS  [dt=13991]
t=1282623720050 [st=13993]           HTTP_TRANSACTION_READ_RESPONSE_HEADERS



By quick refreshing, those two lines becomes:

t=1282624401369 [st=   1]           HTTP_STREAM_PARSER_READ_HEADERS  [dt= 375]
t=1282624401744 [st= 376]           HTTP_TRANSACTION_READ_RESPONSE_HEADERS

Here is the dump on the quick refresh:

http://felix-halim.net/net-internals-quick-refresh.txt


Any clue what those lines actually doing?

You are correct, it looks like all of those 14 seconds are being spent in:

    HTTP_STREAM_PARSER_READ_HEADERS

This stage is basically waiting for bytes to be received through the socket, and completes once the end of headers is found (or the socket is closed, whichever comes first).

There are some parts to the log which you haven't included, namely the SOCKET log for the request, and the CONNECT_JOB logs. These will have some other interesting data:

If you look at the SOCKET_POOL_BOUND_TO_SOCKET event, it shows the "id" of the socket which that request was carried out on. Look this up in the log to see the events emitted for that particular socket. A couple things to look for in the socket's log: was the connection made to the same IP address in both cases? (unlikely but worth checking) Also check the pattern of reads/writes on the socket -- did the server return any data quickly? (could be that some bytes of the headers were received quickly, but then it took many seconds to receive the final set. The log will show the byte-count for each group that was received).

One thing I noticed in both your logs is it is re-using an existing socket. (Not all the surprising if the XHR was started after loading a page from that domain).

What this means is an earlier HTTP transaction was already carried out over that socket before the XHR was sent. This could be tickling a problem with the keep alive connection, say if the server doesn't flush its written bytes right away. (since you mentioned the problem happens in firefox too, probably more likely server-side issue than client-side).

Another experiment worth trying is loading the XHR url directly from the web browser. Do you get the same results? (One notable difference is it will now be doing a GET rather than a POST).

 

Another thing that different from those two dumps is the load_flags value.

First time loading, the load_flags value is:

 --> load_flags = 129 (ENABLE_LOAD_TIMING | VALIDATE_CACHE)

After quick refresh it switches to:

 --> load_flags = 0 (NORMAL)

I doubt the load flags are having an impact here. That response looks to be uncacheable anyway so VALIDATE_CACHE won't be doing much of anything.

[Felix Halim]

On Tue, Aug 24, 2010 at 1:16 PM, Eric Roman <ero...@chromium.org> wrote:
> There are some parts to the log which you haven't included, namely the
> SOCKET log for the request, and the CONNECT_JOB logs. These will have some
> other interesting data:
> If you look at the SOCKET_POOL_BOUND_TO_SOCKET event, it shows the "id" of
> the socket which that request was carried out on. Look this up in the log to
> see the events emitted for that particular socket. A couple things to look
> for in the socket's log: was the connection made to the same IP address in
> both cases? (unlikely but worth checking)

They are the same IP address in both cases...
So the second page refresh is reusing the same socket...

> One thing I noticed in both your logs is it is re-using an existing socket.
> (Not all the surprising if the XHR was started after loading a page from
> that domain).
> What this means is an earlier HTTP transaction was already carried out over
> that socket before the XHR was sent. This could be tickling a problem with
> the keep alive connection, say if the server doesn't flush its written bytes
> right away. (since you mentioned the problem happens in firefox too,
> probably more likely server-side issue than client-side).

Indeed.. the problem is on the server side >.<

> Another experiment worth trying is loading the XHR url directly from the web
> browser. Do you get the same results? (One notable difference is it will now
> be doing a GET rather than a POST).

The server code seemed unreliable...
It happened to be slow and cached the response for few subsequent request.

Thanks for your help Eric. I learned more tools from you :)

Hopefully this "dump and socket requests information" can be
integrated to the Chrome Developer tools to explain the "idle" waiting
time for an XHR requests and give exact suggestion that this is the
server issue, not the client...

Glad it's not a client-side issue...

Felix Halim