2.6.10-rc3, syslogd hangs then processes get stuck in schedule_timeout

[Chris Stromsoe]

I'm still seeing this problem.  It repeats every week or week and a half, 
usually after logs have been rotated and a dvd has been written.  syslogd 
stops writing output, then everything that does schedule_timeout() hangs, 
the process table fills, and everything grinds to a halt.

If the problem is detected early enough, syslogd can be manually killed 
and restarted, unwedging everything and returning everything to normal 
operation.

I'm running 2.6.10-rc3, compiled with smp.  I've been seeing this since at 
least 2.6.8.1, both smp and nosmp.  userspace is debian testing.

sysrq+t output from three hangs in November with 2.6.9 is at 
http://hashbrown.cts.ucla.edu/deadlock/.

A gdb backtrace for syslogd from the latest hang shows

#0  0xb7f937a1 in pthread_setcanceltype () from /lib/tls/libc.so.6
#1  0xb7fe4ae0 in _obstack () from /lib/tls/libc.so.6
#2  0xb7fe1fcc in ?? () from /lib/tls/libc.so.6
#3  0x0804f8dc in optind ()
#4  0xb7f41cbf in tzset () from /lib/tls/libc.so.6
#5  0x0804f820 in optind ()
#6  0x00000014 in ?? ()
#7  0x0804d2bc in _IO_stdin_used ()
#8  0xbfffec28 in ?? ()
#9  0x00000006 in ?? ()
#10 0x0804a8e8 in ?? ()
#11 0xb7fe1fcc in ?? () from /lib/tls/libc.so.6
#12 0x0000000c in ?? ()
#13 0x00000001 in ?? ()
#14 0x0000000c in ?? ()
#15 0xb7f400a1 in localtime () from /lib/tls/libc.so.6
#16 0x0804f8dc in optind ()
#17 0x00000001 in ?? ()
#18 0xb7fe4ae0 in _obstack () from /lib/tls/libc.so.6
#19 0x0000000a in ?? ()
#20 0xb7f3ff3f in ctime () from /lib/tls/libc.so.6
#21 0x0804f8dc in optind ()
#22 0x0804acfa in ?? ()
#23 0x0804f8dc in optind ()
#24 0x0804f820 in optind ()
#25 0x0000000c in ?? ()
#26 0x0804f900 in optind ()
#27 0x0804d393 in _IO_stdin_used ()
#28 0x00000000 in ?? ()
#29 0x00000000 in ?? ()
#30 0x00000000 in ?? ()
#31 0x0000000a in ?? ()
#32 0x00000000 in ?? ()
#33 0x00000000 in ?? ()
#34 0x0804f900 in optind ()
#35 0x0000000c in ?? ()
#36 0x00000001 in ?? ()
#37 0x00000000 in ?? ()
#38 0x0804b996 in ?? ()
#39 0x00000006 in ?? ()
#40 0x0804d393 in _IO_stdin_used ()
#41 0x0804f900 in optind ()
#42 0x0000000c in ?? ()
#43 0x00000000 in ?? ()
#44 0xb7fe1fcc in ?? () from /lib/tls/libc.so.6
#45 0xb7fe4ae0 in _obstack () from /lib/tls/libc.so.6
#46 <signal handler called>
#47 0xb7f41881 in tzset () from /lib/tls/libc.so.6



I can't repeat this at will, but it does seem to happen fairly frequently. 
How do I tell if this is a kernel problem or a userspace issue?  Is there 
anything I should look for to figure out why syslogd is causing everything 
else to block?


-Chris

---------- Forwarded message ----------
Date: Tue, 23 Nov 2004 10:17:57 -0800 (PST)
From: Chris Stromsoe <cbs@xxxxxxxxxxxx>
To: linux-kernel@xxxxxxxxxxxxxxx
Subject: Re: deadlock also with 2.6.9 nosmp, and 2.6.10-rc1 nosmp,
    was Re: deadlock with 2.6.9

I managed to get access to the system while it was exhibiting the problem. 
There are two cron processes both in D state.  I was not able to attach to 
either process with gdb.  /proc/pid/wchan showed do_fork for both processes.

I was able to 'killall -9 cron' and kill all of the cron tasks.

I had several other processes that /proc/pid/wchan showed in unix_wait_for_peer 
(sshd), futex_wait (syslogd), and do_exit (zombie sshd).

When I killed syslogd, the zombie sshd processes disappeared and everything 
started magically working again.


-Chris

On Fri, 19 Nov 2004, Chris Stromsoe wrote:

> I am still seeing this with 2.6.9 nosmp and with 2.6.10-rc1 nosmp.  The 
> symptoms are the same.  Every so often, things stop forking.  sysrq+t shows 
> almost every running process in schedule_timeout.  It seems to happen every 
> few days.
>
> The system is a syslog collector for >100 devices that log everything at 
> debug level.  Every 3 or 4 days (twice a week) it writes all of the logs to 
> dvd using growisofs.
>
> Every few days -- maybe 3 or 4, but not tied in any way that I can see to the 
> dvd writing -- the system becomes unresponsive; nothing forks. I can use 
> sysrq+e and sysrq+i to kill everything and then regain console access and 
> restart everything through /etc/rc*.d/* manually.  Life continues on until 
> the next hang.
>
> I have had the same problem with 2.6.8.1 smp, 2.6.9 smp, 2.6.9 smp booted 
> with nosmp, and now 2.6.10-rc1 smp booted with nosmp.
>
> I'm not sure where to look next.  This is fairly reproducible; it just takes 
> a few days.
>
>
> -Chris
>
>
> On Sat, 6 Nov 2004, Chris Stromsoe wrote:
>
> > I had a third lockup, this time not related to burning a dvd.  As before, 
> > the bulk of the processes that were hung were cron, and looked like:
> >
> > cron          S C1205F60     0  5023    444          5036  5022 (NOTLB)
> > c721ec9c 00000082 cd1b27f0 c1205f60 ca82ab7c c252a97c c721ec94 c014584e
> >       c252a940 c1fe8900 b7fe7000 ce607150 c1205f60 00239d5b fac8e72b 
> > 00003496
> >       cd1b2950 cf9b1d40 7fffffff 00000001 c721ecd8 c02f9f04 b7fe7000 
> > 00000001
> > Call Trace:
> > [<c02f9f04>] schedule_timeout+0xb4/0xc0
> > [<c02ef86e>] unix_wait_for_peer+0xbe/0xd0
> > [<c02f028a>] unix_dgram_sendmsg+0x26a/0x500
> > [<c0293cab>] sock_sendmsg+0xbb/0xe0
> > [<c0295161>] sys_sendto+0xe1/0x100
> > [<c02951b2>] sys_send+0x32/0x40
> > [<c0295a1a>] sys_socketcall+0x13a/0x250
> > [<c0104383>] syscall_call+0x7/0xb
> >
> >
> > Full sysrq+t dump is at <http://hashbrown.cts.ucla.edu/deadlock/>.
> >
> >
> > Several others that were in the same state:
> >
> > sendmail-mta  S C1205F60     0   416      1           434   334 (NOTLB)
> > ceaaceac 00000082 00000000 c1205f60 c12068c0 ceaacf44 ceaace84 c0139bb5
> >       cfba6b80 00000246 ceaaceac c01236d6 c1205f60 00005a1e cb12fa34 
> > 0000acdf
> >       ce9f97f0 0b4fcb33 ceaacec0 00000007 ceaacee8 c02f9eb5 ceaacec0 
> > 0b4fcb33
> > Call Trace:
> > [<c02f9eb5>] schedule_timeout+0x65/0xc0
> > [<c01671ee>] do_select+0x16e/0x2a0
> > [<c016760e>] sys_select+0x2ae/0x4c0
> > [<c0104383>] syscall_call+0x7/0xb
> >
> >
> > ntpd          S C1205F60     0   434      1           437   416 (NOTLB)
> > cf7e1eac 00000086 00000000 c1205f60 c12068c0 00000010 c034eb80 00000000
> >       cfba6700 bffffa10 000000d0 cfb1a2e0 c1205f60 000008d0 0c7e1cd2 
> > 0000ace0
> >       ce9f87d0 00000000 7fffffff 00000008 cf7e1ee8 c02f9f04 00000246 
> > cf7e1ed0
> > Call Trace:
> > [<c02f9f04>] schedule_timeout+0xb4/0xc0
> > [<c01671ee>] do_select+0x16e/0x2a0
> > [<c016760e>] sys_select+0x2ae/0x4c0
> > [<c0104383>] syscall_call+0x7/0xb
> >
> >
> > mdadm         S C1205F60     0   437      1           440   434 (NOTLB)
> > cf707eac 00000086 00000000 c1205f60 c12068c0 cfb3c610 00000003 00000000
> >       cf8204c0 00000246 cf707eac c01236d6 c1205f60 00000448 b1f651f9 
> > 0000acd3
> >       cfb3d790 0b4fd705 cf707ec0 00000005 cf707ee8 c02f9eb5 cf707ec0 
> > 0b4fd705
> > Call Trace:
> > [<c02f9eb5>] schedule_timeout+0x65/0xc0
> > [<c01671ee>] do_select+0x16e/0x2a0
> > [<c016760e>] sys_select+0x2ae/0x4c0
> > [<c0104383>] syscall_call+0x7/0xb
> >
> >
> >
> > atd           S C1205F60     0   440      1           444   437 (NOTLB)
> > ce5e0f48 00000082 00000000 c1205f60 c12068c0 00000000 00000000 00000000
> >       cfba6280 00000246 ce5e0f48 c01236d6 c1205f60 00006970 daf6df4d 
> > 0000aa54
> >       ce9f8270 0b5bfcbc ce5e0f5c 000f41a7 ce5e0f84 c02f9eb5 ce5e0f5c 
> > 0b5bfcbc
> > Call Trace:
> > [<c02f9eb5>] schedule_timeout+0x65/0xc0
> > [<c01243ce>] sys_nanosleep+0xde/0x160
> > [<c0104383>] syscall_call+0x7/0xb
> >
> >
> >
> > The box is P3 SMP, 256Mb ram, dual Intel eepro100 controllers, bonded into a 
> > single failover device.  The box is a syslog server for ~100 different other 
> > machines logging at debug level.  UDP traffic is constant.  syslog logs to a 
> > stripe of two mirrors, built with mdadm.
> >
> > Each of the three hangs has been exactly the same.  Nothing forks, but I can 
> > use sysrq to dump the process table, or to kill everything, log in, and 
> > restart.
> >
> > After I logged in today, all of the partitions were mounted ro, and one of 
> > the mirrors had kicked a partition out.  Tests on the partition and the disk 
> > that it's on so far show no errors.
> >
> > What would cause everything on the box to hang in schedule_timeout?
> >
> >
> > -Chris
> >
> > On Thu, 4 Nov 2004, Chris Stromsoe wrote:
> >
> > > I had another deadlock after the completion of a dvd writing session last 
> > > night.  The dvd was written using the ide interface with growisof.
> > >
> > > sysrq+p, sysrq+m, and a partial sysrq+t are at 
> > > http://hashbrown.cts.ucla.edu/deadlock/sysrq+t-20041104.
> > >
> > > Virtually everything is stuck in schedule_timeout+0xb4/0xc0.  It looks very 
> > > similar to the last deadlock I had (sysrq+t output is in the same directory 
> > > as the above as sysrq+t-20041101).
> > >
> > > cbs:~ > lsmod
> > > Module                  Size  Used by
> > > ide_cd                 39328  0
> > > cdrom                  38460  1 ide_cd
> > > e100                   29760  0
> > > bonding                64552  0
> > >
> > > Any ideas?  Anything in particular to check?
> > >
> > >
> > > -Chris
> > >
> > > On Mon, 1 Nov 2004, Chris Stromsoe wrote:
> > >
> > > > The machine collects remote syslog, roughly 1000 packets per second. The 
> > > > logs are burned to dvd several times per week.  The hanging may have 
> > > > coincided with the completion of one of the log burning sessions. Before 
> > > > the last crash I was using ide-scsi to do the burning.  Since the last 
> > > > crash, I switched over to directly using the ide device and have disabled 
> > > > ide-scsi.
> > > >
> > > > The machine did not crash.  Remote access with ssh would hang after 
> > > > authentication.  Already running processes that didn't fork anything 
> > > > responded fine to the network.  I could not fork a shell from a serial 
> > > > console.  I was able to use sysrq to pull debugging information.  I was 
> > > > also able to kill off all running processes (sysrq+e and sysrq+i), then 
> > > > log in from the serial console and restart things.
> > > >
> > > > I had the same problem with 2.6.8.1
> > > >
> > > > Most of the processes seem to be stuck in schedule_timeout.
> > > >
> > > > The full sysrq and .config are at http://hashbrown.cts.ucla.edu/deadlock/
> > > >
> > > >
> > > > cbs:~ > lsmod
> > > > Module                  Size  Used by
> > > > sg                     35040  0
> > > > sr_mod                 14884  0
> > > > cdrom                  38460  1 sr_mod
> > > > ide_scsi               15332  0
> > > > e100                   29760  0
> > > > bonding                64552  0
> > > >
> > > >
> > > >
> > > > telnet> send brk
> > > > SysRq : Show Regs
> > > >
> > > > Pid: 0, comm:              swapper
> > > > EIP: 0060:[<c01022cf>] CPU: 0
> > > > EIP is at default_idle+0x2f/0x40
> > > > EFLAGS: 00000246    Not tainted  (2.6.9)
> > > > EAX: 00000000 EBX: c039b000 ECX: c01022a0 EDX: c039b000
> > > > ESI: c04080a0 EDI: c04081a0 EBP: c039bfc4 DS: 007b ES: 007b
> > > > CR0: 8005003b CR2: bffffd66 CR3: 0fb3f000 CR4: 000006d0
> > > > [<c0102516>] show_regs+0x146/0x170
> > > > [<c0207a81>] __handle_sysrq+0x71/0xf0
> > > > [<c021a5aa>] receive_chars+0x11a/0x230
> > > > [<c021a9bd>] serial8250_interrupt+0xdd/0xe0
> > > > [<c0106c96>] handle_IRQ_event+0x36/0x70
> > > > [<c0107063>] do_IRQ+0xe3/0x1b0
> > > > [<c0104cf0>] common_interrupt+0x18/0x20
> > > > [<c010235b>] cpu_idle+0x3b/0x50
> > > > [<c039cb8b>] start_kernel+0x16b/0x190
> > > > [<c0100211>] 0xc0100211
> > > >
> > > >
> > > >
> > > > telnet> send brk
> > > > SysRq : Show Memory
> > > > Mem-info:
> > > > DMA per-cpu:
> > > > cpu 0 hot: low 2, high 6, batch 1
> > > > cpu 0 cold: low 0, high 2, batch 1
> > > > Normal per-cpu:
> > > > cpu 0 hot: low 30, high 90, batch 15
> > > > cpu 0 cold: low 0, high 30, batch 15
> > > > HighMem per-cpu: empty
> > > >
> > > > Free pages:        1348kB (0kB HighMem)
> > > > Active:26008 inactive:2118 dirty:10 writeback:0 unstable:0 free:337 
> > > > slab:16168 mapped:25917 pagetables:12564
> > > > DMA free:172kB min:32kB low:64kB high:96kB active:160kB inactive:48kB 
> > > > present:16384kB
> > > > protections[]: 0 0 0
> > > > Normal free:1176kB min:480kB low:960kB high:1440kB active:103872kB 
> > > > inactive:8424kB present:245760kB
> > > > protections[]: 0 0 0
> > > > HighMem free:0kB min:128kB low:256kB high:384kB active:0kB inactive:0kB 
> > > > present:0kB
> > > > protections[]: 0 0 0
> > > > DMA: 23*4kB 2*8kB 0*16kB 0*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 
> > > > 0*2048kB 0*4096kB = 172kB
> > > > Normal: 54*4kB 8*8kB 14*16kB 5*32kB 2*64kB 1*128kB 1*256kB 0*512kB 
> > > > 0*1024kB 0*2048kB 0*4096kB = 1176kB
> > > > HighMem: empty
> > > > Swap cache: add 66873, delete 65915, find 54916/55208, race 0+0
> > > > Free swap:       805560kB
> > > > 65536 pages of RAM
> > > > 0 pages of HIGHMEM
> > > > 1786 reserved pages
> > > > 600111 pages shared
> > > > 958 pages swap cached
> > > >
> > > >
> > > >
> > > >
> > > > cron          S C1205F60     0  2614    435          2628  2613 (NOTLB)
> > > > cde0bc9c 00000082 00000000 c1205f60 c12068c0 c4dba97c cde0bc94 c014584e
> > > >       c4dba940 c57d3468 b7fe7000 00000001 c1205f60 001aff4a d6c5bd65 
> > > > 0003d278
> > > >       c8c5e530 cf9aed40 7fffffff 00000001 cde0bcd8 c02f9f04 b7fe7000 
> > > > 00000001
> > > > Call Trace:
> > > > [<c02f9f04>] schedule_timeout+0xb4/0xc0
> > > > [<c02ef86e>] unix_wait_for_peer+0xbe/0xd0
> > > > [<c02f028a>] unix_dgram_sendmsg+0x26a/0x500
> > > > [<c0293cab>] sock_sendmsg+0xbb/0xe0
> > > > [<c0295161>] sys_sendto+0xe1/0x100
> > > > [<c02951b2>] sys_send+0x32/0x40
> > > > [<c0295a1a>] sys_socketcall+0x13a/0x250
> > > > [<c0104383>] syscall_call+0x7/0xb
> > > > cron          S C1205F60     0  2628    435          2640  2614 (NOTLB)
> > > > cc738c9c 00000086 c8c5e930 c1205f60 c82e1b7c c4dba73c cc738c94 00000000
> > > >       c4dba700 00000007 cc738cac cebb0690 c1205f60 00289ad9 af39036a 
> > > > 0003d2be
> > > >       c8c5ea90 cf9aed40 7fffffff 00000001 cc738cd8 c02f9f04 00000246 
> > > > 000000d0
> > > > Call Trace:
> > > > [<c02f9f04>] schedule_timeout+0xb4/0xc0
> > > > [<c02ef86e>] unix_wait_for_peer+0xbe/0xd0
> > > > [<c02f028a>] unix_dgram_sendmsg+0x26a/0x500
> > > > [<c0293cab>] sock_sendmsg+0xbb/0xe0
> > > > [<c0295161>] sys_sendto+0xe1/0x100
> > > > [<c02951b2>] sys_send+0x32/0x40
> > > > [<c0295a1a>] sys_socketcall+0x13a/0x250
> > > > [<c0104383>] syscall_call+0x7/0xb
> > > >
> > > > cron          S C1205F60     0  2640    435          2655  2628 (NOTLB)
> > > > c2bfbc9c 00000082 c721b9d0 c1205f60 cd21db7c c4dba07c c2bfbc94 00000000
> > > >       c4dba040 00000007 cf06b200 cebb0690 c1205f60 0027ced4 87b993a6 
> > > > 0003d304
> > > >       c721bb30 cf9aed40 7fffffff 00000001 c2bfbcd8 c02f9f04 c138f6c0 
> > > > c9bdea4c
> > > > Call Trace:
> > > > [<c02f9f04>] schedule_timeout+0xb4/0xc0
> > > > [<c02ef86e>] unix_wait_for_peer+0xbe/0xd0
> > > > [<c02f028a>] unix_dgram_sendmsg+0x26a/0x500
> > > > [<c0293cab>] sock_sendmsg+0xbb/0xe0
> > > > [<c0295161>] sys_sendto+0xe1/0x100
> > > > [<c02951b2>] sys_send+0x32/0x40
> > > > [<c0295a1a>] sys_socketcall+0x13a/0x250
> > > > [<c0104383>] syscall_call+0x7/0xb
> > > > sshd          S C1205F60     0  2653   1410          2654 17528 (NOTLB)
> > > > c163dc9c 00000086 c721b470 c1205f60 00000000 00000000 00000000 00000000
> > > >       c4dba4c0 00000007 cf06b560 c721af10 c1205f60 00039ddd 67910d34 
> > > > 0003d32a
> > > >       c721b5d0 cf9aed40 7fffffff 00000001 c163dcd8 c02f9f04 c138f6c0 
> > > > c9bdea4c
> > > > Call Trace:
> > > > [<c02f9f04>] schedule_timeout+0xb4/0xc0
> > > > [<c02ef86e>] unix_wait_for_peer+0xbe/0xd0
> > > > [<c02f028a>] unix_dgram_sendmsg+0x26a/0x500
> > > > [<c0293cab>] sock_sendmsg+0xbb/0xe0
> > > > [<c0295161>] sys_sendto+0xe1/0x100
> > > > [<c02951b2>] sys_send+0x32/0x40
> > > > [<c0295a1a>] sys_socketcall+0x13a/0x250
> > > > [<c0104383>] syscall_call+0x7/0xb
> > > >
> > > >
> > > >
> > > >
> > > >
> > > > -Chris
> > > > -
> > > > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> > > > the body of a message to majordomo@xxxxxxxxxxxxxxx
> > > > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> > > > Please read the FAQ at  http://www.tux.org/lkml/
> > > -
> > > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> > > the body of a message to majordomo@xxxxxxxxxxxxxxx
> > > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> > > Please read the FAQ at  http://www.tux.org/lkml/
> > -
> > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> > the body of a message to majordomo@xxxxxxxxxxxxxxx
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> > Please read the FAQ at  http://www.tux.org/lkml/
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/