[syslog-ng] Profiling syslog-ng

[John Morrissey]

On Tue, Feb 14, 2006 at 10:48:33AM +0100, Balazs Scheidler wrote:
> On Mon, 2006-02-13 at 10:57 -0500, John Morrissey wrote:
> > On Sun, Feb 12, 2006 at 08:07:14PM +0100, Balazs Scheidler wrote:
> > > Strange, it's been a while since I last profiled syslog-ng. What were
> > > your build options?
> > 
> > They're pretty stock. We used the Debian package for 1.6.9, adding 'debug'
> > to DEB_BUILD_OPTIONS, which seems to use:
> > 
> > ./configure --prefix=/ --mandir=/usr/share/man --sysconfdir=/etc \
> > 	--enable-debug
> > 
> > and '-g -Wall' for CFLAGS. We added -pg manually.
> 
> It should be ok. Maybe some kind of kernel patch (grsec or something
> like that?) 

Nope, it's essentially the stock Debian 2.6.8 kernel (the only changes we
make are to add drivers and optimize for the Pentium IV Xeon CPU).

> the problem is that it is not so simple, this code is in libol, it is
> generic and the program relies on this behaviour at a lot of places. (to
> request a read callback, it simply changes the value for a want_read
> value, no functions called to update the pollfd state)

FWIW, I modified syslog-ng 1.6.9 to usleep(10000) at the end of the
io_iter() loop in src/main.c. This dropped CPU consumption by about fourfold
- instead of spinning in that io_iter() loop, reading one or two messages
per poll(), it's now reading several (3-15) messages per poll().

Increasing the time to 20000 usec cuts CPU in half again - to about 1/8 of
the original consumption. It's now using ~10-15% of a CPU under the same
heavy log load from ~750 connections. Granted, this increases latency, but I
don't think 10 or 20 msec delays will kill anything.

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