I don't see anything that looks particular bad -- and I've never before heard of such a problem (which obviously doesn't mean a lot ;)). Maybe you should enable debug mode so that we can see if some unusual processing happens.
Rainer > -----Original Message----- > From: [email protected] [mailto:rsyslog- > [email protected]] On Behalf Of Piavlo > Sent: Wednesday, April 06, 2011 11:19 PM > To: rsyslog-users > Subject: Re: [rsyslog] high cpu spkies by rsyslog which barely does > anything > > > > Anyone has an idea? > Might it be due to some rsyslog compilation option? > > Is my question inappropriate for this list? > > Thanks > Alex > > Piavlo wrote: > > > > Hi, > > > > I'd like to use rsyslog as central log collection solution. > > Manwhile I've compiled and installed as rsyslog 5.6.4 with a stock > > configuration as drop in replacement to local ksyslogd > > But I see a high quick cpu usage bursts by rsyslog every few seconds > > while it barely does anything. > > Most of the cpu time is spent in user mode. > > This happends on ec2 large instance with Centos-5.5. > > > > Below are the configs and sample strace/lsof of the rsyslogd process. > > > > Any idea why this happens? > > > > [root@www1a ~]# cat /etc/rsyslog.conf | grep -v -e '^$' -e '^#' > > $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat > > $ModLoad imklog > > $ModLoad imuxsock > > *.info;mail.none;authpriv.none;cron.none > /var/log/messages > > authpriv.* > /var/log/secure > > mail.* - > /var/log/maillog > > cron.* /var/log/cron > > *.emerg * > > uucp,news.crit > /var/log/spooler > > local7.* > /var/log/boot.log > > [root@www1a ~]# > > [root@www1a ~]# lsof -p $(pgrep rsyslogd) > > COMMAND PID USER FD TYPE DEVICE SIZE > NODE NAME > > rsyslogd 29994 root cwd DIR 8,1 4096 > 2 / > > rsyslogd 29994 root rtd DIR 8,1 4096 > 2 / > > rsyslogd 29994 root txt REG 8,1 1961412 > 2378118 > > /usr/local/rsyslog/5.6.4/sbin/rsyslogd > > rsyslogd 29994 root mem REG 8,1 137256 > 1720349 > > /lib64/ld-2.5.so > > rsyslogd 29994 root mem REG 8,1 83344 > 1543492 > > /usr/lib64/libz.so.1.2.3 > > rsyslogd 29994 root mem REG 8,1 142696 > 1720364 > > /lib64/libpthread-2.5.so > > rsyslogd 29994 root mem REG 8,1 20424 > 1720336 > > /lib64/libdl-2.5.so > > rsyslogd 29994 root mem REG 8,1 50288 > 1720370 > > /lib64/librt-2.5.so > > rsyslogd 29994 root mem REG 8,1 1712536 > 1720326 > > /lib64/libc-2.5.so > > rsyslogd 29994 root mem REG 8,1 85956 > 2378093 > > /usr/local/rsyslog/5.6.4/lib/rsyslog/lmnet.so > > rsyslogd 29994 root mem REG 8,1 90745 > 2378128 > > /usr/local/rsyslog/5.6.4/lib/rsyslog/imklog.so > > rsyslogd 29994 root mem REG 8,1 53471 > 2378110 > > /usr/local/rsyslog/5.6.4/lib/rsyslog/imuxsock.so > > rsyslogd 29994 root 0r REG 0,3 0 > 4026531849 > > /proc/kmsg > > rsyslogd 29994 root 1w REG 8,1 5019 > 1048938 > > /var/log/messages > > rsyslogd 29994 root 2w REG 8,1 18336275 > 1048939 > > /var/log/secure > > rsyslogd 29994 root 3u unix 0xffff8800241a2a80 > 80601917 > > /dev/log > > rsyslogd 29994 root 4w REG 8,1 214769 > 1048943 > > /var/log/cron > > [root@www1a ~]# > > [root@www1a ~]# strace -c -r -T -q -f -p $(pgrep rsyslogd) > > % time seconds usecs/call calls errors syscall > > ------ ----------- ----------- --------- --------- ---------------- > > nan 0.000000 0 4 write > > nan 0.000000 0 4 select > > nan 0.000000 0 4 recvfrom > > nan 0.000000 0 4 gettimeofday > > nan 0.000000 0 20 4 futex > > ------ ----------- ----------- --------- --------- ---------------- > > 100.00 0.000000 36 4 total > > [root@www1a ~]# > > [root@www1a ~]# strace -v -r -T -q -f -p $(pgrep rsyslogd) > > [pid 29995] 0.000000 futex(0x6a5d5c, FUTEX_WAIT, 1167, NULL > > <unfinished ...> > > [pid 29994] 0.005107 select(1, NULL, NULL, NULL, {85286, 180000} > > <unfinished ...> > > [pid 29997] 0.000049 read(0, <unfinished ...> > > [pid 29998] 0.000021 select(4, [3], NULL, NULL, NULL) = 1 (in > [3]) > > <4.329724> > > [pid 29998] 4.329868 recvfrom(3, "<86>Mar 24 14:01:07 > sshd[4487]: > > "..., 2048, 0, NULL, NULL) = 92 <0.000015> > > [pid 29998] 0.000097 gettimeofday({1300975267, 753128}, NULL) = > 0 > > <0.000010> > > [pid 29998] 0.000079 futex(0x6a5d5c, FUTEX_WAKE_OP, 1, 1, > 0x6a5d58, > > {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000014> > > [pid 29998] 0.000052 select(4, [3], NULL, NULL, NULL <unfinished > ...> > > [pid 29995] 0.000021 <... futex resumed> ) = 0 <4.335124> > > [pid 29995] 0.000077 futex(0x6a1b30, FUTEX_WAKE, 1) = 0 > <0.000057> > > [pid 29995] 0.000203 write(2, "Mar 24 14:01:07 www1a > > sshd[4487]"..., 95 <unfinished ...> > > [pid 29998] 0.024438 <... select resumed> ) = 1 (in [3]) > <0.024706> > > [pid 29995] 0.000024 <... write resumed> ) = 95 <0.024442> > > [pid 29998] 0.000247 recvfrom(3, "<86>Mar 24 14:01:07 > sshd[4487]: > > "..., 2048, 0, NULL, NULL) = 95 <0.000014> > > [pid 29998] 0.000066 gettimeofday({1300975267, 778334}, NULL) = > 0 > > <0.000010> > > [pid 29998] 0.000078 select(4, [3], NULL, NULL, NULL <unfinished > ...> > > [pid 29995] 0.005155 write(2, "Mar 24 14:01:07 www1a > > sshd[4487]"..., 98) = 98 <0.000345> > > [pid 29995] 0.000489 futex(0x6a5d5c, FUTEX_WAIT, 1169, NULL > > <unfinished ...> > > [pid 29998] 0.107333 <... select resumed> ) = 1 (in [3]) > <0.112941> > > [pid 29998] 0.000053 recvfrom(3, "<86>Mar 24 14:01:07 > sshd[4487]: > > "..., 2048, 0, NULL, NULL) = 84 <0.000016> > > [pid 29998] 0.000068 gettimeofday({1300975267, 891512}, NULL) = > 0 > > <0.000010> > > [pid 29998] 0.000079 futex(0x6a5d5c, FUTEX_WAKE_OP, 1, 1, > 0x6a5d58, > > {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000014> > > [pid 29998] 0.000050 select(4, [3], NULL, NULL, NULL <unfinished > ...> > > [pid 29995] 0.001586 <... futex resumed> ) = 0 <0.109150> > > [pid 29995] 0.000071 futex(0x6a1b30, FUTEX_WAKE, 1) = 0 > <0.000046> > > [pid 29995] 0.000169 write(2, "Mar 24 14:01:07 www1a > > sshd[4487]"..., 87) = 87 <0.000065> > > [pid 29995] 0.000194 futex(0x6a5d5c, FUTEX_WAIT, 1171, NULL > > <unfinished ...> > > [pid 29998] 1.420908 <... select resumed> ) = 1 (in [3]) > <1.422893> > > [pid 29998] 0.000049 recvfrom(3, "<86>Mar 24 14:01:09 > sshd[4517]: > > "..., 2048, 0, NULL, NULL) = 64 <0.000014> > > [pid 29998] 0.000503 gettimeofday({1300975269, 315123}, NULL) = > 0 > > <0.000042> > > [pid 29998] 0.000121 futex(0x6a5d5c, FUTEX_WAKE_OP, 1, 1, > 0x6a5d58, > > {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> > > [pid 29995] 0.000490 <... futex resumed> ) = 0 <1.422056> > > [pid 29998] 0.000010 <... futex resumed> ) = 1 <0.000487> > > [pid 29995] 0.000122 futex(0x6a1b30, FUTEX_WAKE, 1 <unfinished > ...> > > [pid 29998] 0.000019 select(4, [3], NULL, NULL, NULL <unfinished > ...> > > [pid 29995] 0.000067 <... futex resumed> ) = 0 <0.000072> > > [pid 29995] 0.000127 write(2, "Mar 24 14:01:09 www1a > > sshd[4517]"..., 67) = 67 <0.000105> > > [pid 29995] 0.001215 futex(0x6a5d5c, FUTEX_WAIT, 1173, NULL > > <unfinished ...> > > [pid 29998] 4.916991 <... select resumed> ) = 1 (in [3]) > <4.918369> > > [pid 29998] 0.000050 recvfrom(3, "<86>Mar 24 14:01:14 > sshd[4518]: > > "..., 2048, 0, NULL, NULL) = 92 <0.000013> > > [pid 29998] 0.000060 gettimeofday({1300975274, 234392}, NULL) = > 0 > > <0.000009> > > [pid 29998] 0.000079 futex(0x6a5d5c, FUTEX_WAKE_OP, 1, 1, > 0x6a5d58, > > {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000014> > > [pid 29998] 0.000050 select(4, [3], NULL, NULL, NULL <unfinished > ...> > > [pid 29995] 0.002861 <... futex resumed> ) = 0 <4.920060> > > [pid 29995] 0.000177 futex(0x6a1b30, FUTEX_WAKE, 1) = 0 > <0.000059> > > [pid 29995] 0.000218 write(2, "Mar 24 14:01:14 www1a > > sshd[4518]"..., 95) = 95 <0.000076> > > [pid 29995] 0.000378 futex(0x6a5d5c, FUTEX_WAIT, 1175, NULL > > <unfinished ...> > > [pid 29998] 0.067782 <... select resumed> ) = 1 (in [3]) > <0.071383> > > [pid 29998] 0.000054 recvfrom(3, "<86>Mar 24 14:01:14 > sshd[4518]: > > "..., 2048, 0, NULL, NULL) = 95 <0.000014> > > [pid 29998] 0.000069 gettimeofday({1300975274, 306060}, NULL) = > 0 > > <0.000011> > > [pid 29998] 0.000080 futex(0x6a5d5c, FUTEX_WAKE_OP, 1, 1, > 0x6a5d58, > > {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000014> > > [pid 29998] 0.000050 select(4, [3], NULL, NULL, NULL <unfinished > ...> > > [pid 29995] 0.001890 <... futex resumed> ) = 0 <0.069908> > > [pid 29995] 0.000070 futex(0x6a1b30, FUTEX_WAKE, 1) = 0 > <0.000044> > > [pid 29995] 0.000170 write(2, "Mar 24 14:01:14 www1a > > sshd[4518]"..., 98) = 98 <0.000069> > > [pid 29995] 0.000285 futex(0x6a5d5c, FUTEX_WAIT, 1177, NULL > > <unfinished ...> > > [pid 29998] 0.098664 <... select resumed> ) = 1 (in [3]) > <0.101048> > > [pid 29998] 0.001766 recvfrom(3, "<86>Mar 24 14:01:14 > sshd[4518]: > > "..., 2048, 0, NULL, NULL) = 84 <0.000047> > > [pid 29998] 0.000125 gettimeofday({1300975274, 409161}, NULL) = > 0 > > <0.000039> > > [pid 29998] 0.000119 futex(0x6a5d5c, FUTEX_WAKE_OP, 1, 1, > 0x6a5d58, > > {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...> > > [pid 29995] 0.000062 <... futex resumed> ) = 0 <0.100721> > > [pid 29998] 0.000009 <... futex resumed> ) = 1 <0.000058> > > [pid 29995] 0.000071 futex(0x6a1b30, FUTEX_WAKE, 1 <unfinished > ...> > > [pid 29998] 0.000019 select(4, [3], NULL, NULL, NULL <unfinished > ...> > > [pid 29995] 0.000065 <... futex resumed> ) = 0 <0.000070> > > [pid 29995] 0.000118 write(2, "Mar 24 14:01:14 www1a > > sshd[4518]"..., 87) = 87 <0.000069> > > [pid 29995] 0.000200 futex(0x6a5d5c, FUTEX_WAIT, 1179, NULL > > <unfinished ...> > > [root@www1a ~]# > > > > > > PS. One difference I noticed between stock rsyslog and syslog-ng > configs > > is that rsyslog holds just one fd open to /dev/log > > and select's it, while syslog-ng holds about 15 different fd's to > > /dev/log and epoll's them. > > Any particular reason for such a drastic difference? > > > > Thanks > > Alex > > > > _______________________________________________ > > rsyslog mailing list > > http://lists.adiscon.net/mailman/listinfo/rsyslog > > http://www.rsyslog.com > > > > _______________________________________________ > rsyslog mailing list > http://lists.adiscon.net/mailman/listinfo/rsyslog > http://www.rsyslog.com _______________________________________________ rsyslog mailing list http://lists.adiscon.net/mailman/listinfo/rsyslog http://www.rsyslog.com
