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 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?

> 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?

> : 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...

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