Hi Daniel,

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
> immediately
> 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
>> timeout.
>
> 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:
if curlfds==0:
    curl_timeout=<new option value>
else:
    curl_timeout=as returned by multi_timeout()
if extra_fds >0:
    final_timeout = min(user-specified timeout, curl_timeout)
else
    final_timeout = curl_timeout
Does this make sense?

>
>> : multi_timeout: return 0, multi->timetree->key=[485:670697]
>> now=[485:690777]
>
> 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]
>> now=[485:907776]
>
> ... and here.
>
>> : multi_timeout: return 0, multi->timetree->key=[486:429936]
>> now=[486:430346]
>
> ... 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...

Thanks,
Alex.

>
> --
>
> / daniel.haxx.se
>
>
> ------------------------------
>
> Subject: Digest Footer
>
> _______________________________________________
> curl-library mailing list
> curl-library_at_cool.haxx.se
> http://cool.haxx.se/cgi-bin/mailman/listinfo/curl-library
>
>
> ------------------------------
>
> End of curl-library Digest, Vol 112, Issue 41
> *********************************************
-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-library
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2015-01-07