Re: [curl-loader-devel] [PROF RFC 1/2] profiling of libcurl by curl-loader, steady state

[Robert I. <cor...@gm...>]

On 4/17/07, Daniel Stenberg <da...@ha...> wrote:
>
> I had a first look at these just now and three things struck me:
>
>   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 ();
}

An example from curl-loader here, look for get_tick_count (),
that calls gettimeofday ():
http://curl-loader.svn.sourceforge.net/viewvc/curl-loader/trunk/curl-loader/loader_smooth.c?view=markup

Better, that somebody with a deep understanding of curl will do the job.

>
>   2 - dprintf_formatf() seems to take quite a lot of time as well and I find
>       it strange. What kind of *printf() operations are made with your tests?
>       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]

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?

More details:
The profiling was done in a non-verbose mode. Still
client_tracing_function receives
all messages, but prints to a logfile only errors (CURL_ERROR). There was no any
errors during profiling.
Y can see here the patch, that we use to filter errors and to enable
for a user to segregate among really important errors and just infos:
http://curl-loader.svn.sourceforge.net/viewvc/curl-loader/trunk/curl-loader/patches/curl-trace-info-error.patch?view=markup

For our client_tracing_function you can look here:
http://curl-loader.svn.sourceforge.net/viewvc/curl-loader/trunk/curl-loader/loader.c?view=markup

>   3 - I figure we need more precision on the 5th and 6th columns (how long
>       each specific time takes by itself) to better identify functions that
>       seem to take too long.

Y can get more understanding from the lower (call-stack) sections
of *.prof outputs

For event more detailed information, please, find code-type gprof
output for the same expetiments with more details attached.

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