performance test questions

30 Jan 2003

      Hi,

I'm conducting syslog-ng performance tests. I've deployed a central loghost 
environment and three clients trying to send messages which should end up on the 
central loghost with as few losses as possible. The whole thing is currently 
done over UDP and the clients have either syslogd or syslog-ng as daemons.

If I deploy syslog-ng as a client to send messages from /dev/log via UDP to the 
central loghost I experience a rather high message loss starting on a threshold 
of about 1000 messages sent in the least amount of time possible. If I do the 
same thing with syslogd the threshold is up to 35000 from the same machine. That 
means I can send 35000 messages to /dev/log as fast as possible and they still 
get reliably transferred to the central loghost and written to disk there.

A little stunned over this strange occurrance I've started to narrow the problem 
down and I ended up with following question: Why does syslog-ng not send a UDP 
packet per message sent via syslog() and an ending '\n'? And is there a mean to 
configure this odd behaviour? To illustrate what I mean I provide you with two 
sample dumps from a tcpdump session where I sent 3 messages. The first one is 
the tcpdump snipped of syslogd processing the messages and the second one is the 
result when syslog-ng processes the logs:

16:01:09.210645 x.y.z.6.514 > x.y.z.117.514: udp 71
0x0000	 4500 0063 ca2c 0000 4011 87aa ac1b e806	E..c.,..@.......
0x0010	 ac1b e875 0202 0202 004f 3a51 3c31 313e	...u.....O:Q<11>
0x0020	 6c6f 6774 6573 7420 3a20 5b31 5d20 4920	logtest.:.[1].I.
0x0030	 6c69 6b65 2074 6f20 6c6f 6720 6661 7374	like.to.log.fast
0x0040	 2062 7574 206d 6f73 7420 696d 706f 7274	.but.most.import
0x0050	 616e 746c 7920 6163 6375 7261 7465 2121	antly.accurate!!
0x0060	 2120 0a                                	!..
16:01:09.210820 x.y.z6.514 > x.y.z.117.514: udp 71
0x0000	 4500 0063 ca2d 0000 4011 87a9 ac1b e806	E..c.-..@.......
0x0010	 ac1b e875 0202 0202 004f 3a50 3c31 313e	...u.....O:P<11>
0x0020	 6c6f 6774 6573 7420 3a20 5b32 5d20 4920	logtest.:.[2].I.
0x0030	 6c69 6b65 2074 6f20 6c6f 6720 6661 7374	like.to.log.fast
0x0040	 2062 7574 206d 6f73 7420 696d 706f 7274	.but.most.import
0x0050	 616e 746c 7920 6163 6375 7261 7465 2121	antly.accurate!!
0x0060	 2120 0a                                	!..
16:01:09.211064 x.y.z.6.514 > x.y.z.117.514: udp 71
0x0000	 4500 0063 ca2e 0000 4011 87a8 ac1b e806	E..c....@.......
0x0010	 ac1b e875 0202 0202 004f 3a4f 3c31 313e	...u.....O:O<11>
0x0020	 6c6f 6774 6573 7420 3a20 5b33 5d20 4920	logtest.:.[3].I.
0x0030	 6c69 6b65 2074 6f20 6c6f 6720 6661 7374	like.to.log.fast
0x0040	 2062 7574 206d 6f73 7420 696d 706f 7274	.but.most.import
0x0050	 616e 746c 7920 6163 6375 7261 7465 2121	antly.accurate!!
0x0060	 2120 0a                                	!..
------
16:01:53.458412 x.y.z.6.1031 > x.y.z.117.514: udp 306
0x0000	 4500 014e ca6c 0000 4011 867f ac1b e806	E..N.l..@.......
0x0010	 ac1b e875 0407 0202 013a b8e8 3c31 313e	...u.....:..<11>
0x0020	 4a61 6e20 3330 2031 373a 3137 3a31 3920	Jan.30.17:17:19.
0x0030	 735f 696e 7440 6d69 6c6b 2d6e 6574 5f6f	s_int@milk-net_o
0x0040	 7665 7266 6c6f 7720 3a20 5b31 5d20 4920	verflow.:.[1].I.
0x0050	 6c69 6b65 2074 6f20 6c6f 6720 6661 7374	like.to.log.fast
0x0060	 2062 7574 206d 6f73 7420 696d 706f 7274	.but.most.import
0x0070	 616e 746c 7920 6163 6375 7261 7465 2121	antly.accurate!!
0x0080	 210a 3c31 313e 4a61 6e20 3330 2031 373a	!.<11>Jan.30.17:
0x0090	 3137 3a31 3920 735f 696e 7440 6d69 6c6b	17:19.s_int@milk
0x00a0	 2d6e 6574 5f6f 7665 7266 6c6f 7720 3a20	-net_overflow.:.
0x00b0	 5b32 5d20 4920 6c69 6b65 2074 6f20 6c6f	[2].I.like.to.lo
0x00c0	 6720 6661 7374 2062 7574 206d 6f73 7420	g.fast.but.most.
0x00d0	 696d 706f 7274 616e 746c 7920 6163 6375	importantly.accu
0x00e0	 7261 7465 2121 210a 3c31 313e 4a61 6e20	rate!!!.<11>Jan.
0x00f0	 3330 2031 373a 3137 3a31 3920 735f 696e	30.17:17:19.s_in
0x0100	 7440 6d69 6c6b 2d6e 6574 5f6f 7665 7266	t@milk-net_overf
0x0110	 6c6f 7720 3a20 5b33 5d20 4920 6c69 6b65	low.:.[3].I.like
0x0120	 2074 6f20 6c6f 6720 6661 7374 2062 7574	.to.log.fast.but
0x0130	 206d 6f73 7420 696d 706f 7274 616e 746c	.most.importantl
0x0140	 7920 6163 6375 7261 7465 2121 210a     	y.accurate!!!.
------

The configuration file for syslogd is:
---------------------------------------------------------
user.err	@x.y.z.117
---------------------------------------------------------

The configuration file for syslog-ng is:
---------------------------------------------------------
options {
         sync (0);
         time_reopen (10);
         log_fifo_size (1024);
         long_hostnames (on);
         use_dns (no);
         use_fqdn (no);
         create_dirs (yes);
         keep_hostname (yes);
};

source s_int {
         internal();
         unix-stream("/dev/log" max-connections(256));
};

filter f_test {
         facility(user) and level(err);
};

destination d_test {
         udp("x.y.z.117" port(514));
};

log {
         source(s_int);
         filter(f_test);
         destination(d_test);
         flags(final);
};
---------------------------------------------------------

Please enlighten me with an explanation to this problem. As an example take 
following verified numbers for a syslog() storm of 50000 messages where I do a 
50ms sleep every 250 messages sent. All in all this results in a 14332ms log 
burst (usleep() syscall overhead).

Message lines lost with syslog-ng (average): ~6300
Message lines lost with syslogd   (average): 0 !!!!

I've also attached the test tool which I use to conduct my tests. It's extremely 
simple so I don't expect any problems with this. It has sequence numbers so one 
is able to track down the losses (something which should be in syslog-ng too IMHO).

I currently have no explanation for this observation because I haven't read the 
whole source code yet. I suspect you have a read buffer on sources (/dev/log in 
this example) which overrides the '\n' -> fflush() semantics to be able to send 
less UDP packets with more content per packet. So I hope this is tunable 
somewhere or one can even disable it to mimic the old syslogd behavior.

Another question: Why is there no message sent when a buffer reaches its maximum 
size? This would help debugging and tuning a lot IMHO. Sorry if this has been 
discussed before.

Best regards,
Roberto Nibali, ratz
-- 
echo '[q]sa[ln0=aln256%Pln256/snlbx]sb3135071790101768542287578439snlbxq' | dc

#include <stdio.h>
#include <stdlib.h>
#include <syslog.h>
#include <unistd.h>
#include <sys/time.h>

/*
	logtest.c: RTSL!

	Copyright 2003, Roberto Nibali, terreActive AG
	Published under the GPLv2 license.
*/

#define DEF_STRING	"I like to log fast but most importantly accurate!!!"
#define DEF_IDENT	"logtest "
#define DEF_FACILITY	LOG_KERN
#define DEF_PRIO	LOG_ERR
#define DEF_NUM		10
#define DEF_INT		-1
#define DEF_MOD		1

void flood_log(const char *message, 
               unsigned int num,
               unsigned int seq,
	       long int interval,
	       unsigned int mod) {
	int i;

	for (i=1; i<=num; i++, seq++) {
		syslog(DEF_PRIO, "[%d] %s\n", seq, message);
		if (interval != DEF_INT && ((seq % mod) == 0)) {
			usleep(interval*1000);
		}
	}
}

int main(int argc, char *argv[]) {
	unsigned int seq = 1;
	unsigned int num = DEF_NUM;
	long int interval= DEF_INT;
	unsigned int mod = DEF_MOD;
	struct timeval start;
	struct timeval end;
	unsigned long diff;

	if (argc < 2) {
		printf("\n");
		printf("Usage: %s [<num>][<int>{ms}][<mod>]\n\n", argv[0]);
		printf("<num>: Amount of log messages\n");
		printf("<int>: Sleep time in miliseconds\n");
		printf("<mod>: Every <mod> do sleep for <int> miliseconds\n\n");
		printf("Example: %s 1000 700 250\n", argv[0]);
		printf("--------\n");
		printf("This will send 1000 messages and do a 0.7s delay ");
		printf("for every 250 messages sent.\n");
		printf("It should approximately take 2.8sec plus syscall ");
		printf("overhead which depends on the\n");
		printf("CPU, thus it effectively takes roughly 3s.\n");
		printf("\n");
		exit(1);
	} else if (argc == 2) {
		num=atoi(argv[1]);
	} else if (argc == 3) {
		num=atoi(argv[1]);
		interval=strtoul(argv[2], NULL, 10);
	} else if (argc == 4) {
		num=atoi(argv[1]);
		interval=strtoul(argv[2], NULL, 10);
		mod=atoi(argv[3]);
	}

	printf("Estimated time: %ld msecs\n",num*(interval==-1?1:interval)/mod);
	openlog(DEF_IDENT, 0, DEF_FACILITY);
	gettimeofday(&start, NULL);
	flood_log(DEF_STRING, num, seq, interval, mod);
	gettimeofday(&end, NULL);
	closelog();
	diff = (end.tv_sec - start.tv_sec) * 1000000
             + (end.tv_usec - start.tv_usec);
	printf("Message string: %s\n", DEF_STRING); 
	printf("Sent messages : %d\n", num); 
	printf("Elapsed time  : %ld msecs\n", diff/1000);
	printf("Bytes written : %d Bytes\n", num*sizeof(DEF_STRING));
	printf("Interval      : %ld msecs\n", interval == -1 ? 0 : interval);
	printf("Modulus       : %d\n", mod);
	return(0);
}

Roberto Nibali

Balazs Scheidler

Roberto Nibali

Balazs Scheidler

Roberto Nibali

Balazs Scheidler

Richard E. Perlotto II

Balazs Scheidler

Roberto Nibali

Balazs Scheidler

Roberto Nibali

Balazs Scheidler

Roberto Nibali

Achim Gsell

Balazs Scheidler

Achim Gsell

Roberto Nibali

Dmitry Frolov

Roberto Nibali

Roberto Nibali

Balazs Scheidler

Roberto Nibali

Richard E. Perlotto II

Roberto Nibali

Richard E. Perlotto II

Nate Campi

Roberto Nibali

tags

participants (6)