On 4/17/07, Daniel Stenberg <daniel_at_haxx.se> 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 We need pretty accurate time info at many places

Yes, that is why a really good knowledge of curl is required to detect the
right places for the trick.

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

Indeed. This is similar to what we are doing ++ correcting timestamp
in the cases, where
looping takes long cycles. I would call it sloppy++ approach :).

If you will look through the code and indicate the appropriate places
besides curl_multi_socket*(), I could try to cook some patch proposal.

> >> 2 - dprintf_formatf() seems to take quite a lot of time as well
> >> How come this function is used so much?
> > -----------------------------------------------
> > 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
> >
> 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.

Sorry, for the poor explanation. libcurl library verbose mode was always on
during these profiling experiments.

It was curl-loader's verbose mode was off which has another meaning, namely:
- don't print to the logfile file any messages besides having CURLINFO_ERROR
level (our patch to split CURLINFO_TEXT to errors and indeed info text).

The motivation for the patch:
- curl-loader verbose mode prints tons of libcurl messages, and it is
important to
grep fast to errors, when treating GB files;
- curl-loader non-verbose mode is normally used for heavy loads, when
it is important
to save CPU by filtering out from the logfile output everything and
leaving only really
important errors.

By the way, do you think, that this patch may be of interest for somebody else
besides curl-loader:
http://curl-loader.svn.sourceforge.net/viewvc/curl-loader/trunk/curl-loader/patches/curl-trace-info-error.patch?view=markup

Hopefully, this misunderstanding does not impact the analysis below:

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

Thank you.

Sincerely,
Robert Iakobashvili,
coroberti %x40 gmail %x2e com
...................................................................
Navigare necesse est, vivere non est necesse
...................................................................
http://curl-loader.sourceforge.net
An open-source HTTP/S, FTP/S traffic
generating, and web testing tool.
Received on 2007-04-17