[syslog-ng] Profiling syslog-ng

[Balazs Scheidler]

On Mon, 2006-03-13 at 15:41 -0500, John Morrissey wrote:
> On Sun, Feb 12, 2006 at 08:07:14PM +0100, Balazs Scheidler wrote:
> > Can you check if the attached patch decreases your load? It avoids
> > getting back to the poll loop after every log message and loops on the
> > currently processed fd until it either returns EAGAIN or it reaches a
> > hard-coded number. (which is currently 30)
> 
> Going back to this patch for a minute...
> 
> I'm now tuning our syslog hub, running the same 1.6.x. All of our servers
> forward their logs to this hub, mainly via UDP but there are a handful of
> TCP connections. This instance of syslog-ng is consuming ~30-35% of a CPU.
> 
> I would like to get it lower, which is probably a reasonable goal given the
> gains seen on the other machines (~80-90% of a CPU down to ~15%). I haven't
> profiled it yet, but strace(1) shows this one in a tight:
> 
> poll()
> recvfrom()
> poll()
> 
> loop. It seems poll() overhead could be cut with this patch that you posted
> (decrease-poll-load.diff). However, it looks like this code hunk in
> src/sources.c:
> 
>   122         if (closure->dgram || (!eol && closure->pos == closure->max_log_line)) {
>               [snip]
>   137             do_handle_line(closure, closure->pos, closure->buffer, salen ? (abstract_addr *) &sabuf : NULL, salen);
>   138             closure->pos = 0;
>   139             return ST_OK | ST_GOON;
> 
> doesn't treat datagram sockets the same as streams - instead of reading
> until a threshold is hit or we receive EAGAIN, a single datagram is read and
> processed and it returns, triggering another io_recv(). Could this be
> changed to give datagrams the same treatment as streams?

The latest 1.9.x snapshot already has this behaviour, although I'd
understand you hesitate going from 1.6.x -> 1.9.x in a sudden move.

What about the following (compile-tested) patch:

diff -u -r1.37.4.8 sources.c
--- sources.c   23 Feb 2006 17:44:46 -0000      1.37.4.8
+++ sources.c   13 Mar 2006 23:17:04 -0000
@@ -117,7 +117,7 @@
                if (closure->pad_size && eol) {
                        do_handle_line(closure, eol - closure->buffer, closure->buffer, salen ? (abstract_addr *) &sabuf : NULL, salen);
                        closure->pos = 0;
-                       return ST_OK | ST_GOON;
+                       goto next_fetch;
                }
                if (closure->dgram || (!eol && closure->pos == closure->max_log_line)) {
                        /* we don't have a terminating nl nor \0, and our buffer is
@@ -136,7 +136,7 @@
                        }
                        do_handle_line(closure, closure->pos, closure->buffer, salen ? (abstract_addr *) &sabuf : NULL, salen);
                        closure->pos = 0;
-                       return ST_OK | ST_GOON;
+                       goto next_fetch;
                }
                start = closure->buffer;
                while (eol) {
@@ -162,6 +162,8 @@
                }
                memmove(closure->buffer, start, &closure->buffer[closure->pos] - start);
                closure->pos = &closure->buffer[closure->pos] - start;
+
+       next_fetch:
                fetch_count++;
        }
        return ST_OK | ST_GOON;


-- 
Bazsi