[syslog-ng] Profiling syslog-ng

[Balazs Scheidler]

On Fri, 2006-02-10 at 16:11 -0500, John Morrissey wrote:
> I'm trying to profile syslog-ng on a set of servers that generate high
> levels of logging traffic (a few GB/day). Currently, syslog-ng is consuming
> anywhere from 40-80% of a CPU on a dual Pentium IV Xeon machine.
> 
> gprof(1) generates a profile, except for time consumed - it says "no time
> accumulated" even after running a profile-enabled syslog-ng for several
> minutes. For example:
> 
> Flat profile:
> 
> Each sample counts as 0.01 seconds.
>  no time accumulated
> 
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls  Ts/call  Ts/call  name
>   0.00      0.00     0.00      667     0.00     0.00  xalloc
>   0.00      0.00     0.00      593     0.00     0.00  prepare
>   0.00      0.00     0.00      434     0.00     0.00  gc_mark
>   0.00      0.00     0.00      372     0.00     0.00  ol_string_free
>   0.00      0.00     0.00      313     0.00     0.00  do_prepare_write
> 
> I've found similar complaints in the binutils list archives:
> 
> http://sourceware.org/ml/binutils/2005-07/msg00364.html
> http://sourceware.org/ml/binutils/2002-01/msg00121.html
> http://sourceware.org/ml/binutils/2001-10/msg00315.html
> 
> Personally, we're using glibc 2.3.2.ds1-22 and building the Debian syslog-ng
> 1.6.9-1 package using gcc 3.3.5-3 or 3.4.3-13.

Strange, it's been a while since I last profiled syslog-ng. What were
your build options?

> 
> I've also tried oprofile, but it only(?) seems to report call counts, not
> time consumed. For example:
> 
> samples  %        symbol name
> 102829   67.7349  io_iter
> 16560    10.9083  prepare
> 2975      1.9597  parse_log_msg
> 2518      1.6586  expand_macro
> 
> I've read io_iter() and it doesn't seem to contain any smoking guns that
> would account for 68% of total syslog-ng CPU usage.

It would be nice to know how blocking affects this, io_iter is the
central poll loop and unless syslog-ng is spinning for some reason it
should be really low in the profile. Hm... as I see you have
max-connections set to 2000, how many connections are there in reality?
Can you check lsof -p <syslog-ng pid> how many open fds syslog-ng is
polling?

io_iter basically traverses all registered fds and constructs a "struct
pollfd" array every time it is invoked. If there are a lot of fds, this
might be a problem.

> 
> Any suggestions on how to profile syslog-ng? I can post my configuration if
> it'd be helpful, but we've twisted many knobs (gc idle/busy thresholds,
> buffering via different sync() levels, disabling remote syslogging via UDP,
> etc.) without a major change in CPU consumption.

I would say call-graph enabled oprofile should do it. My first guess is
that it does not handle 1000s of connections too well, especially as
that list is traversed every time a single message is received.

-- 
Bazsi