MonitorWare Knowledge Base

rgerhards wrote:

dlang wrote:I never get a chance to do anything like this. I do "rsyslogd -c3 -d" and a bunch of text scrolls by, with the segfault error at the bottom.

This is to be done AFTER the segault. Once it aborts, you get a core file (if not, set ulimit -c 99999999999). That core file should reside in the root directory. Then call gdb:

gdb /path/to/rsyslogd
core /core.whatever
bt
threads
{manually do}
thread n
bt
{for each thread you see}

threads doesn't work as a command (sorry, I don't have experiance with gdb)

This GDB was configured as "x86_64-linux-gnu"...Using host libthread_db library "/lib/libthread_db.so.1".

Reading symbols from /usr/lib/libz.so.1...done.
Loaded symbols for /usr/lib/libz.so.1
Reading symbols from /lib/libpthread.so.0...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/librt.so.1...done.
Loaded symbols for /lib/librt.so.1
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux-x86-64.so.2...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /usr/local/lib/rsyslog/lmnet.so...done.
Loaded symbols for /usr/local/lib/rsyslog/lmnet.so
Reading symbols from /lib/libnss_files.so.2...done.
Loaded symbols for /lib/libnss_files.so.2
Reading symbols from /usr/local/lib/rsyslog/immark.so...done.
Loaded symbols for /usr/local/lib/rsyslog/immark.so
Reading symbols from /usr/local/lib/rsyslog/imuxsock.so...done.
Loaded symbols for /usr/local/lib/rsyslog/imuxsock.so
Reading symbols from /usr/local/lib/rsyslog/imudp.so...done.
Loaded symbols for /usr/local/lib/rsyslog/imudp.so
Reading symbols from /usr/local/lib/rsyslog/imklog.so...done.
Loaded symbols for /usr/local/lib/rsyslog/imklog.so
Reading symbols from /lib/libnss_compat.so.2...done.
Loaded symbols for /lib/libnss_compat.so.2
Reading symbols from /lib/libnsl.so.1...done.
Loaded symbols for /lib/libnsl.so.1
Reading symbols from /lib/libnss_nis.so.2...done.
Loaded symbols for /lib/libnss_nis.so.2
Failed to read a valid object file image from memory.
Core was generated by `tools/rsyslogd -c3 -d'.
Program terminated with signal 6, Aborted.
#0 0x00007fb6849d807b in raise () from /lib/libc.so.6
(gdb) bt
#0 0x00007fb6849d807b in raise () from /lib/libc.so.6
#1 0x00007fb6849d984e in abort () from /lib/libc.so.6
#2 0x000000000041b079 in sigsegvHdlr (signum=11) at debug.c:759
#3 <signal handler called>
#4 0x0000000000418d67 in getCurrTime (t=0x7fb683f00a90, ttSeconds=0x7fb6843901ca) at datetime.c:92
#5 0x00007fb68438e44f in enqMsg (msg=0x7fff8d130f30 "imklog 3.21.5, log source = /proc/kmsg started.",
pszTag=0x7fb6843901c2 "kernel:", iFacility=0, iSeverity=<value optimized out>) at imklog.c:109
#6 0x00007fb68438e623 in imklogLogIntMsg (priority=6, fmt=<value optimized out>) at imklog.c:171
#7 0x00007fb68438e75e in klogWillRun () at linux.c:154
#8 0x000000000040b3fc in init () at syslogd.c:2230
#9 0x000000000040bc48 in mainThread () at syslogd.c:2854
#10 0x000000000040ce02 in realMain (argc=<value optimized out>, argv=0x7fff8d133dd8) at syslogd.c:3506
#11 0x00007fb6849c54ca in __libc_start_main () from /lib/libc.so.6
#12 0x000000000040931a in _start () at ../sysdeps/x86_64/elf/start.S:113
(gdb) threads
Undefined command: "threads". Try "help".
(gdb) help
List of classes of commands:

aliases -- Aliases of other commands
breakpoints -- Making program stop at certain points
data -- Examining data
files -- Specifying and examining files
internals -- Maintenance commands
obscure -- Obscure features
running -- Running the program
stack -- Examining the stack
status -- Status inquiries
support -- Support facilities
tracepoints -- Tracing of program execution without stopping the program
user-defined -- User-defined commands

Type "help" followed by a class name for a list of commands in that class.
Type "help" followed by command name for full documentation.
Command name abbreviations are allowed if unambiguous.

• Custom written rsyslog.conf?
• Maintenance Contract?
• Installation support?

my bad. I think it is "info threads", but let me verify....

yes, "info threads". This is a (partial screenshot from my system):

Code: Select all

This GDB was configured as "x86_64-redhat-linux-gnu"...
(gdb) core /vgcore.2127
Core was generated by `'.
Program terminated with signal 6, Aborted.
[New process 2130]
[New process 2129]
[New process 2128]
[New process 2127]
#0  0x00000035f20dcc02 in _start () from /lib64/ld-linux-x86-64.so.2
Missing separate debuginfos, use: debuginfo-install glibc.x86_64
(gdb) info thread
  4 process 2127  0x00000035f2032215 in ?? ()
  3 process 2128  0x00000035f2c0b19d in ?? ()
  2 process 2129  0x00000035f20dcc02 in _start () from /lib64/ld-linux-x86-64.so.2
* 1 process 2130  0x00000035f20dcc02 in _start () from /lib64/ld-linux-x86-64.so.2
(gdb) thread 1
[Switching to thread 1 (process 2130)]#0  0x00000035f20dcc02 in _start ()
   from /lib64/ld-linux-x86-64.so.2
(gdb) bt
#0  0x00000035f20dcc02 in _start () from /lib64/ld-linux-x86-64.so.2
#1  0x0000000000000000 in ?? ()
(gdb) thread 2
[Switching to thread 2 (process 2129)]#0  0x00000035f20dcc02 in _start ()
   from /lib64/ld-linux-x86-64.so.2
(gdb) bt
#0  0x00000035f20dcc02 in _start () from /lib64/ld-linux-x86-64.so.2
#1  0x0000000000000000 in ?? ()
(gdb)


Note that the data is not meaningful, because I had no real abort (just sent SIGABRT) AND no debug info with that build.

rgerhards wrote:my bad. I think it is "info threads", but let me verify....

just think of me as a semi-trained monkey (aka "operator")at this point

that works

(gdb) bt
#0 0x00007fb6849d807b in raise () from /lib/libc.so.6
#1 0x00007fb6849d984e in abort () from /lib/libc.so.6
#2 0x000000000041b079 in sigsegvHdlr (signum=11) at debug.c:759
#3 <signal handler called>
#4 0x0000000000418d67 in getCurrTime (t=0x7fb683f00a90, ttSeconds=0x7fb6843901ca) at datetime.c:92
#5 0x00007fb68438e44f in enqMsg (msg=0x7fff8d130f30 "imklog 3.21.5, log source = /proc/kmsg started.",
pszTag=0x7fb6843901c2 "kernel:", iFacility=0, iSeverity=<value optimized out>) at imklog.c:109
#6 0x00007fb68438e623 in imklogLogIntMsg (priority=6, fmt=<value optimized out>) at imklog.c:171
#7 0x00007fb68438e75e in klogWillRun () at linux.c:154
#8 0x000000000040b3fc in init () at syslogd.c:2230
#9 0x000000000040bc48 in mainThread () at syslogd.c:2854
#10 0x000000000040ce02 in realMain (argc=<value optimized out>, argv=0x7fff8d133dd8) at syslogd.c:3506
#11 0x00007fb6849c54ca in __libc_start_main () from /lib/libc.so.6
#12 0x000000000040931a in _start () at ../sysdeps/x86_64/elf/start.S:113
(gdb) info threads
5 process 506 0x00007fb684dfad2f in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
4 process 507 0x00007fb684a6ba96 in select () from /lib/libc.so.6
3 process 508 0x00007fb684a6ba96 in select () from /lib/libc.so.6
2 process 509 0x00007fb684a6ba96 in select () from /lib/libc.so.6
* 1 process 505 0x00007fb6849d807b in raise () from /lib/libc.so.6
(gdb) thread 2
[Switching to thread 2 (process 509)]#0 0x00007fb684a6ba96 in select () from /lib/libc.so.6
(gdb) bt
#0 0x00007fb684a6ba96 in select () from /lib/libc.so.6
#1 0x00007fb68449409f in runInput (pThrd=<value optimized out>) at imudp.c:177
#2 0x000000000042a1f0 in thrdStarter (arg=0x56e130) at ../threads.c:139
#3 0x00007fb684df7f1a in start_thread () from /lib/libpthread.so.0
#4 0x00007fb684a725d2 in clone () from /lib/libc.so.6
#5 0x0000000000000000 in ?? ()
(gdb) (gdb) thread 3
[Switching to thread 3 (process 508)]#0 0x00007fb684a6ba96 in select () from /lib/libc.so.6
(gdb) bt
#0 0x00007fb684a6ba96 in select () from /lib/libc.so.6
#1 0x00007fb684596577 in runInput (pThrd=<value optimized out>) at imuxsock.c:278
#2 0x000000000042a1f0 in thrdStarter (arg=0x56c050) at ../threads.c:139
#3 0x00007fb684df7f1a in start_thread () from /lib/libpthread.so.0
#4 0x00007fb684a725d2 in clone () from /lib/libc.so.6
#5 0x0000000000000000 in ?? ()
(gdb) thread 4
[Switching to thread 4 (process 507)]#0 0x00007fb684a6ba96 in select () from /lib/libc.so.6
(gdb) bt
#0 0x00007fb684a6ba96 in select () from /lib/libc.so.6
#1 0x000000000042a0aa in thrdSleep (pThis=0x550a00, iSeconds=<value optimized out>, iuSeconds=<value optimized out>)
at ../threads.c:211
#2 0x00007fb684698aad in runInput (pThrd=0x550a00) at immark.c:78
#3 0x000000000042a1f0 in thrdStarter (arg=0x550a00) at ../threads.c:139
#4 0x00007fb684df7f1a in start_thread () from /lib/libpthread.so.0
#5 0x00007fb684a725d2 in clone () from /lib/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 5
[Switching to thread 5 (process 506)]#0 0x00007fb684dfad2f in pthread_cond_timedwait@@GLIBC_2.3.2 ()
from /lib/libpthread.so.0
(gdb) bt
#0 0x00007fb684dfad2f in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#1 0x0000000000421e79 in wtiWorker (pThis=0x550940) at wti.c:402
#2 0x0000000000421618 in wtpWorker (arg=<value optimized out>) at wtp.c:422
#3 0x00007fb684df7f1a in start_thread () from /lib/libpthread.so.0
#4 0x00007fb684a725d2 in clone () from /lib/libc.so.6
#5 0x0000000000000000 in ?? ()

Ok, a first shot at this: remove imklog for the time being. I am evaluating what's wrong, but I guess this causes it...

rgerhards wrote:Ok, a first shot at this: remove imklog for the time being. I am evaluating what's wrong, but I guess this causes it...

that got it working, I'm copying to my high-end systems now to see how it works

It's strange... my imklog works, and I also have code at line 109 which hardly matches the backtrace. Could you post a copy of your imklog (I am hunting for anything that brought the pull process out of sync)?

on the high-end system under load one thread eats up all the CPU in a loop doing

select(3, [1 2], NULL, NULL, NULL) = 1 (in [2])
select(3, [1 2], NULL, NULL, NULL) = 1 (in [2])
select(3, [1 2], NULL, NULL, NULL) = 1 (in [2])

nothing else happens? Mhh... That in theory could be the reader, but then it should also use recvfrom(). I think I must re-check the git commits. I get the strong impression that our code pathes are different.

rgerhards wrote:It's strange... my imklog works, and I also have code at line 109 which hardly matches the backtrace. Could you post a copy of your imklog (I am hunting for anything that brought the pull process out of sync)?

secdev:/usr/src/rsyslog# ls -l plugins/imklog/*
-rw-r--r-- 1 root src 6182 2008-09-30 18:20 plugins/imklog/bsd.c
-rw-r--r-- 1 root src 8232 2008-10-06 11:15 plugins/imklog/imklog.c
-rw-r--r-- 1 root src 2328 2008-09-30 18:20 plugins/imklog/imklog.h
-rw-r--r-- 1 root src 799 2008-10-09 00:09 plugins/imklog/imklog.la
-rw-r--r-- 1 root src 355 2008-10-09 00:09 plugins/imklog/imklog_la-imklog.lo
-rw-r--r-- 1 root src 46032 2008-10-09 00:09 plugins/imklog/imklog_la-imklog.o
-rw-r--r-- 1 root src 349 2008-10-09 00:09 plugins/imklog/imklog_la-ksym.lo
-rw-r--r-- 1 root src 361 2008-10-09 00:09 plugins/imklog/imklog_la-ksym_mod.lo
-rw-r--r-- 1 root src 18304 2008-10-09 00:09 plugins/imklog/imklog_la-ksym_mod.o
-rw-r--r-- 1 root src 27168 2008-10-09 00:09 plugins/imklog/imklog_la-ksym.o
-rw-r--r-- 1 root src 352 2008-10-09 00:09 plugins/imklog/imklog_la-linux.lo
-rw-r--r-- 1 root src 30400 2008-10-09 00:09 plugins/imklog/imklog_la-linux.o
-rw-r--r-- 1 root src 25174 2008-09-30 18:20 plugins/imklog/ksym.c
-rw-r--r-- 1 root src 15339 2008-09-30 18:20 plugins/imklog/ksym_mod.c
-rw-r--r-- 1 root src 1347 2008-09-30 18:20 plugins/imklog/ksyms.h
-rw-r--r-- 1 root src 14554 2008-09-30 18:20 plugins/imklog/linux.c
-rw-r--r-- 1 root src 19274 2008-10-09 00:25 plugins/imklog/Makefile
-rw-r--r-- 1 root src 377 2008-09-30 18:20 plugins/imklog/Makefile.am
-rw-r--r-- 1 root src 20866 2008-10-09 00:25 plugins/imklog/Makefile.in
-rw-r--r-- 1 root src 1158 2008-09-30 18:20 plugins/imklog/module.h

line 109 of imklog.c
CHKiRet(submitMsg(pMsg));

finalize_it:
RETiRet;
}

/* parse the PRI from a kernel message. At least BSD seems to have
* non-kernel messages inside the kernel log...
* Expected format: "<pri>". piPri is only valid if the function
* successfully returns. If there was a proper pri ppSz is advanced to the
* position right after ">".
* rgerhards, 2008-04-14
*/
static rsRetVal



secdev:/usr/src/rsyslog# git log
commit 5742f9cdd0da18a3ddfb0a51a981637124a6ab25
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Thu Oct 9 07:48:22 2008 +0200

fixing segfault caused by all inputs but imudp

commit ace4f2f75202aec39449dac11b9eb1deca7428d7
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Wed Oct 8 18:55:11 2008 +0200

reordered imudp processing.

Message parsing is now done as part of main message queue worker
processing (was part of the input thread) This should also improve
performance, as potentially more work is done in parallel.

commit 82b583c4f99dd9beb30360f222c4d2a1152f75e1
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Wed Oct 8 14:56:02 2008 +0200

restructured imudp receive loop

cleaned up previous code and redid it in a way that makes
it much easier to extend it

also added a new macro DBGPRINTF which is a performance-optimzed
version of dbgprintf

commit 0fa23994669417fff4c4c057ce0c9d1e96f6d56c
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Tue Oct 7 15:10:03 2008 +0200

cleanup of output timestamp generation

commit 8528344ef58b5d2907bba8809f63d0bca2ce8d38
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Tue Oct 7 14:26:41 2008 +0200

"output" timestamp now taken from mesg's time generated

This enhances performance and, as some have pointed out, is
probably also more consistent with what users expect how
the various output-timestamp related function should work. This
commit needs some more testing.

commit cdecd7e524a5114ccff4f2909b32738bdb33c6ea
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Tue Oct 7 11:46:46 2008 +0200

slightly improved lock contention situation by moving out of

the critical section what could so with acceptable consequences

commit 7b3c05da9f126063384c80e9dd6fd5b2ae610074
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Tue Oct 7 10:28:44 2008 +0200

simple (yet efficient) name caching added to imudp

commit 65f74a712b111f946faaddd0583a6c7b22bd062f
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Mon Oct 6 14:25:23 2008 +0200

added $UDPServerTimeRequery option

...which enables to work with
less acurate timestamps in favor of performance. This enables querying
of the time only every n-th time if imudp is running in the tight
receive loop (aka receiving messsages at a high rate)

commit b849df20045ca5dfec36cdff5641e8a78d326b49
Merge: 1e53745... 39000a6...
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Mon Oct 6 12:07:53 2008 +0200

Merge branch 'master' into perf

Conflicts:

ChangeLog

commit 39000a62024510cd62607200e6100e3cd7c05005
Merge: 02bb3c9... 1ec8582...
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Thu Oct 2 15:52:47 2008 +0200

Merge branch 'beta'

commit 02bb3c901d9b14e8a08b111dde151f1ed4d2d1da
Author: Rainer Gerhards <rgerhards@adiscon.com>
Date: Thu Oct 2 15:52:24 2008 +0200

consolidated time calls during msg object creation

...this improves performance and consistency and also fixes
a bug where subsecond time properties generated by imfile, imklog and

rgerhards wrote:nothing else happens? Mhh... That in theory could be the reader, but then it should also use recvfrom(). I think I must re-check the git commits. I get the strong impression that our code pathes are different.

after doing a git checkout origin/perf I run the following script (I got tired of hunting for the prior commands)

secdev:/usr/src/rsyslog# cat reconfigure
#!/bin/bash
autoreconf -vfi
./configure --enable-static
make
tools/rsyslogd -c3 -d

Just to be on the save side, I have created a tarball based on what I currently have in my working directory. It is available at

http://download.rsyslog.com/rsyslog/rsy ... st1.tar.gz

I am trying to make sure we have the same state as quick as possible, it's already quite late for you (very, very much appreciated ), thus this somewhat dirty approach with the download.

you can start with ./configure
Rainer

FYI: I had a typo in the URL, just fixed that...

dlang wrote:
secdev:/usr/src/rsyslog# ls -l plugins/imklog/*
-rw-r--r-- 1 root src 6182 2008-09-30 18:20 plugins/imklog/bsd.c
-rw-r--r-- 1 root src 8232 2008-10-06 11:15 plugins/imklog/imklog.c
-rw-r--r-- 1 root src 2328 2008-09-30 18:20 plugins/imklog/imklog.h

[snip]

...this improves performance and consistency and also fixes
a bug where subsecond time properties generated by imfile, imklog and

This looks perfect - no I am even more puzzled. The imklog line does not contain a call to datetime modules, which is what the backtrace says.

AHHHH... I think I got it! If you just do a make, you do not install the loadable modules. So I assume you run the new rsyslogd together with the old modules! That would explain a lot.

rgerhards wrote:Just to be on the save side, I have created a tarball based on what I currently have in my working directory. It is available at

http://download.rsyslog.com/rsyslog/rsy ... st1.tar.gz

I am trying to make sure we have the same state as quick as possible, it's already quite late for you (very, very much appreciated ), thus this somewhat dirty approach with the download.

you can start with ./configure
Rainer

same result, the thread in the loop is the last one started (the highest pid)

from history
179 tar -xzpf rsyslog-3.21.6-Test1.tar.gz
180 ls
181 cd rsyslog-3.21.6-Test1
182 ls
183 ../../rsyslog/reconfigure
184 checkinstall
185 cp *.deb ../../