Messages in this thread | | | Date | Tue, 21 Dec 2004 16:39:43 -0800 (PST) | From | Chris Stromsoe <> | Subject | 2.6.10-rc3, syslogd hangs then processes get stuck in schedule_timeout |
| |
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@cts.ucla.edu> To: linux-kernel@vger.kernel.org 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@vger.kernel.org >>>> 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@vger.kernel.org >>> 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@vger.kernel.org >> 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@vger.kernel.org > 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@vger.kernel.org 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@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
| |