[syslog-ng] Profiling syslog-ng

[John Morrissey]

On Tue, Mar 14, 2006 at 11:42:48PM +0100, Balazs Scheidler wrote:
> > One more thing I've noticed: syslog-ng is making huge numbers of time(2)
> > calls. Our hub is calling time() 14-18,000 times/second(!) at peak. Is
> > there a way to optimize this away, or is 1.9.x more frugal in calling
> > it?
> 
> Maybe it calls somewhat less, but not significantly as it still calls
> time() for each message, and maybe even multiple times.
> 
> How expensive do you think calling time() is?

I did some crude benchmarking (running time() in a for loop) and it seems
each call consumes about 5usec of time on the machines I tried it on
(~2.5GHz Xeons running Debian sarge). Most of the time consumed is in system
state.

__GI_time() isn't very high in oprofile sampling (~1.8% of samples), so it
doesn't seem that expensive. I'll leave it alone for now. :-)

Thanks for all your help!

samples  %        app name                 symbol name
239113   21.6752  syslog-ng                io_iter
67510     6.1197  libc-2.3.2.so            strlen
42656     3.8667  syslog-ng                do_prepare_write
38041     3.4484  libc-2.3.2.so            re_search_internal
37159     3.3684  libc-2.3.2.so            _int_malloc
33938     3.0764  syslog-ng                affile_find_writer
30920     2.8028  libc-2.3.2.so            strptime_internal
30305     2.7471  syslog-ng                prepare
27297     2.4744  libc-2.3.2.so            transit_state
23447     2.1254  syslog-ng                parse_log_msg
23210     2.1039  libc-2.3.2.so            memcpy
20568     1.8645  syslog-ng                c_vformat_write
19815     1.7962  libc-2.3.2.so            __GI_time
19386     1.7573  libc-2.3.2.so            __offtime
17908     1.6233  libc-2.3.2.so            strcmp
16430     1.4894  syslog-ng                c_vformat_length
15923     1.4434  libc-2.3.2.so            check_matching
15899     1.4412  syslog-ng                expand_macros
15876     1.4391  libc-2.3.2.so            __GI_getenv
15568     1.4112  libc-2.3.2.so            memset
13982     1.2674  libc-2.3.2.so            build_upper_buffer
13210     1.1975  syslog-ng                do_distribute_log
12668     1.1483  syslog-ng                format_size_in_decimal
12397     1.1238  libc-2.3.2.so            __memchr
12311     1.1160  libc-2.3.2.so            _IO_vfprintf_internal
11740     1.0642  libc-2.3.2.so            re_string_reconstruct
11189     1.0143  libc-2.3.2.so            __cfree

john
-- 
John Morrissey          _o            /\         ----  __o
jwm at horde.net        _-< \_          /  \       ----  <  \,
www.horde.net/    __(_)/_(_)________/    \_______(_) /_(_)__