On Thu, 25 Jul 2013, Daniel Stenberg wrote:

> However, at line 75 we can see the second HTTP response being received 36817
> microseconds after the data was sent! Going down the log we can see that all
> subsequent responses show this exessive time.

...

> I can also confirm these numbers when stracing the problematic version. Now
> I'm diving into why this is happening and what I can do about it...

Using strace -T, I can also see that the poll() call actually takes that long:

23:58:38.816031 poll([{fd=3, events=POLLIN}], 1, 1002) = 1 ([{fd=3,
revents=POLLIN}]) <0.037972>

...

23:58:38.855623 poll([{fd=3, events=POLLIN}], 1, 1002) = 1 ([{fd=3,
revents=POLLIN}]) <0.038399>

...

23:58:38.896152 poll([{fd=3, events=POLLIN}], 1, 1002) = 1 ([{fd=3,
revents=POLLIN}]) <0.037898>

etc - the time there in <brackets> is in seconds.

(this particular log says 1002 instead of 1000 simply because I changed a few
occurances of 1000 to better detect exactly which 1000 use that takes this
long)

In the current code, this slow poll is the one called from within
curl_multi_wait() which in turn is used from within curl_easy_perform().

Next on my agenda is to wireshark and see if I can detect on the network why
the poll takes such a long time in this situation.

-- 
  / daniel.haxx.se
-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette:  http://curl.haxx.se/mail/etiquette.html