Skip to contentSkip to conversation

kupdated, bdflush and kjournald stuck in D state on RAID1 device (deadlock?)

DISCUSSION David Rees 2 participants 12 messages Aug 29, 2001 – Aug 30, 2001

lore
Share & tools
lore

David Rees

author
#0 lore raw

(Sent to linux-raid, linux-kernel and ext3-users since I'm not sure what type of issue this is)

I've got a test system here running Redhat 7.1 + stock 2.4.9 with these patches:

http://www.fys.uio.no/~trondmy/src/2.4.9/linux-2.4.9-NFS_ALL.dif
http://www.zip.com.au/~akpm/ext3-2.4-0.9.6-249.gz
http://domsch.com/linux/aacraid/linux-2.4.9-aacraid-20010816.patch

All three patches applied without any problems.

I've got a RAID1 device running over two IDE drives on a Promise controller. ext3 is the filesystem on the partition. In this machine, the aacraid driver isn't enabled.

The machine is to be used as a development database server running Sybase 11.9.2. Shortly after installing Sybase and loading some data, I noticed this:

[sybase@zorro ~]$ uptime
1:01pm up 1 day, 18:29, 3 users, load average: 3.00, 3.00, 2.91
[sybase@zorro ~]$ ps aux | head -15

USER       PID %CPU %MEM   VSZ  RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0  1368   72 ?        S    Aug27   0:05 init [3] 
root         2  0.0  0.0     0    0 ?        SW   Aug27   0:00 [keventd]
root         3  0.0  0.0     0    0 ?        SWN  Aug27   0:00 [ksoftirqd_CPU0]
root         4  0.0  0.0     0    0 ?        SW   Aug27   0:03 [kswapd]
root         5  0.0  0.0     0    0 ?        SW   Aug27   0:00 [kreclaimd]
root         6  0.0  0.0     0    0 ?        DW   Aug27   0:00 [bdflush]
root         7  0.0  0.0     0    0 ?        DW   Aug27   0:00 [kupdated]
root         9  0.0  0.0     0    0 ?        SW<  Aug27   0:00 [mdrecoveryd]
root        10  0.0  0.0     0    0 ?        SW<  Aug27   0:00 [raid1d]
root        11  0.0  0.0     0    0 ?        SW   Aug27   0:02 [kjournald]
root       130  0.0  0.0     0    0 ?        SW   Aug27   0:00 [kjournald]
root       131  0.0  0.0     0    0 ?        DW   Aug27   0:01 [kjournald]
root       374  0.0  0.0  1428  176 ?        S    Aug27   0:00 syslogd -m 0
root       379  0.0  0.0  1984  396 ?        S    Aug27   0:00 klogd -2

[sybase@zorro ~]$

As you can see, bdflush, kupdated and kjournald appear to be deadlocked.

How can I debug this problem and find out who's the problem? I will try rebooting and to see if the problem returns. If it does, it's back to ext2 for me on this partition, I guess. It seems like it could be a ext3 issue to me...

If there's any more information I can get, let me know. I'll leave the machine like this for a while before I reboot it.

Thanks,
-Dave

#1 lore raw
Quoted 17 lines · David Rees

...

USER       PID %CPU %MEM   VSZ  RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0  1368   72 ?        S    Aug27   0:05 init [3]
root         2  0.0  0.0     0    0 ?        SW   Aug27   0:00 [keventd]
root         3  0.0  0.0     0    0 ?        SWN  Aug27   0:00 [ksoftirqd_CPU0]
root         4  0.0  0.0     0    0 ?        SW   Aug27   0:03 [kswapd]
root         5  0.0  0.0     0    0 ?        SW   Aug27   0:00 [kreclaimd]
root         6  0.0  0.0     0    0 ?        DW   Aug27   0:00 [bdflush]
root         7  0.0  0.0     0    0 ?        DW   Aug27   0:00 [kupdated]
root         9  0.0  0.0     0    0 ?        SW<  Aug27   0:00 [mdrecoveryd]
root        10  0.0  0.0     0    0 ?        SW<  Aug27   0:00 [raid1d]
root        11  0.0  0.0     0    0 ?        SW   Aug27   0:02 [kjournald]
root       130  0.0  0.0     0    0 ?        SW   Aug27   0:00 [kjournald]
root       131  0.0  0.0     0    0 ?        DW   Aug27   0:01 [kjournald]
root       374  0.0  0.0  1428  176 ?        S    Aug27   0:00 syslogd -m 0
root       379  0.0  0.0  1984  396 ?        S    Aug27   0:00 klogd -2
Quoted 4 lines

[sybase@zorro ~]$

As you can see, bdflush, kupdated and kjournald appear to be deadlocked.

Certainly seems that way.

Can you please send the output of

ps xwo pid,command,wchan

Also, try a SYSRQ-T and, if the result makes it into the logs, please pass it through `ksymoops -m System.map'.

Thanks.

-

author
#4 lore raw
In reply to David Rees
Quoted 9 lines · Andrew Morton

Certainly seems that way.

Can you please send the output of

ps xwo pid,command,wchan

Also, try a SYSRQ-T and, if the result makes it into the logs, please pass it through `ksymoops -m System.map'.

OK, here's the ps output:

# ps xwo pid,command,wchan
  PID COMMAND          WCHAN
    1 init [3]         do_select
    2 [keventd]        context_thread
    3 [ksoftirqd_CPU0] ksoftirqd
    4 [kswapd]         kswapd
    5 [kreclaimd]      kreclaimd
    6 [bdflush]        raid1_alloc_r1bh
    7 [kupdated]       log_wait_commit
    9 [mdrecoveryd]    md_thread
   10 [raid1d]         md_thread
   11 [kjournald]      kjournald
  130 [kjournald]      kjournald
  131 [kjournald]      wait_on_buffer
  374 syslogd -m 0     do_select
  379 klogd -2         do_syslog
  433 ntpd             do_select
  444 sshd             do_select
  475 crond            nanosleep
  489 /sbin/mingetty t read_chan
  490 /sbin/mingetty t read_chan
  491 /sbin/mingetty t read_chan
  492 /sbin/mingetty t read_chan
  493 /sbin/mingetty t read_chan
16670 xinetd -stayaliv do_select
17481 /sbin/mingetty t read_chan
17814 sshd             do_select
18006 [rpciod]         rpciod
18007 [lockd]          svc_recv
18061 sshd             do_select
18238 su -             wait4
18239 -bash            wait4
18274 umount /opt      rwsem_down_write_failed
18277 su -             wait4
18278 -bash            wait4
18321 CROND            pipe_wait
18322 /bin/bash /usr/b wait4
18324 awk -v progname= pipe_wait
18325 /bin/sh /usr/lib wait4
18327 /usr/lib/sa/sadc pause
18328 ps xwo pid,comma -
#

Since last time I had tried unsuccessfully unmount the /opt partition which is the RAID1 disk. Otherwise, the partition still seems to behaving normally.

Below is the output from ksymoops.

Thanks,
Dave

# ksymoops -m /boot/System.map < ksym.out 
ksymoops 2.4.0 on i686 2.4.9-pl2-c1.  Options used
     -V (default)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.4.9-pl2-c1/ (default)
     -m /boot/System.map (specified)

No modules in ksyms, skipping objects
Warning (read_lsmod): no symbols in lsmod, is /proc/modules a valid lsmod file?
Warning (compare_maps): mismatch on symbol partition_name , ksyms_base says c01f17e0, System.map says c014c590. Ignoring ksyms_base entry

Call Trace: [<c011144d>] [<c0111380>] [<c013dafb>] [<c013de8c>] [<c0106cdb>] 
Call Trace: [<c011ebbd>] [<c011eac0>] [<c0105000>] [<c0105516>] [<c011eac0>] 
Call Trace: [<c0105000>] [<c0117bdf>] [<c0105516>] [<c0117b70>] 
Call Trace: [<c011144d>] [<c0111380>] [<c0111b71>] [<c012a139>] [<c0105000>] 
   [<c0105000>] [<c0105516>] [<c012a090>] 
Call Trace: [<c0111b0c>] [<c012a1fa>] [<c0105000>] [<c0105516>] [<c012a1b0>] 
Call Trace: [<c01e9745>] [<c01e9e80>] [<c01d23fa>] [<c01f1609>] [<c01c3c70>] 
   [<c01d2a53>] [<c01c3cd8>] [<c0130554>] [<c0130613>] [<c0133656>]
[<c0105000>] 
   [<c0105516>] [<c01335e0>] 
Call Trace: [<c0111bcc>] [<c015a8ca>] [<c0156e7e>] [<c0156eba>] [<c0155381>] 
   [<c0105bd7>] [<c01553d4>] [<c013452e>] [<c01334cc>] [<c0133786>]
[<c0105000>] 
   [<c0105516>] [<c0133690>] 
Call Trace: [<c01f5536>] [<c0105516>] [<c01f5460>] 
Call Trace: [<c01f5536>] [<c0105516>] [<c01f5460>] 
Call Trace: [<c0111b0c>] [<c015a49a>] [<c015a350>] [<c0105516>] [<c015a370>] 
Call Trace: [<c0111b0c>] [<c015a49a>] [<c015a350>] [<c0105516>] [<c015a370>] 
Call Trace: [<c01304b8>] [<c0157c4f>] [<c015a476>] [<c015a350>] [<c0105516>] 
   [<c015a370>] 
Call Trace: [<c013d7c3>] [<c01113e7>] [<c01fceaf>] [<c013dafb>] [<c013de8c>] 
   [<c0106cdb>] 
Call Trace: [<c01139ee>] [<c012f725>] [<c0108208>] [<c010822c>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c013e039>] [<c013e103>] [<c013e139>] [<c013e3a9>] 
   [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01fceaf>] [<c013dafb>] [<c013de8c>] [<c0106cdb>] 
Call Trace: [<c013d7c3>] [<c01113e7>] [<c01fceaf>] [<c013dafb>] [<c013de8c>] 
   [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01fceaf>] [<c013dafb>] [<c013de8c>] [<c0106cdb>] 
Call Trace: [<c011144d>] [<c0111380>] [<c01374e2>] [<c011ae12>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01ae39b>] [<c01afab5>] [<c01ac046>] [<c0121b5e>] 
   [<c012f725>] [<c012f2f2>] [<c0121ba2>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01ae39b>] [<c01afab5>] [<c01ac046>] [<c0121b5e>] 
   [<c012f725>] [<c012f2f2>] [<c0121ba2>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01ae39b>] [<c01afab5>] [<c01ac046>] [<c0121b5e>] 
   [<c012f725>] [<c012f2f2>] [<c0121ba2>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01ae39b>] [<c01afab5>] [<c01ac046>] [<c0121b5e>] 
   [<c012f725>] [<c012f2f2>] [<c0121ba2>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01ae39b>] [<c01afab5>] [<c01ac046>] [<c0121b5e>] 
   [<c012f725>] [<c012f2f2>] [<c0121ba2>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c0110c16>] [<c01fceaf>] [<c013dafb>] [<c013de8c>] 
   [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01ae39b>] [<c01afab5>] [<c01ac046>] [<c0121b5e>] 
   [<c012f725>] [<c012f2f2>] [<c0121ba2>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01fceaf>] [<c013dafb>] [<c013de8c>] [<c010823c>] 
   [<c0106cdb>] 
Call Trace: [<c0116a71>] [<c0106cdb>] 
Call Trace: [<c02358e2>] [<c0105516>] [<c0235750>] 
Call Trace: [<c01113e7>] [<c0127f07>] [<c02385c6>] [<c0181c12>] [<c0181ac0>] 
   [<c0105516>] [<c0181ac0>] 
Call Trace: [<c01113e7>] [<c01fceaf>] [<c013dafb>] [<c013de8c>] [<c0202e92>] 
   [<c010823c>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01afab5>] [<c01ac046>] [<c011c652>] [<c012f725>] 
   [<c0120df7>] [<c0106cdb>] 
Call Trace: [<c0116a71>] [<c0106cdb>] 
Call Trace: [<c0116a71>] [<c0106cdb>] 
Call Trace: [<c023b6d5>] [<c023db5e>] [<c0139697>] [<c0135058>] [<c012f2f2>] 
   [<c0121ba2>] [<c013509b>] [<c0106cdb>] 
Call Trace: [<c0116a71>] [<c0106cdb>] 
Call Trace: [<c01113e7>] [<c01afab5>] [<c01ac046>] [<c011c652>] [<c012f725>] 
   [<c0106cdb>] 
Call Trace: [<c013882b>] [<c0138914>] [<c012f725>] [<c012f677>] [<c0106cdb>] 
Call Trace: [<c0116a71>] [<c0106cdb>] 
Call Trace: [<c013882b>] [<c0138914>] [<c012f725>] [<c0120df7>] [<c012f677>] 
   [<c0106cdb>] 
Call Trace: [<c0116a71>] [<c0106cdb>] 
Call Trace: [<c010b912>] [<c0106cdb>]

Warning (Oops_read): Code line not seen, dumping what data is available

Trace; c011144d <schedule_timeout+7d/a0> Trace; c0111380 <process_timeout+0/50>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c0106cdb <system_call+33/38>
Trace; c011ebbd <context_thread+fd/1b0> Trace; c011eac0 <context_thread+0/1b0>
Trace; c0105000 <_stext+0/0>
Trace; c0105516 <kernel_thread+26/30>
Trace; c011eac0 <context_thread+0/1b0>
Trace; c0105000 <_stext+0/0>
Trace; c0117bdf <ksoftirqd+6f/c0>
Trace; c0105516 <kernel_thread+26/30>
Trace; c0117b70 <ksoftirqd+0/c0>
Trace; c011144d <schedule_timeout+7d/a0> Trace; c0111380 <process_timeout+0/50>
Trace; c0111b71 <interruptible_sleep_on_timeout+41/60> Trace; c012a139 <kswapd+a9/b0>
Trace; c0105000 <_stext+0/0>
Trace; c0105000 <_stext+0/0>
Trace; c0105516 <kernel_thread+26/30>
Trace; c012a090 <kswapd+0/b0>
Trace; c0111b0c <interruptible_sleep_on+3c/60> Trace; c012a1fa <kreclaimd+4a/a0>
Trace; c0105000 <_stext+0/0>
Trace; c0105516 <kernel_thread+26/30>
Trace; c012a1b0 <kreclaimd+0/a0>
Trace; c01e9745 <raid1_alloc_r1bh+f5/140> Trace; c01e9e80 <raid1_make_request+50/330> Trace; c01d23fa <ide_wait_stat+ba/100>
Trace; c01f1609 <md_make_request+49/80> Trace; c01c3c70 <generic_make_request+100/110> Trace; c01d2a53 <ide_do_request+293/2e0> Trace; c01c3cd8 <submit_bh+58/70>
Trace; c0130554 <write_locked_buffers+24/30> Trace; c0130613 <write_some_buffers+b3/120> Trace; c0133656 <bdflush+76/b0>
Trace; c0105000 <_stext+0/0>
Trace; c0105516 <kernel_thread+26/30>
Trace; c01335e0 <bdflush+0/b0>
Trace; c0111bcc <sleep_on+3c/60>
Trace; c015a8ca <log_wait_commit+3a/50> Trace; c0156e7e <journal_stop+17e/190>
Trace; c0156eba <journal_force_commit+2a/30> Trace; c0155381 <ext3_force_commit+21/30> Trace; c0105bd7 <__down_failed_trylock+7/c> Trace; c01553d4 <ext3_write_super+44/60> Trace; c013452e <sync_supers+be/e0>
Trace; c01334cc <sync_old_buffers+c/40> Trace; c0133786 <kupdate+f6/100>
Trace; c0105000 <_stext+0/0>
Trace; c0105516 <kernel_thread+26/30>
Trace; c0133690 <kupdate+0/100>
Trace; c01f5536 <md_thread+d6/160>
Trace; c0105516 <kernel_thread+26/30>
Trace; c01f5460 <md_thread+0/160>
Trace; c01f5536 <md_thread+d6/160>
Trace; c0105516 <kernel_thread+26/30>
Trace; c01f5460 <md_thread+0/160>
Trace; c0111b0c <interruptible_sleep_on+3c/60> Trace; c015a49a <kjournald+12a/1a0>
Trace; c015a350 <commit_timeout+0/10>
Trace; c0105516 <kernel_thread+26/30>
Trace; c015a370 <kjournald+0/1a0>
Trace; c0111b0c <interruptible_sleep_on+3c/60> Trace; c015a49a <kjournald+12a/1a0>
Trace; c015a350 <commit_timeout+0/10>
Trace; c0105516 <kernel_thread+26/30>
Trace; c015a370 <kjournald+0/1a0>
Trace; c01304b8 <__wait_on_buffer+68/90> Trace; c0157c4f <journal_commit_transaction+40f/1090> Trace; c015a476 <kjournald+106/1a0>
Trace; c015a350 <commit_timeout+0/10>
Trace; c0105516 <kernel_thread+26/30>
Trace; c015a370 <kjournald+0/1a0>
Trace; c013d7c3 <__pollwait+33/90>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01fceaf <sock_poll+1f/30>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c0106cdb <system_call+33/38>
Trace; c01139ee <do_syslog+be/2e0>
Trace; c012f725 <sys_read+95/d0>
Trace; c0108208 <do_IRQ+68/b0>
Trace; c010822c <do_IRQ+8c/b0>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c013e039 <do_pollfd+59/80>
Trace; c013e103 <do_poll+a3/100>
Trace; c013e139 <do_poll+d9/100>
Trace; c013e3a9 <sys_poll+249/380>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01fceaf <sock_poll+1f/30>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c0106cdb <system_call+33/38>
Trace; c013d7c3 <__pollwait+33/90>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01fceaf <sock_poll+1f/30>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01fceaf <sock_poll+1f/30>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c0106cdb <system_call+33/38>
Trace; c011144d <schedule_timeout+7d/a0> Trace; c0111380 <process_timeout+0/50>
Trace; c01374e2 <sys_stat64+62/70>
Trace; c011ae12 <sys_nanosleep+122/1a0> Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01ae39b <opost+1ab/1c0>
Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c0121b5e <do_munmap+26e/280>
Trace; c012f725 <sys_read+95/d0>
Trace; c012f2f2 <filp_close+52/60>
Trace; c0121ba2 <sys_munmap+32/50>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01ae39b <opost+1ab/1c0>
Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c0121b5e <do_munmap+26e/280>
Trace; c012f725 <sys_read+95/d0>
Trace; c012f2f2 <filp_close+52/60>
Trace; c0121ba2 <sys_munmap+32/50>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01ae39b <opost+1ab/1c0>
Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c0121b5e <do_munmap+26e/280>
Trace; c012f725 <sys_read+95/d0>
Trace; c012f2f2 <filp_close+52/60>
Trace; c0121ba2 <sys_munmap+32/50>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01ae39b <opost+1ab/1c0>
Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c0121b5e <do_munmap+26e/280>
Trace; c012f725 <sys_read+95/d0>
Trace; c012f2f2 <filp_close+52/60>
Trace; c0121ba2 <sys_munmap+32/50>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01ae39b <opost+1ab/1c0>
Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c0121b5e <do_munmap+26e/280>
Trace; c012f725 <sys_read+95/d0>
Trace; c012f2f2 <filp_close+52/60>
Trace; c0121ba2 <sys_munmap+32/50>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c0110c16 <do_page_fault+176/470> Trace; c01fceaf <sock_poll+1f/30>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01ae39b <opost+1ab/1c0>
Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c0121b5e <do_munmap+26e/280>
Trace; c012f725 <sys_read+95/d0>
Trace; c012f2f2 <filp_close+52/60>
Trace; c0121ba2 <sys_munmap+32/50>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01fceaf <sock_poll+1f/30>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c010823c <do_IRQ+9c/b0>
Trace; c0106cdb <system_call+33/38>
Trace; c0116a71 <sys_wait4+371/3a0>
Trace; c0106cdb <system_call+33/38>
Trace; c02358e2 <rpciod+192/240>
Trace; c0105516 <kernel_thread+26/30>
Trace; c0235750 <rpciod+0/240>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c0127f07 <kmem_cache_free+237/2e0> Trace; c02385c6 <svc_recv+1a6/3e0>
Trace; c0181c12 <lockd+152/270>
Trace; c0181ac0 <lockd+0/270>
Trace; c0105516 <kernel_thread+26/30>
Trace; c0181ac0 <lockd+0/270>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01fceaf <sock_poll+1f/30>
Trace; c013dafb <do_select+1fb/230>
Trace; c013de8c <sys_select+32c/480>
Trace; c0202e92 <net_tx_action+52/c0>
Trace; c010823c <do_IRQ+9c/b0>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c011c652 <sys_rt_sigaction+92/f0> Trace; c012f725 <sys_read+95/d0>
Trace; c0120df7 <sys_brk+b7/f0>
Trace; c0106cdb <system_call+33/38>
Trace; c0116a71 <sys_wait4+371/3a0>
Trace; c0106cdb <system_call+33/38>
Trace; c0116a71 <sys_wait4+371/3a0>
Trace; c0106cdb <system_call+33/38>
Trace; c023b6d5 <rwsem_down_write_failed+115/140> Trace; c023db5e <stext_lock+6ce/2cae>
Trace; c0139697 <path_release+27/30>
Trace; c0135058 <sys_umount+d8/110>
Trace; c012f2f2 <filp_close+52/60>
Trace; c0121ba2 <sys_munmap+32/50>
Trace; c013509b <sys_oldumount+b/10>
Trace; c0106cdb <system_call+33/38>
Trace; c0116a71 <sys_wait4+371/3a0>
Trace; c0106cdb <system_call+33/38>
Trace; c01113e7 <schedule_timeout+17/a0> Trace; c01afab5 <read_chan+365/690>
Trace; c01ac046 <tty_read+b6/e0>
Trace; c011c652 <sys_rt_sigaction+92/f0> Trace; c012f725 <sys_read+95/d0>
Trace; c0106cdb <system_call+33/38>
Trace; c013882b <pipe_wait+7b/b0>
Trace; c0138914 <pipe_read+b4/220>
Trace; c012f725 <sys_read+95/d0>
Trace; c012f677 <sys_llseek+c7/e0>
Trace; c0106cdb <system_call+33/38>
Trace; c0116a71 <sys_wait4+371/3a0>
Trace; c0106cdb <system_call+33/38>
Trace; c013882b <pipe_wait+7b/b0>
Trace; c0138914 <pipe_read+b4/220>
Trace; c012f725 <sys_read+95/d0>
Trace; c0120df7 <sys_brk+b7/f0>
Trace; c012f677 <sys_llseek+c7/e0>
Trace; c0106cdb <system_call+33/38>
Trace; c0116a71 <sys_wait4+371/3a0>
Trace; c0106cdb <system_call+33/38>
Trace; c010b912 <sys_pause+12/20>
Trace; c0106cdb <system_call+33/38>

3 warnings issued. Results may not be reliable.
#

#6 lore raw
In reply to David Rees
Quoted 14 lines · David Rees
Quoted 9 lines · Andrew Morton

Certainly seems that way.

Can you please send the output of

ps xwo pid,command,wchan

Also, try a SYSRQ-T and, if the result makes it into the logs, please pass it through `ksymoops -m System.map'.

OK, here's the ps output:

Quoted 15 lines
# ps xwo pid,command,wchan
  PID COMMAND          WCHAN
    1 init [3]         do_select
    2 [keventd]        context_thread
    3 [ksoftirqd_CPU0] ksoftirqd
    4 [kswapd]         kswapd
    5 [kreclaimd]      kreclaimd
    6 [bdflush]        raid1_alloc_r1bh
    7 [kupdated]       log_wait_commit
    9 [mdrecoveryd]    md_thread
   10 [raid1d]         md_thread
   11 [kjournald]      kjournald
  130 [kjournald]      kjournald
  131 [kjournald]      wait_on_buffer
  374 syslogd -m 0     do_select

OK, thanks. bdflush is stuck in raid1_alloc_r1bh() and everything else is blocked by it. I thought we fixed that a couple of months ago :(

Could you send the output of `cat /proc/meminfo'?

Quoted 2 lines

18239 -bash wait4
18274 umount /opt rwsem_down_write_failed

What are we trying to do here? Is /opt the deadlocked filesytem?

author
#7 lore raw
In reply to David Rees
Quoted 5 lines · Andrew Morton

OK, thanks. bdflush is stuck in raid1_alloc_r1bh() and everything else is blocked by it. I thought we fixed that a couple of months ago :(

Quoted 7 lines

Could you send the output of `cat /proc/meminfo'?

Quoted 2 lines

18239 -bash wait4
18274 umount /opt rwsem_down_write_failed

What are we trying to do here? Is /opt the deadlocked filesytem?

Yep, /dev/md0 is mounted on /opt.

-Dave

#9 lore raw
In reply to David Rees
Quoted 9 lines · David Rees
Quoted 7 lines · Andrew Morton

OK, thanks. bdflush is stuck in raid1_alloc_r1bh() and everything else is blocked by it. I thought we fixed that a couple of months ago :(

Could you send the output of `cat /proc/meminfo'?

Quoted 8 lines
Quoted 5 lines
Quoted 2 lines

18239 -bash wait4
18274 umount /opt rwsem_down_write_failed

What are we trying to do here? Is /opt the deadlocked filesytem?

Yep, /dev/md0 is mounted on /opt.

OK, and according to your /proc/meminfo:

total: used: free: shared: buffers: cached:

Mem:  525422592 497364992 28057600        0 133500928 335839232
Swap: 1052794880  4710400 1048084480
MemTotal:       513108 kB
MemFree:         27400 kB
MemShared:           0 kB
Buffers:        130372 kB
Cached:         323368 kB
SwapCached:       4600 kB
Active:         293704 kB
Inact_dirty:    161536 kB
Inact_clean:      3100 kB
Inact_target:       16 kB
HighTotal:           0 kB
HighFree:            0 kB
LowTotal:       513108 kB
LowFree:         27400 kB
SwapTotal:     1028120 kB
SwapFree:      1023520 kB

it's not an out-of-memory deadlock.

The RAID1 buffer allocation is pretty simple - unless the disk controller has decided to stop delivering interrupts, everything shold just come back to life as physical writes complete. I assume the hardware is still working OK?

It's a uniprocessor machine, yes?

author
#10 lore raw
In reply to David Rees
Quoted 41 lines · Andrew Morton
Quoted 9 lines · David Rees
Quoted 7 lines · Andrew Morton

OK, thanks. bdflush is stuck in raid1_alloc_r1bh() and everything else is blocked by it. I thought we fixed that a couple of months ago :(

Could you send the output of `cat /proc/meminfo'?

Quoted 8 lines
Quoted 5 lines
Quoted 2 lines

18239 -bash wait4
18274 umount /opt rwsem_down_write_failed

What are we trying to do here? Is /opt the deadlocked filesytem?

Yep, /dev/md0 is mounted on /opt.

OK, and according to your /proc/meminfo:

total: used: free: shared: buffers: cached:

Mem:  525422592 497364992 28057600        0 133500928 335839232
Swap: 1052794880  4710400 1048084480
MemTotal:       513108 kB
MemFree:         27400 kB
MemShared:           0 kB
Buffers:        130372 kB
Cached:         323368 kB
SwapCached:       4600 kB
Active:         293704 kB
Inact_dirty:    161536 kB
Inact_clean:      3100 kB
Inact_target:       16 kB
HighTotal:           0 kB
HighFree:            0 kB
LowTotal:       513108 kB
LowFree:         27400 kB
SwapTotal:     1028120 kB
SwapFree:      1023520 kB
Quoted 8 lines

it's not an out-of-memory deadlock.

The RAID1 buffer allocation is pretty simple - unless the disk controller has decided to stop delivering interrupts, everything shold just come back to life as physical writes complete. I assume the hardware is still working OK?

It's a uniprocessor machine, yes?

It is a uniprocessor machine, yes. The machine is a 1.1GHz Athlon on a Soyo motherboard. This is the first problem we've seen with the machine.

The machine was and is still working mostly ok. Since I typed "umount /opt", the opt directory doesn't show any contents any more, but before that things appear OK. I can still use fdisk to look at the partition layout of the drives in /opt raid1 array. /proc/mdstat is normal.

There are no other software raid devices on the machine (/ is also ext3 on a separate drive/controller). There are no suspicious messages printed from dmesg, either.

-Dave

#11 lore raw
In reply to David Rees
Quoted 12 lines · David Rees

...

The machine was and is still working mostly ok. Since I typed "umount /opt", the opt directory doesn't show any contents any more, but before that things appear OK. I can still use fdisk to look at the partition layout of the drives in /opt raid1 array. /proc/mdstat is normal.

There are no other software raid devices on the machine (/ is also ext3 on a separate drive/controller). There are no suspicious messages printed from dmesg, either.

Are you able to access all the underlying devices on the array? For example, if /dev/md0 consists of /dev/hda1 and /dev/hdb2, can you run 'cp /dev/hda1 /dev/null' and 'cp /dev/hdb1 /dev/null'?

If so, then I'm all out of ideas. Your raid1 buffers have disappeared into thin air :(

-

author
#2 lore raw
In reply to Andrew Morton
Quoted 8 lines · Andrew Morton

David Rees wrote:

Are you able to access all the underlying devices on the array? For example, if /dev/md0 consists of /dev/hda1 and /dev/hdb2, can you run 'cp /dev/hda1 /dev/null' and 'cp /dev/hdb1 /dev/null'?

If so, then I'm all out of ideas. Your raid1 buffers have disappeared into thin air :(

Copying as I write this (actually, cat /dev/hde1 > /dev/null and cat /dev/hdg1 >/dev/null.

Well, if no-one knows, I'll reboot and cross my fingers that it doesn't happen again.

Thanks,
Dave

author
#3 lore raw
In reply to Andrew Morton
Quoted 18 lines · Neil Brown

Thanks David and Andrew for providing all the helpful details. I know what happened. As Andrew said, the raid1 buffers have simply disappeared into thin air.
The line that makes them invisible is

			r1_bh->state = 0;
at line 165 in drivers/md/raid1.c.  This should be more like
			r1_bh->state = (1 << R1BH_PreAlloc);

We need to clear the Uptodate bit and the Phase bit, but not the prealloc bit.

Linus: Please consider applying this patch.

NeilBrown

md/raid1.c line 168

Quoted 8 lines
md/raid1.c +1 -1
@@ -162,7 +162,7 @@
 			conf->freer1 = r1_bh->next_r1;
 			conf->freer1_cnt--;
 			r1_bh->next_r1 = NULL;
-			r1_bh->state = 0;
+			r1_bh->state = (1 << R1BH_PreAlloc);
 			r1_bh->bh_req.b_state = 0;
 		}
 		md_spin_unlock_irq(&conf->device_lock);

Since rebooting, I haven't encountered any problems (but I did lose a lot of data on that partition!). I'll apply this patch and let you know if anything strange happens. Otherwise assume that it works for me.

I'm curious, why hasn't this bug shown up before? Did I just get unlucky? Or is everyone else using software raid1 without problems lucky? 8)

-Dave

author
#5 lore raw
In reply to David Rees

(took ext3-users out of CC, not relevant to them anymore)

Quoted 5 lines · Neil Brown
Quoted 3 lines · On Wednesday August 29, [email protected] wrote:

I'm curious, why hasn't this bug shown up before? Did I just get unlucky? Or is everyone else using software raid1 without problems lucky? 8)

Quoted 8 lines

You just got lucky.....
This could affect anyone who ran out of free memory while doing IO to a RAID1 array.
A recent change, which was intended to make this stuff more robust, probably had the side effect of making the bug more fatal. So it probably only affects people running 2.4.9.
It could affect earlier kernels, but they would have to sustain an out-of-memory condition for longer.

Now, when you say out-of-memory, do you mean out of memory plus swap? Or just out of memory?

Running out of memory is quite common with the kernel always filling up buffers and cache, but running out of memory+swap is not common (and I know I didn't hit that in my setup!)

Thanks for your help,

-Dave

author
#8 lore raw
In reply to David Rees
Quoted 5 lines · Neil Brown
Quoted 3 lines · On Wednesday August 29, [email protected] wrote:

Now, when you say out-of-memory, do you mean out of memory plus swap? Or just out of memory?

Quoted 7 lines

kmalloc(,GFP_NOIO) failure. i.e. transient out-of-phyical-memory condition.
I suspect that kmalloc tends to fail only occasionally as the failure will then to slow allocation requests down, and give the VM system a bit of time to write more stuff out to disc and so free up memory. I am fairly sure that without the patch it will happen again, but maybe not straight away.

OK, that explains how it happened, then. Memory had filled up while copying a good deal of data to the raid partition from another partition. That must have been when it ran out of memory and hung up.

I'll post again if anything else strange/bad happens.

Thanks,
Dave