On Thu, 2008-01-17 at 17:27 +0200, dstuxo wrote:
Since I made some changes to the config since then, just to be sure, I attached another 3 strace logs with corresponding config file.
I can see some delay for each test...
* The script used for testing: #!/bin/sh
for i in `seq 1 10000`; do echo "THIS IS A TEST MESSAGE $i" logger -t tester -p cron.info "THIS IS A TEST MESSAGE $i" done #eof
I've checked the strace dumps that you posted, and I see nothing out of the ordinary here. For example: first three test messages in test_1.txt: 14:41:09.227599 read(6, "<78>Jan 17 14:41:09 tester: THIS IS A TEST MESSAGE 1\0", 8192) = 53 <0.000012> 14:41:09.228875 write(10, "Jan 17 14:41:09 localhost tester: THIS IS A TEST MESSAGE 1\n", 59) = 59 <0.000017> 14:41:09.229576 read(9, "<78>Jan 17 14:41:09 tester: THIS IS A TEST MESSAGE 2\0", 8192) = 53 <0.000010> 14:41:09.230433 write(10, "Jan 17 14:41:09 localhost tester: THIS IS A TEST MESSAGE 2\n", 59) = 59 <0.000011> 14:41:09.231096 read(6, "<78>Jan 17 14:41:09 tester: THIS IS A TEST MESSAGE 3\0", 8192) = 53 <0.000010> 14:41:09.231924 write(10, "Jan 17 14:41:09 localhost tester: THIS IS A TEST MESSAGE 3\n", 59) = 59 <0.000011> test_2.txt: 14:48:06.211659 read(6, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 1\0", 8192) = 53 <0.000011> 14:48:06.212941 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 1\n", 59) = 59 <0.001210> 14:48:06.214877 read(7, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 2\0", 8192) = 53 <0.000011> 14:48:06.215676 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 2\n", 59) = 59 <0.000013> 14:48:06.216339 read(6, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 3\0", 8192) = 53 <0.000010> 14:48:06.217114 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 3\n", 59) = 59 <0.000011> 14:48:06.217798 read(7, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 4\0", 8192) = 53 <0.000010> 14:48:06.218596 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 4\n", 59) = 59 <0.000011> test_3.txt: 14:54:19.460453 read(8, "<78>Jan 17 14:54:19 tester: THIS IS A TEST MESSAGE 1\0", 8192) = 53 <0.000011> 14:54:19.460891 read(8, 0x8079138, 8192) = -1 EAGAIN (Resource temporarily unavailable) <0.000008> 14:54:19.461267 write(9, "Jan 17 14:54:19 localhost tester: THIS IS A TEST MESSAGE 1\n", 59) = 59 <0.000016> 14:54:19.463589 read(8, "<78>Jan 17 14:54:19 tester: THIS IS A TEST MESSAGE 2\0", 8192) = 53 <0.000009> 14:54:19.464037 read(8, 0x8079138, 8192) = -1 EAGAIN (Resource temporarily unavailable) <0.000009> 14:54:19.464409 write(9, "Jan 17 14:54:19 localhost tester: THIS IS A TEST MESSAGE 2\n", 59) = 59 <0.000013> 14:54:19.466650 read(8, "<78>Jan 17 14:54:19 tester: THIS IS A TEST MESSAGE 3\0", 8192) = 53 <0.000010> 14:54:19.467075 read(8, 0x8079138, 8192) = -1 EAGAIN (Resource temporarily unavailable) <0.000008> 14:54:19.467447 write(9, "Jan 17 14:54:19 localhost tester: THIS IS A TEST MESSAGE 3\n", 59) = 59 <0.000014> The latency between the read and the accompanying write system call is about 0.001sec. If syslog-ng issues the write system call, then it is up to the kernel and the disks to get it written. You can ask syslog-ng to issue an fsync on the file(), but as you mention, that seriously degrades performance. Or was I missing something? syslog-ng received the message and wrote it to a destination file within a couple of msecs. If you turn off power after 2-3 seconds, and the message is lost, it is probably not syslog-ng's fault. -- Bazsi