Re: 2.6.12.3 lockup with lots of D state processes
Just an update to this, I've found some more information. I can now reliably reproduce this lock up. I was trying to remove a large number of files from a reiserfs partition nohup rm -rf /var/spool/imap3/?/user/.migrated/*& And just a second or two after I started that command, I got a message on the console and the following in the log: Aug 8 22:37:13 server1 kernel: REISERFS: panic (device sdc3): journal-1413: journal_mark_dirty: j_len (1024) is too big Aug 8 22:37:13 server1 kernel: Aug 8 22:37:13 server1 kernel: [ cut here ] Aug 8 22:37:13 server1 kernel: kernel BUG at fs/reiserfs/prints.c:362! Aug 8 22:37:13 server1 kernel: invalid operand: [#1] Aug 8 22:37:13 server1 kernel: SMP Aug 8 22:37:13 server1 kernel: Modules linked in: Aug 8 22:37:13 server1 kernel: CPU:3 Aug 8 22:37:13 server1 kernel: EIP:0060:[]Not tainted VLI Aug 8 22:37:13 server1 kernel: EFLAGS: 00010282 (2.6.12.3-reiserfix-big) Aug 8 22:37:13 server1 kernel: EIP is at reiserfs_panic+0x38/0x60 Aug 8 22:37:13 server1 kernel: eax: 0063 ebx: c044a2e0 ecx: f4593b10 edx: c0451280 Aug 8 22:37:13 server1 kernel: esi: f6f4f800 edi: f6f4f958 ebp: f56ef868 esp: f4593b0c Aug 8 22:37:13 server1 kernel: ds: 007b es: 007b ss: 0068 Aug 8 22:37:13 server1 kernel: Process rm (pid: 4216, threadinfo=f4592000 task=e3293020) Aug 8 22:37:13 server1 kernel: Stack: c0451280 f6f4f958 c06cf5a0 c0453860 f4593b38 f6f4f800 f8fc3000 Aug 8 22:37:13 server1 kernel:c01ad8ad f6f4f800 c0453860 0400 f56ef868 f56ef868 f6f4f800 Aug 8 22:37:13 server1 kernel:05c5 f8fbc000 c018b052 f4593f0c f6f4f800 f56ef868 f585f834 f6e5d000 Aug 8 22:37:13 server1 kernel: Call Trace: Aug 8 22:37:13 server1 kernel: [] journal_mark_dirty+0x11d/0x250 Aug 8 22:37:13 server1 kernel: [] _reiserfs_free_block+0xe2/0x150 Aug 8 22:37:13 server1 kernel: [] reiserfs_free_block+0x2d/0x50 Aug 8 22:37:13 server1 kernel: [] prepare_for_delete_or_cut+0x604/0x6a0 Aug 8 22:37:13 server1 kernel: [] reiserfs_cut_from_item+0xda/0x480 Aug 8 22:37:13 server1 kernel: [] __find_get_block+0xee/0x100 Aug 8 22:37:13 server1 kernel: [] journal_begin+0x8e/0xe0 Aug 8 22:37:13 server1 kernel: [] reiserfs_do_truncate+0x346/0x4b0 Aug 8 22:37:13 server1 kernel: [] reiserfs_delete_object+0x32/0x60 Aug 8 22:37:13 server1 kernel: [] reiserfs_delete_inode+0x65/0xc0 Aug 8 22:37:13 server1 kernel: [] _atomic_dec_and_lock+0x27/0x50 Aug 8 22:37:13 server1 kernel: [] reiserfs_delete_inode+0x0/0xc0 Aug 8 22:37:13 server1 kernel: [] generic_delete_inode+0x7d/0xe0 Aug 8 22:37:13 server1 kernel: [] iput+0x63/0x70 Aug 8 22:37:13 server1 kernel: [] sys_unlink+0xcf/0x120 Aug 8 22:37:13 server1 kernel: [] syscall_call+0x7/0xb Aug 8 22:37:13 server1 kernel: Code: 74 24 10 50 8b 4c 24 18 8d be 58 01 00 00 51 e8 8f fd ff ff 68 a0 f5 6c c0 85 f6 89 d8 0f 45 c7 50 68 80 12 45 c0 e8 58 8e f7 ff <0f> 0b 6a 01 a5 a8 44 c0 68 a0 f5 6c c0 85 f6 0f 45 df 53 68 c0 After that and as below, processes started locking up in D state all over the place and the machine needed to be rebooted. Checking back through the log, it appears that the same error appeared in the log just before the same problem occured last time, so it seems basically to have been the same issue. The partition in question is fullish, but definitely has space and has never been totally full: [EMAIL PROTECTED] hm]$ ls -l /var/spool/imap3 lrwxrwxrwx1 root root 30 Jul 31 2003 /var/spool/imap3 -> /var/spool/backup/spool-imap3/ [EMAIL PROTECTED] hm]$ mount | grep /var/spool/backup /dev/sdc3 on /var/spool/backup type reiserfs (rw,noatime,nodiratime,nolargeio=1,notail) Any idea why running an rm -rf would cause this to happen? Rob --- FYI if it's any extra help, the BUG log message that occured just before the sysrq-t output at: http://robm.fastmail.fm/kernel/t8/ Was: Aug 7 08:49:33 server1 kernel: [ cut here ] Aug 7 08:49:33 server1 kernel: kernel BUG at fs/reiserfs/prints.c:362! Aug 7 08:49:33 server1 kernel: invalid operand: [#1] Aug 7 08:49:33 server1 kernel: SMP Aug 7 08:49:33 server1 kernel: Modules linked in: Aug 7 08:49:33 server1 kernel: CPU:0 Aug 7 08:49:33 server1 kernel: EIP:0060:[]Not tainted VLI Aug 7 08:49:33 server1 kernel: EFLAGS: 00010282 (2.6.12.3-reiserfix-big) Aug 7 08:49:33 server1 kernel: EIP is at reiserfs_panic+0x38/0x60 Aug 7 08:49:33 server1 kernel: eax: 0063 ebx: c044a2e0 ecx: f3587b10 edx: c0451280 Aug 7 08:49:33 server1 kernel: esi: f7123600 edi: f7123758 ebp: f59947cc esp: f3587b0c Aug 7 08:49:33 server1 kernel: ds: 007b es: 007b ss: 0068 Aug 7 08:49:33 server1 kernel: Process rm (pid: 13531, threadinfo=f3586000 task=e21cda40) Aug 7 08:49:33 server1 kernel: Stack: c0451280 f7123758 c06cf5a0 c0453860 f3587b38 f7123600 f8fc3000 Aug 7 08:49:33 server1 kerne
2.6.12.3 lockup with lots of D state processes
I have a feeling this might be related back to this issue... http://www.uwsg.iu.edu/hypermail/linux/kernel/0507.1/1518.html As a reminder: we've been running a number of IBM x235 machines with 6G of RAM with a 2.6.12.3 kernel fine for a couple of weeks now. Last night one of the machines started locking up. We could still ssh into the machine, and run some commands (free, uptime, etc), but lots of commands would just lock up and never return (ps, top, etc). The machine mostly runs a cyrus imap server with a number of reiserfs partitions. The partitions are all mounted as below: /dev/sda4 on /var/spool/imap type reiserfs (rw,noatime,nodiratime,nolargeio=1,notail) A full sysrq-t output (700k+) and kernel config are available here: http://robm.fastmail.fm/kernel/t8/ This time it definitely is a full one. In times past it's been bigger than our 1M dmesg buffer. The trace seems to show lots of procs like this: lmtpd D F27E2A40 0 16479 1 16480 16451 (NOTLB) dcb49e98 0086 0008 f27e2a40 f7878b1c f7c9fdfc c016a9d2 f7c9fdfc c0585800 c4293520 4448 06aa7882 000227d8 c4293520 c04c0bc0 f27e2a40 f27e2b64 0002 0001 f7c9fdfc f7f30580 Call Trace: [] dput+0x32/0x1b0 [] __down+0x88/0x100 [] default_wake_function+0x0/0x20 [] __down_failed+0x7/0xc [] .text.lock.namei+0xc4/0x1f8 [] filp_open+0x36/0x60 [] sys_open+0x35/0x70 [] syscall_call+0x7/0xb And a few looking something like this: pop3d D E67AA020 0 16368 1 16376 16296 (NOTLB) d2c27bac 0086 0008 e67aa020 c02b5177 f785a220 0282 c02b52ab 2085a000 c4293520 1a7f 8e0dd38c 000227d7 c4293520 c04c0bc0 e67aa020 e67aa144 c03bffc5 0002 8000 d2c27ba0 Call Trace: [] e100_xmit_frame+0x147/0x300 [] e100_xmit_frame+0x27b/0x300 [] qdisc_restart+0x15/0x1f0 [] queue_log_writer+0x5d/0x80 [] default_wake_function+0x0/0x20 [] do_journal_begin_r+0x1ca/0x2b0 [] ip_queue_xmit+0x425/0x4c0 [] ip_queue_xmit+0x447/0x4c0 [] journal_begin+0x8e/0xe0 [] reiserfs_dirty_inode+0x48/0x90 [] current_fs_time+0x50/0x70 [] __mark_inode_dirty+0x2d/0x170 [] inode_update_time+0xaf/0xc0 [] __generic_file_aio_write_nolock+0x514/0x5f0 [] __link_path_walk+0xadc/0xd40 [] tcp_sendmsg+0x39d/0x1000 [] dput+0x32/0x1b0 [] kmap_high+0x18/0x1e0 [] __generic_file_write_nolock+0x9e/0xc0 [] __d_lookup+0x109/0x140 [] dput+0x32/0x1b0 [] __link_path_walk+0xadc/0xd40 [] autoremove_wake_function+0x0/0x40 [] generic_file_write+0x4e/0xc0 [] reiserfs_file_write+0x17f/0x190 [] link_path_walk+0x97/0xd0 [] copy_to_user+0x60/0x70 [] cp_new_stat64+0xf3/0x110 [] default_llseek+0xbb/0xd0 [] vfs_write+0x8e/0xf0 [] sys_write+0x3d/0x70 [] syscall_call+0x7/0xb As an additional, we have applied this patch to the kernel to try and work around a previously identified deadlock situation in reiserfs. --- file.c~ 2004-10-02 12:29:33.223660850 +0400 +++ file.c 2004-10-08 10:03:03.001561661 +0400 @@ -1137,6 +1137,8 @@ return result; } +return generic_file_write(file, buf, count, ppos); + if ( unlikely((ssize_t) count < 0 )) return -EINVAL; Does this new lockup appear to be a remanifestation of the old problem, or does it appear to be something new... Rob - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
