On Tue, 17 Apr 2007, Robert Iakobashvili wrote:

>> 1 - gettimeofday() certainly is called a lot and indeed takes a
>> significant time. We should address this (somehow).
>
> It is called in cycles in many cases.
> A pattern to solve it something like this :
>
> gettimeofday ();
> int cycle_counter = 0;
>
> for (i....) {
>
> DO_THE_JOB
>
> if (! (++cycle_counter % TIME_RECALCULATION_CYCLES_NUM)) {
> gettimeofday ();
> }

Yes, but that relies on the fact that the condition equals true often enough
to keep the date value accurate enough. We just recently added code to libcurl
that allows it to timeout with a a millisecond precision and that doesn't give
us much room to speculate on. We need pretty accurate time info at many places
in the code, and it isn't easy to come up with a generic approach for skipping
system calls for this.

Possibly we should simply detect that no millisecond timeout option is used,
and then switch to a more "sloppy" approach. That could perhaps involve
getting the time immediately when curl_multi_socket*() is called and then
simply not get it again (i.e keep returning the same) unless one of the
functions is called that we know is time consuming.

>> 2 - dprintf_formatf() seems to take quite a lot of time as well
>> How come this function is used so much?
>
> This is the question, that I was going to ask you. :)
> Y can dig inside into the callstasks for .prof files and look, where
> it is called.
> What I see is, e.g.:
> -----------------------------------------------
> 0.00 0.00 1/239402 curl_msnprintf [67]
> 0.04 0.00 37300/239402 curl_mvaprintf [27]
> 0.08 0.01 79201/239402 curl_maprintf [21]
> 0.12 0.02 122900/239402 curl_mvsnprintf [16]
> [12] 19.9 0.24 0.03 239402 dprintf_formatf [12]
> 0.02 0.00 5696319/5696319 addbyter [34]
> 0.01 0.00 7782971/7782971 alloc_addbyter [45]

This is the snprintf() and similar calls within libcurl.

> Just a hypotheses below:
> We are using (as posted) options:
> CURLOPT_VERBOSE with 1
> CURLOPT_DEBUGFUNCTION with client_tracing_function
>
> All these CURL_INFO, etc messages are somehow printed to the buffers
> delivered. May be there is something there, that may be improved?

Well, VERBOSE and DEBUGFUNCTION are for debugging and then we should be
prepared to get extra function calls like this.

> The profiling was done in a non-verbose mode.

Then we should use these functions for only "core" creation of strings and not
for debug/verbose messages. There are several things we can do to improve the
situation:

  1 - optimize buffer sizes for the typical sizes (for the aprintf() function)

  2 - make sure we don't use *printf() functions when there's no need. Possibly
      use memcpy() etc instead.

  3 - make sure that the *_formatf() is written to perform well, especially for
      the typical input/flags that we use (which I guess means %s).

-- 
  Commercial curl and libcurl Technical Support: http://haxx.se/curl.html