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