Re: curl_multi_timeout and the multi_socket API

From: Henrik Holst via curl-library <curl-library_at_cool.haxx.se>
Date: Mon, 5 Apr 2021 20:51:44 +0200

Den mån 5 apr. 2021 kl 20:06 skrev Henrik Holst <
henrik.holst_at_millistream.com>:

>
>
> Den mån 5 apr. 2021 kl 18:39 skrev Fulup Ar Foll <fulup.arfoll_at_iot.bzh>:
>
>> Henrik,
>>
>> I confirm what Daniel said. If you take 100% of CPU your logic is
>> obviously wrong.
>>
>> If you run with a main loop, it is up to your your code to select which
>> socket is ready for reading. From your mainloop callback your should call curl_multi_socket_action
>> with the corresponding socket-fd and action. If you do so timeout callback
>> will only be called once per get resquest. You may run my sample on your
>> private server, you will see that it takes only few % of CPUs, this even
>> when you have 50 parallel ongoing requests.
>>
>
> hmm, I tried it with your example and yes that does not take 100% cpu but
> your code gets a timeout of 2ms from multiSetTimerCB so shouldn't that mean
> that your code would call curl_multi_socket_action (curlm,
> CURL_SOCKET_TIMEOUT, 0, &running_handles); every 2 milliseconds? That your
> code takes 0% cpu indicates that you don't call it every 2 milliseconds so
> am I understanding the timeout given by libcurl somehow or are (in this
> case the systemd event loop) the event loop used imposing some limit on how
> often it calls or rather convert it to usleep (2000) then that would also
> lead to 0% cpu since such a small value for usleep would be the full quanta
> (10ms) unless running under a realtime scheduler.
>
> [httpPool-create-async] multi curl pool initialized
> [request-sent] reqId=0 http://press.xxx.com/items&lastId=126599
> -- multiSetTimerCB timeout=0
> [multi-sock-insert] sock=7 (multiSetSockCB)
> -- multiSetTimerCB timeout=1
> -- waiting 1 pending request(s)
> httpOnSocketCB: sock=7 action=1
> [multi-sock-remove] sock=7 (multiSetSockCB)
> [multi-sock-insert] sock=7 (multiSetSockCB)
> -- multiSetTimerCB timeout=49
> -- waiting 1 pending request(s)
> -- multiSetTimerCB timeout=49
> -- waiting 1 pending request(s)
> httpOnSocketCB: sock=7 action=2
> -- waiting 1 pending request(s)
> -- multiSetTimerCB timeout=2
> -- waiting 1 pending request(s)
> *-- multiSetTimerCB timeout=2 <-- here is the last Timer Function CB
> setting the timeout to 2 milliseconds*
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> -- waiting 1 pending request(s)
> ^C
>

Ok so I added logging in httpOnTimerCB to output the time whenever it was
called (btw I have problems with your Makefile but perhaps we should take
that in private) and it appears to only be called once per
CURLMOPT_TIMERFUNCTION so is that where I'm thinking this wrong?

Aka I have seen the value returned from CURLMOPT_TIMERFUNCTION as "call
curl with CURL_SOCKET_TIMEOUT each timeout period" but by going by your
code it instead looks to be "call me again after timeout milliseconds once,
but only once" and if so then I definitely understand where I got wrong
this entire time.

-- multiSetTimerCB timeout=0
18:43:20.923012
[multi-sock-insert] sock=7 (multiSetSockCB)
-- multiSetTimerCB timeout=1
-- waiting 1 pending request(s)
httpOnSocketCB: sock=7 action=1
[multi-sock-remove] sock=7 (multiSetSockCB)
[multi-sock-insert] sock=7 (multiSetSockCB)
-- multiSetTimerCB timeout=49
-- waiting 1 pending request(s)
18:43:20.983453
-- multiSetTimerCB timeout=49
-- waiting 1 pending request(s)
httpOnSocketCB: sock=7 action=2
-- waiting 1 pending request(s)
18:43:21.173004
-- multiSetTimerCB timeout=10
-- waiting 1 pending request(s)
18:43:21.173030
-- multiSetTimerCB timeout=10
-- waiting 1 pending request(s)
18:43:21.423003
-- waiting 1 pending request(s)
18:43:21.423028
-- waiting 1 pending request(s)
-- waiting 1 pending request(s)
-- waiting 1 pending request(s)
-- waiting 1 pending request(s)
-- waiting 1 pending request(s)
-- waiting 1 pending request(s)
-- waiting 1 pending request(s)
-- waiting 1 pending request(s)
^C

/HH


> /HH
>
>>
>> Fulup
>>
>> On 05/04/2021 17:33, Daniel Stenberg wrote:
>>
>> On Mon, 5 Apr 2021, Henrik Holst wrote:
>>
>> On a side note (and perhaps I should have written this in a separate
>> mail) I did notice that the timer function callback returns far too low
>> values for long polling http servers if the user haven't set
>> CURLOPT_TIMEOUT. Caveat here is that I have only tested this with 7.58 and
>> 7.68 as of yet and not with HEAD.
>>
>>
>> As I mentioned before, we've removed the need for polling since then so a
>> lot of the really low-value timeouts are gone for a normal build. Now
>> libcurl waits on a socket even during a threaded name resolve.
>>
>> Here is one such run with CURLOPT_VERBOSE set, unfortunately the server
>> is not public so replication might be hard:
>>
>>
>> If this problem was widespread/common, then you wouldn't need to use a
>> private server to reproduce surely?
>>
>> Simply based on the fact that libcurl is fairly well used and nobody
>> (else) is reporting "100% cpu use", I don't think this is a common problem.
>> But I'm also sure there are bugs still to fix and I'm also sure that we've
>> fixed bugs since the versions you run. Some of those might change these
>> things.
>>
>>
>>


-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://curl.se/mail/etiquette.html
Received on 2021-04-05