Re: curl_multi_wait changes timeout to 0 and returns immediately
Date: Wed, 7 Jan 2015 20:38:17 +0200
On Sat, Dec 27, 2014 at 1:00 PM, <curl-library-request_at_cool.haxx.se> wrote:
> From: Daniel Stenberg <daniel_at_haxx.se>
> To: libcurl development <curl-library_at_cool.haxx.se>
> Subject: Re: curl_multi_wait changes timeout to 0 and returns
> Message-ID: <alpine.DEB.2.00.1412261703010.5939_at_tvnag.unkk.fr>
> Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed
> On Thu, 25 Dec 2014, Alex Lyakas wrote:
> Thanks a lot for all these additional debugging and research details Alex!
>> What happens is this: curl_multi_wait() calls multi_timeout(), which sets
>> its output parameter to 0. As a result, curl_multi_wait does:
>> /* If the internally desired timeout is actually shorter than requested from
>> the outside, then use the shorter time! But only if the internal timer
>> is actually larger than -1! */
>> (void)multi_timeout(multi, &timeout_internal);
>> if((timeout_internal >= 0) && (timeout_internal < (long)timeout_ms))
>> timeout_ms = (int)timeout_internal;
>> So timeout_ms ends up being 0.
> But the reason for it being set to 0 is that the closest timeout libcurl has
> for this multi handle has already passed or expires this millisecond!
>> Next, we call Curl_poll() with timeout_ms=0. This ends up in Linux system
>> call poll(), which returns immediately due to zero timeout. This happens
>> again and again, and leads to busy loop.
> The big question is how it can end up doing this in a loop. Which libcurl
> version are you using?
As I mentioned, I am using curl-7.35.0. But I have just retested with
the latest version (curl-7.39.0), and I see the same results, i.e.,
Curl_splaycomparekeys returning -1:
multi_timeout: return 0, multi->timetree->key=[2738:950134] now=[2739:129497]
multi_timeout: return 0, multi->timetree->key=[2738:950134] now=[2739:129576]
multi_timeout: return 0, multi->timetree->key=[2738:950134] now=[2739:129656]
multi_timeout: return 0, multi->timetree->key=[2738:950134] now=[2739:129726]
multi_timeout: return 0, multi->timetree->key=[2739:148140] now=[2739:149212]
multi_timeout: return 0, multi->timetree->key=[2739:148140] now=[2739:149262]
multi_timeout: return 0, multi->timetree->key=[2739:148140] now=[2739:149378]
multi_timeout: return 0, multi->timetree->key=[2739:148140] now=[2739:149423]
Any suggestion how to move forward with this issue?
>> As for the descriptors: even if curl_multi_wait() would not have found any
>> curl descriptors to wait for, I always pass an additional descriptor, so we
>> always have to wait for at least one descriptor. But in my tests,
>> curl_multi_wait() always finds some curl descriptor(s) to wait for as well.
> Right, but that won't matter much if it thinks there are timeouts that expire.
>> Debugging further, I found that curl_multi_wait() calls
>> Curl_splaycomparekeys() and it always returns -1.
> *always* ? I don't think that is true, as then everyone would always see this
> problem happen and I know for a fact not everybody does...
>> I added prints to see why Curl_splaycomparekeys() returns -1:
>> #define Curl_splaycomparekeys(i,j) ( ((i.tv_sec) < (j.tv_sec)) ? -1 : \
>> ( ((i.tv_sec) > (j.tv_sec)) ? 1 : \
>> ( ((i.tv_usec) < (j.tv_usec)) ? -1 : \
>> ( ((i.tv_usec) > (j.tv_usec)) ? 1 : 0 ))))
>> What happens is that i.tv_sec==j.tv_sec, but i.tv_usec<j.tv_usec.
> Yes, it is a comparison of two time stamps. It returns -1 or 1 if they differ
> or 0 if they are identical. Right?
Yes, this macro looks correct...
>> The behavior that would be ideal for me (after fixing the timeout=0 issue):
>> # if curl_multi_wait() finds at least one curl descriptor to wait for,
>> wait for all the descriptors (including the extra_fds) for the proper
> That's basically what it does already - with the litte twist: If it has an
> timeout that expires in 75 and it was given a timeout of 100, it is REALLY
> helpful that it returns after 75 without activity so that applications can
> maintain accurate timeout timers etc.
>> # otherwise: wait for extra_fd descriptors for a very short timeout, like
>> 100ms and reutrn. This way, user has a chance to poll every 100ms in case no
>> curl descriptors to wait are available. But I realize this behavior is very
>> custom to my use-case.
> I'm thinking about a new option for curl_multi_setopt() to tell
> curl_multi_wait() how long to wait if it finds no file descriptors at all to
> wait for... Or something like that.
> Would that be something you'd like and would consider using?
Yes, this sounds awesome! To be precise: we should use this new option
only if there are no *curl* file descriptors to wait for (i.e., not
including the extra_fds). So the logic would be something like this:
curl_timeout=<new option value>
curl_timeout=as returned by multi_timeout()
if extra_fds >0:
final_timeout = min(user-specified timeout, curl_timeout)
final_timeout = curl_timeout
Does this make sense?
>> : multi_timeout: return 0, multi->timetree->key=[485:670697]
> See, the timeout has already expired. The timestamp is in the past so it
> decides it should run now!
>> : multi_timeout: return 0, multi->timetree->key=[485:890191]
> ... and here.
>> : multi_timeout: return 0, multi->timetree->key=[486:429936]
> ... and here. And so on. The question is how you end up having those timeout
> expire times in them multi handle, as it indidates something is odd.
> It also resembles symptoms of previous bugs we've already fixed...
> / daniel.haxx.se
> Subject: Digest Footer
> curl-library mailing list
> End of curl-library Digest, Vol 112, Issue 41
List admin: http://cool.haxx.se/list/listinfo/curl-library
Received on 2015-01-07