2009-10-27 21:20:01

by Pavel Machek

[permalink] [raw]
Subject: 2.6.32-rc5: surprise removal of USB mass storage, and whole system goes to hell


I did remove one harddrive w/o unmounting, and now the whole system
becomes unusable :-(: (whole dmesg attached).

Stuff like "sync" hangs, and I'll probably have to reboot soon.
Pavel

usb 1-1:1.0: uevent
usb-storage 1-1:1.0: usb_probe_interface
usb-storage 1-1:1.0: usb_probe_interface - got id
scsi18 : SCSI emulation for USB Mass Storage devices
usb-storage: device found at 18
usb-storage: waiting for device to settle before scanning
drivers/usb/core/inode.c: creating file '018'
scsi 18:0:0:0: Direct-Access HTS54106 0G9SA00 PQ: 0 ANSI: 2 CCS
sd 18:0:0:0: [sdc] 117210240 512-byte logical blocks: (60.0 GB/55.8 GiB)
sd 18:0:0:0: [sdc] Write Protect is off
sd 18:0:0:0: [sdc] Mode Sense: 3c 00 00 00
sd 18:0:0:0: [sdc] Assuming drive cache: write through
sd 18:0:0:0: Attached scsi generic sg1 type 0
sd 18:0:0:0: [sdc] Assuming drive cache: write through
sdc: sdc1 sdc2 sdc4
usb-storage: device scan complete
sd 18:0:0:0: [sdc] Assuming drive cache: write through
sd 18:0:0:0: [sdc] Attached SCSI disk
usb 1-1:1.0: uevent
usb 1-1: uevent
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
kjournald starting. Commit interval 5 seconds
EXT3 FS on sdc2, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
EXT3-fs error (device sdb2): ext3_find_entry: reading directory #2 offset 0
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
EXT3-fs error (device sdb2): ext3_find_entry: reading directory #2 offset 0
------------[ cut here ]------------
WARNING: at fs/buffer.c:1159 mark_buffer_dirty+0x80/0xa0()
Hardware name: 17097HU
Modules linked in:
Pid: 2110, comm: sh Not tainted 2.6.32-rc5-00154-gfbad3ad-dirty #83
Call Trace:
[<c0791da9>] ? printk+0x18/0x1a
[<c02b9110>] ? mark_buffer_dirty+0x80/0xa0
[<c023113c>] warn_slowpath_common+0x6c/0xc0
[<c02b9110>] ? mark_buffer_dirty+0x80/0xa0
[<c02311a5>] warn_slowpath_null+0x15/0x20
[<c02b9110>] mark_buffer_dirty+0x80/0xa0
[<c02eeed4>] ext3_commit_super+0x44/0x80
[<c02f01c8>] ext3_handle_error+0x48/0xb0
[<c0791da9>] ? printk+0x18/0x1a
[<c02f02f1>] ext3_error+0x51/0x60
[<c02ece2d>] ext3_find_entry+0x5ad/0x6d0
[<c02a96b4>] ? d_alloc+0x114/0x190
[<c02ed73d>] ext3_lookup+0x3d/0x100
[<c02a96d8>] ? d_alloc+0x138/0x190
[<c029faf9>] do_lookup+0x199/0x1c0
[<c02a12ed>] __link_path_walk+0x31d/0xd70
[<c02a1f34>] path_walk+0x54/0xb0
[<c02a2081>] do_path_lookup+0x51/0x60
[<c02a2b1a>] user_path_at+0x4a/0x80
[<c029b045>] vfs_fstatat+0x35/0x70
[<c029b15b>] vfs_stat+0x1b/0x20
[<c029b174>] sys_stat64+0x14/0x30
[<c0255dc3>] ? lockdep_sys_exit+0x23/0x80
[<c0202e5c>] ? sysenter_do_call+0x1e/0x31
[<c0202e50>] sysenter_do_call+0x12/0x31
---[ end trace 4eaf1068b9a2a4ba ]---
EXT3-fs error (device sdb2): ext3_readdir: directory #2 contains a hole at offset 0
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
INFO: task umount:21522 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
umount D c8469eb4 0 21522 24889 0x00000000
c8469ec8 00000046 00000002 c8469eb4 c2c01d64 00000000 c8469e6c c8469e7c
508b0602 00013840 00000000 00000003 00000000 db18ac40 c0ad2d64 cd044680
cd044908 c2c050c0 00000000 051c883d 00000046 cd044680 db18ac40 c8469eac
Call Trace:
[<c07946fe>] ? rwsem_down_failed_common+0x2e/0x190
[<c0794775>] rwsem_down_failed_common+0xa5/0x190
[<c079487d>] rwsem_down_write_failed+0x1d/0x30
[<c07948fe>] call_rwsem_down_write_failed+0x6/0x8
[<c0793f67>] ? down_write+0x47/0x50
[<c029a082>] ? deactivate_super+0x42/0x60
[<c029a082>] deactivate_super+0x42/0x60
[<c02ae1b8>] mntput_no_expire+0x98/0xc0
[<c02ae49f>] sys_umount+0x4f/0x2e0
[<c02ae749>] sys_oldumount+0x19/0x20
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
INFO: task sync:21224 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync D e527dec8 0 21224 21221 0x00000000
e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
Call Trace:
[<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
[<c02b31b8>] bdi_sched_wait+0x8/0x10
[<c07931e7>] __wait_on_bit+0x47/0x70
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
[<c02b31b0>] ? bdi_sched_wait+0x0/0x10
[<c0245820>] ? wake_bit_function+0x0/0x60
[<c02b3222>] sync_inodes_sb+0x62/0x130
[<c02b7250>] __sync_filesystem+0x20/0x60
[<c02b7375>] sync_filesystems+0xe5/0x120
[<c02b73fb>] sys_sync+0x1b/0x40
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.
INFO: task umount:21522 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
umount D c8469eb4 0 21522 24889 0x00000000
c8469ec8 00000046 00000002 c8469eb4 c2c01d64 00000000 c8469e6c c8469e7c
508b0602 00013840 00000000 00000003 00000000 db18ac40 c0ad2d64 cd044680
cd044908 c2c050c0 00000000 051c883d 00000046 cd044680 db18ac40 c8469eac
Call Trace:
[<c07946fe>] ? rwsem_down_failed_common+0x2e/0x190
[<c0794775>] rwsem_down_failed_common+0xa5/0x190
[<c079487d>] rwsem_down_write_failed+0x1d/0x30
[<c07948fe>] call_rwsem_down_write_failed+0x6/0x8
[<c0793f67>] ? down_write+0x47/0x50
[<c029a082>] ? deactivate_super+0x42/0x60
[<c029a082>] deactivate_super+0x42/0x60
[<c02ae1b8>] mntput_no_expire+0x98/0xc0
[<c02ae49f>] sys_umount+0x4f/0x2e0
[<c02ae749>] sys_oldumount+0x19/0x20
[<c0202e50>] sysenter_do_call+0x12/0x31
INFO: lockdep is turned off.

Pavel
--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html


Attachments:
(No filename) (11.89 kB)
delme.gz (18.58 kB)
Download all attachments

2009-10-28 01:14:18

by Jiri Kosina

[permalink] [raw]
Subject: Re: 2.6.32-rc5: surprise removal of USB mass storage, and whole system goes to hell

On Tue, 27 Oct 2009, Pavel Machek wrote:

> I did remove one harddrive w/o unmounting, and now the whole system
> becomes unusable :-(: (whole dmesg attached).
>
> Stuff like "sync" hangs, and I'll probably have to reboot soon.

>From the traces it seems that it might be related to the new per-bdi
writeback stuff ... adding Jens to CC.

> usb 1-1:1.0: uevent
> usb-storage 1-1:1.0: usb_probe_interface
> usb-storage 1-1:1.0: usb_probe_interface - got id
> scsi18 : SCSI emulation for USB Mass Storage devices
> usb-storage: device found at 18
> usb-storage: waiting for device to settle before scanning
> drivers/usb/core/inode.c: creating file '018'
> scsi 18:0:0:0: Direct-Access HTS54106 0G9SA00 PQ: 0 ANSI: 2 CCS
> sd 18:0:0:0: [sdc] 117210240 512-byte logical blocks: (60.0 GB/55.8 GiB)
> sd 18:0:0:0: [sdc] Write Protect is off
> sd 18:0:0:0: [sdc] Mode Sense: 3c 00 00 00
> sd 18:0:0:0: [sdc] Assuming drive cache: write through
> sd 18:0:0:0: Attached scsi generic sg1 type 0
> sd 18:0:0:0: [sdc] Assuming drive cache: write through
> sdc: sdc1 sdc2 sdc4
> usb-storage: device scan complete
> sd 18:0:0:0: [sdc] Assuming drive cache: write through
> sd 18:0:0:0: [sdc] Attached SCSI disk
> usb 1-1:1.0: uevent
> usb 1-1: uevent
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> kjournald starting. Commit interval 5 seconds
> EXT3 FS on sdc2, internal journal
> EXT3-fs: mounted filesystem with ordered data mode.
> EXT3-fs error (device sdb2): ext3_find_entry: reading directory #2 offset 0
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> EXT3-fs error (device sdb2): ext3_find_entry: reading directory #2 offset 0
> ------------[ cut here ]------------
> WARNING: at fs/buffer.c:1159 mark_buffer_dirty+0x80/0xa0()
> Hardware name: 17097HU
> Modules linked in:
> Pid: 2110, comm: sh Not tainted 2.6.32-rc5-00154-gfbad3ad-dirty #83
> Call Trace:
> [<c0791da9>] ? printk+0x18/0x1a
> [<c02b9110>] ? mark_buffer_dirty+0x80/0xa0
> [<c023113c>] warn_slowpath_common+0x6c/0xc0
> [<c02b9110>] ? mark_buffer_dirty+0x80/0xa0
> [<c02311a5>] warn_slowpath_null+0x15/0x20
> [<c02b9110>] mark_buffer_dirty+0x80/0xa0
> [<c02eeed4>] ext3_commit_super+0x44/0x80
> [<c02f01c8>] ext3_handle_error+0x48/0xb0
> [<c0791da9>] ? printk+0x18/0x1a
> [<c02f02f1>] ext3_error+0x51/0x60
> [<c02ece2d>] ext3_find_entry+0x5ad/0x6d0
> [<c02a96b4>] ? d_alloc+0x114/0x190
> [<c02ed73d>] ext3_lookup+0x3d/0x100
> [<c02a96d8>] ? d_alloc+0x138/0x190
> [<c029faf9>] do_lookup+0x199/0x1c0
> [<c02a12ed>] __link_path_walk+0x31d/0xd70
> [<c02a1f34>] path_walk+0x54/0xb0
> [<c02a2081>] do_path_lookup+0x51/0x60
> [<c02a2b1a>] user_path_at+0x4a/0x80
> [<c029b045>] vfs_fstatat+0x35/0x70
> [<c029b15b>] vfs_stat+0x1b/0x20
> [<c029b174>] sys_stat64+0x14/0x30
> [<c0255dc3>] ? lockdep_sys_exit+0x23/0x80
> [<c0202e5c>] ? sysenter_do_call+0x1e/0x31
> [<c0202e50>] sysenter_do_call+0x12/0x31
> ---[ end trace 4eaf1068b9a2a4ba ]---
> EXT3-fs error (device sdb2): ext3_readdir: directory #2 contains a hole at offset 0
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> INFO: task umount:21522 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> umount D c8469eb4 0 21522 24889 0x00000000
> c8469ec8 00000046 00000002 c8469eb4 c2c01d64 00000000 c8469e6c c8469e7c
> 508b0602 00013840 00000000 00000003 00000000 db18ac40 c0ad2d64 cd044680
> cd044908 c2c050c0 00000000 051c883d 00000046 cd044680 db18ac40 c8469eac
> Call Trace:
> [<c07946fe>] ? rwsem_down_failed_common+0x2e/0x190
> [<c0794775>] rwsem_down_failed_common+0xa5/0x190
> [<c079487d>] rwsem_down_write_failed+0x1d/0x30
> [<c07948fe>] call_rwsem_down_write_failed+0x6/0x8
> [<c0793f67>] ? down_write+0x47/0x50
> [<c029a082>] ? deactivate_super+0x42/0x60
> [<c029a082>] deactivate_super+0x42/0x60
> [<c02ae1b8>] mntput_no_expire+0x98/0xc0
> [<c02ae49f>] sys_umount+0x4f/0x2e0
> [<c02ae749>] sys_oldumount+0x19/0x20
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> INFO: task sync:21224 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sync D e527dec8 0 21224 21221 0x00000000
> e527dedc 00000046 00000002 e527dec8 c2c01d64 00000000 c0224f96 00000000
> c14dbaa0 0001379f c2e050d0 0001379f c14dd6fc c2e05118 c0ad2d64 f61f3680
> f61f3908 c2c050c0 00000000 0519e6c9 00000000 00000001 00000001 00000000
> Call Trace:
> [<c0224f96>] ? select_task_rq_fair+0x46/0x7e0
> [<c02b31b8>] bdi_sched_wait+0x8/0x10
> [<c07931e7>] __wait_on_bit+0x47/0x70
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c07932b8>] out_of_line_wait_on_bit+0xa8/0xc0
> [<c02b31b0>] ? bdi_sched_wait+0x0/0x10
> [<c0245820>] ? wake_bit_function+0x0/0x60
> [<c02b3222>] sync_inodes_sb+0x62/0x130
> [<c02b7250>] __sync_filesystem+0x20/0x60
> [<c02b7375>] sync_filesystems+0xe5/0x120
> [<c02b73fb>] sys_sync+0x1b/0x40
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
> INFO: task umount:21522 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> umount D c8469eb4 0 21522 24889 0x00000000
> c8469ec8 00000046 00000002 c8469eb4 c2c01d64 00000000 c8469e6c c8469e7c
> 508b0602 00013840 00000000 00000003 00000000 db18ac40 c0ad2d64 cd044680
> cd044908 c2c050c0 00000000 051c883d 00000046 cd044680 db18ac40 c8469eac
> Call Trace:
> [<c07946fe>] ? rwsem_down_failed_common+0x2e/0x190
> [<c0794775>] rwsem_down_failed_common+0xa5/0x190
> [<c079487d>] rwsem_down_write_failed+0x1d/0x30
> [<c07948fe>] call_rwsem_down_write_failed+0x6/0x8
> [<c0793f67>] ? down_write+0x47/0x50
> [<c029a082>] ? deactivate_super+0x42/0x60
> [<c029a082>] deactivate_super+0x42/0x60
> [<c02ae1b8>] mntput_no_expire+0x98/0xc0
> [<c02ae49f>] sys_umount+0x4f/0x2e0
> [<c02ae749>] sys_oldumount+0x19/0x20
> [<c0202e50>] sysenter_do_call+0x12/0x31
> INFO: lockdep is turned off.
>
> Pavel
>

--
Jiri Kosina
SUSE Labs, Novell Inc.

2009-10-28 01:18:38

by Yong Zhang

[permalink] [raw]
Subject: Re: 2.6.32-rc5: surprise removal of USB mass storage, and whole system goes to hell

On Wed, Oct 28, 2009 at 5:19 AM, Pavel Machek <[email protected]> wrote:
>
> I did remove one harddrive w/o unmounting, and now the whole system
> becomes unusable :-(: (whole dmesg attached).
>
> Stuff like "sync" hangs, and I'll probably have to reboot soon.
>                                                                Pavel

This a known bug(Bug #14481).

Cc'ed Rafael

2009-10-28 09:55:35

by Jens Axboe

[permalink] [raw]
Subject: Re: 2.6.32-rc5: surprise removal of USB mass storage, and whole system goes to hell

On Wed, Oct 28 2009, Jiri Kosina wrote:
> On Tue, 27 Oct 2009, Pavel Machek wrote:
>
> > I did remove one harddrive w/o unmounting, and now the whole system
> > becomes unusable :-(: (whole dmesg attached).
> >
> > Stuff like "sync" hangs, and I'll probably have to reboot soon.
>
> From the traces it seems that it might be related to the new per-bdi
> writeback stuff ... adding Jens to CC.

It looks like the IO isn't being errored on the device side, or perhaps
it just got stuck. Pavel, if you can reproduce, please try with this
tracing patch. Apply it, and then do something ala:

# cd /sys/kernel/debug/tracing
# echo 0 events/enable
# echo 1 events/writeback/enable
# echo 0 > trace

then start the act of reproducing, and finally

# cat trace > /tmp/foo

and send the output of foo here. Thanks!

diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
index 9d5360c..2643a4f 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -25,7 +25,9 @@
#include <linux/blkdev.h>
#include <linux/backing-dev.h>
#include <linux/buffer_head.h>
+#include <linux/ftrace.h>
#include "internal.h"
+#include <trace/events/writeback.h>

#define inode_to_bdi(inode) ((inode)->i_mapping->backing_dev_info)

@@ -34,33 +36,6 @@
*/
int nr_pdflush_threads;

-/*
- * Passed into wb_writeback(), essentially a subset of writeback_control
- */
-struct wb_writeback_args {
- long nr_pages;
- struct super_block *sb;
- enum writeback_sync_modes sync_mode;
- int for_kupdate:1;
- int range_cyclic:1;
- int for_background:1;
-};
-
-/*
- * Work items for the bdi_writeback threads
- */
-struct bdi_work {
- struct list_head list; /* pending work list */
- struct rcu_head rcu_head; /* for RCU free/clear of work */
-
- unsigned long seen; /* threads that have seen this work */
- atomic_t pending; /* number of threads still to do work */
-
- struct wb_writeback_args args; /* writeback arguments */
-
- unsigned long state; /* flag bits, see WS_* */
-};
-
enum {
WS_USED_B = 0,
WS_ONSTACK_B,
@@ -135,6 +110,8 @@ static void wb_work_complete(struct bdi_work *work)

static void wb_clear_pending(struct bdi_writeback *wb, struct bdi_work *work)
{
+ trace_writeback_clear(work);
+
/*
* The caller has retrieved the work arguments from this work,
* drop our reference. If this is the last ref, delete and free it
@@ -170,12 +147,16 @@ static void bdi_queue_work(struct backing_dev_info *bdi, struct bdi_work *work)
* If the default thread isn't there, make sure we add it. When
* it gets created and wakes up, we'll run this work.
*/
- if (unlikely(list_empty_careful(&bdi->wb_list)))
+ if (unlikely(list_empty_careful(&bdi->wb_list))) {
+ trace_writeback_sched(work, "default");
wake_up_process(default_backing_dev_info.wb.task);
- else {
+ } else {
struct bdi_writeback *wb = &bdi->wb;
+ struct task_struct *task = wb->task;

- if (wb->task)
+ trace_writeback_sched(work, task ? "task" : "notask");
+
+ if (task)
wake_up_process(wb->task);
}
}
@@ -202,6 +183,7 @@ static void bdi_alloc_queue_work(struct backing_dev_info *bdi,
work = kmalloc(sizeof(*work), GFP_ATOMIC);
if (work) {
bdi_work_init(work, args);
+ trace_writeback_queue(args);
bdi_queue_work(bdi, work);
} else {
struct bdi_writeback *wb = &bdi->wb;
@@ -235,6 +217,7 @@ static void bdi_sync_writeback(struct backing_dev_info *bdi,
bdi_work_init(&work, &args);
work.state |= WS_ONSTACK;

+ trace_writeback_queue(&args);
bdi_queue_work(bdi, &work);
bdi_wait_on_work_clear(&work);
}
@@ -901,6 +884,8 @@ long wb_do_writeback(struct bdi_writeback *wb, int force_wait)
if (force_wait)
work->args.sync_mode = args.sync_mode = WB_SYNC_ALL;

+ trace_writeback_exec(work);
+
/*
* If this isn't a data integrity operation, just notify
* that we have seen this work and we are now starting it.
@@ -936,9 +921,13 @@ int bdi_writeback_task(struct bdi_writeback *wb)
unsigned long wait_jiffies = -1UL;
long pages_written;

+ trace_writeback_thread_start_stop(1);
+
while (!kthread_should_stop()) {
pages_written = wb_do_writeback(wb, 0);

+ trace_writeback_pages_written(pages_written);
+
if (pages_written)
last_active = jiffies;
else if (wait_jiffies != -1UL) {
@@ -959,6 +948,8 @@ int bdi_writeback_task(struct bdi_writeback *wb)
try_to_freeze();
}

+ trace_writeback_thread_start_stop(0);
+
return 0;
}

diff --git a/include/linux/writeback.h b/include/linux/writeback.h
index 66ebddc..b12a077 100644
--- a/include/linux/writeback.h
+++ b/include/linux/writeback.h
@@ -22,6 +22,33 @@ enum writeback_sync_modes {
};

/*
+ * Passed into wb_writeback(), essentially a subset of writeback_control
+ */
+struct wb_writeback_args {
+ long nr_pages;
+ struct super_block *sb;
+ enum writeback_sync_modes sync_mode;
+ int for_kupdate:1;
+ int range_cyclic:1;
+ int for_background:1;
+};
+
+/*
+ * Work items for the bdi_writeback threads
+ */
+struct bdi_work {
+ struct list_head list; /* pending work list */
+ struct rcu_head rcu_head; /* for RCU free/clear of work */
+
+ unsigned long seen; /* threads that have seen this work */
+ atomic_t pending; /* number of threads still to do work */
+
+ struct wb_writeback_args args; /* writeback arguments */
+
+ unsigned long state; /* flag bits, see WS_* */
+};
+
+/*
* A control structure which tells the writeback code what to do. These are
* always on the stack, and hence need no locking. They are always initialised
* in a manner such that unspecified fields are set to zero.
diff --git a/include/trace/events/writeback.h b/include/trace/events/writeback.h
new file mode 100644
index 0000000..0f951de
--- /dev/null
+++ b/include/trace/events/writeback.h
@@ -0,0 +1,147 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM writeback
+
+#if !defined(_TRACE_WRITEBACK_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_WRITEBACK_H
+
+#include <linux/backing-dev.h>
+#include <linux/writeback.h>
+
+TRACE_EVENT(writeback_queue,
+
+ TP_PROTO(struct wb_writeback_args *args),
+
+ TP_ARGS(args),
+
+ TP_STRUCT__entry(
+ __field(long, nr_pages)
+ __field(int, sb)
+ __field(int, sync_mode)
+ __field(int, for_kupdate)
+ __field(int, range_cyclic)
+ __field(int, for_background)
+ ),
+
+ TP_fast_assign(
+ __entry->nr_pages = args->nr_pages;
+ __entry->sb = !!args->sb;
+ __entry->for_kupdate = args->for_kupdate;
+ __entry->range_cyclic = args->range_cyclic;
+ __entry->for_background = args->for_background;
+ ),
+
+ TP_printk("pages=%ld, sb=%d, kupdate=%d, range_cyclic=%d "
+ "for_background=%d", __entry->nr_pages, __entry->sb,
+ __entry->for_kupdate, __entry->range_cyclic,
+ __entry->for_background)
+);
+
+TRACE_EVENT(writeback_sched,
+
+ TP_PROTO(struct bdi_work *work, const char *msg),
+
+ TP_ARGS(work, msg),
+
+ TP_STRUCT__entry(
+ __field(struct bdi_work *, work)
+ __array(char, task, 8)
+ ),
+
+ TP_fast_assign(
+ __entry->work = work;
+ snprintf(__entry->task, 8, "%s", msg);
+ ),
+
+ TP_printk("work=%p, task=%s", __entry->work, __entry->task)
+);
+
+TRACE_EVENT(writeback_exec,
+
+ TP_PROTO(struct bdi_work *work),
+
+ TP_ARGS(work),
+
+ TP_STRUCT__entry(
+ __field(struct bdi_work *, work)
+ __field(long, nr_pages)
+ __field(int, sb)
+ __field(int, sync_mode)
+ __field(int, for_kupdate)
+ __field(int, range_cyclic)
+ __field(int, for_background)
+ ),
+
+ TP_fast_assign(
+ __entry->work = work;
+ __entry->nr_pages = work->args.nr_pages;
+ __entry->sb = !!work->args.sb;
+ __entry->for_kupdate = work->args.for_kupdate;
+ __entry->range_cyclic = work->args.range_cyclic;
+ __entry->for_background = work->args.for_background;
+
+ ),
+
+ TP_printk("work=%p pages=%ld, sb=%d, kupdate=%d, range_cyclic=%d"
+ " for_background=%d", __entry->work,
+ __entry->nr_pages, __entry->sb, __entry->for_kupdate,
+ __entry->range_cyclic, __entry->for_background)
+);
+
+TRACE_EVENT(writeback_clear,
+
+ TP_PROTO(struct bdi_work *work),
+
+ TP_ARGS(work),
+
+ TP_STRUCT__entry(
+ __field(struct bdi_work *, work)
+ __field(int, refs)
+ ),
+
+ TP_fast_assign(
+ __entry->work = work;
+ __entry->refs = atomic_read(&work->pending);
+ ),
+
+ TP_printk("work=%p, refs=%d", __entry->work, __entry->refs)
+);
+
+TRACE_EVENT(writeback_pages_written,
+
+ TP_PROTO(long pages_written),
+
+ TP_ARGS(pages_written),
+
+ TP_STRUCT__entry(
+ __field(long, pages)
+ ),
+
+ TP_fast_assign(
+ __entry->pages = pages_written;
+ ),
+
+ TP_printk("%ld", __entry->pages)
+);
+
+
+TRACE_EVENT(writeback_thread_start_stop,
+
+ TP_PROTO(int start),
+
+ TP_ARGS(start),
+
+ TP_STRUCT__entry(
+ __field(int, start)
+ ),
+
+ TP_fast_assign(
+ __entry->start = start;
+ ),
+
+ TP_printk("%s", __entry->start ? "started" : "exited")
+);
+
+#endif /* _TRACE_WRITEBACK_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/mm/backing-dev.c b/mm/backing-dev.c
index 5a37e20..b951e0a 100644
--- a/mm/backing-dev.c
+++ b/mm/backing-dev.c
@@ -11,6 +11,9 @@
#include <linux/writeback.h>
#include <linux/device.h>

+#define CREATE_TRACE_POINTS
+#include <trace/events/writeback.h>
+
void default_unplug_io_fn(struct backing_dev_info *bdi, struct page *page)
{
}

--
Jens Axboe

2009-10-28 14:07:29

by Jens Axboe

[permalink] [raw]
Subject: Re: 2.6.32-rc5: surprise removal of USB mass storage, and whole system goes to hell

On Wed, Oct 28 2009, Jens Axboe wrote:
> On Wed, Oct 28 2009, Jiri Kosina wrote:
> > On Tue, 27 Oct 2009, Pavel Machek wrote:
> >
> > > I did remove one harddrive w/o unmounting, and now the whole system
> > > becomes unusable :-(: (whole dmesg attached).
> > >
> > > Stuff like "sync" hangs, and I'll probably have to reboot soon.
> >
> > From the traces it seems that it might be related to the new per-bdi
> > writeback stuff ... adding Jens to CC.
>
> It looks like the IO isn't being errored on the device side, or perhaps
> it just got stuck. Pavel, if you can reproduce, please try with this
> tracing patch. Apply it, and then do something ala:
>
> # cd /sys/kernel/debug/tracing
> # echo 0 events/enable
> # echo 1 events/writeback/enable
> # echo 0 > trace
>
> then start the act of reproducing, and finally
>
> # cat trace > /tmp/foo
>
> and send the output of foo here. Thanks!

I can reproduce this. The writeback work gets queued, we notice the task
isn't there and wake up the default task. And then nothing happens, I
wonder if the bdi is gone.

I'll fiddle around with this.

--
Jens Axboe

2009-10-29 08:38:17

by Jens Axboe

[permalink] [raw]
Subject: Re: 2.6.32-rc5: surprise removal of USB mass storage, and whole system goes to hell

On Wed, Oct 28 2009, Jens Axboe wrote:
> On Wed, Oct 28 2009, Jens Axboe wrote:
> > On Wed, Oct 28 2009, Jiri Kosina wrote:
> > > On Tue, 27 Oct 2009, Pavel Machek wrote:
> > >
> > > > I did remove one harddrive w/o unmounting, and now the whole system
> > > > becomes unusable :-(: (whole dmesg attached).
> > > >
> > > > Stuff like "sync" hangs, and I'll probably have to reboot soon.
> > >
> > > From the traces it seems that it might be related to the new per-bdi
> > > writeback stuff ... adding Jens to CC.
> >
> > It looks like the IO isn't being errored on the device side, or perhaps
> > it just got stuck. Pavel, if you can reproduce, please try with this
> > tracing patch. Apply it, and then do something ala:
> >
> > # cd /sys/kernel/debug/tracing
> > # echo 0 events/enable
> > # echo 1 events/writeback/enable
> > # echo 0 > trace
> >
> > then start the act of reproducing, and finally
> >
> > # cat trace > /tmp/foo
> >
> > and send the output of foo here. Thanks!
>
> I can reproduce this. The writeback work gets queued, we notice the task
> isn't there and wake up the default task. And then nothing happens, I
> wonder if the bdi is gone.
>
> I'll fiddle around with this.

Problem is, we cannot control if the bdi disappears all of a sudden.
This happens when the device is yanked. This bug got introduced with the
addition of the sb s_bdi cache pointer, it would now point to a bdi that
was gone (and memory had been freed).

Pavel, can you try this?

diff --git a/mm/backing-dev.c b/mm/backing-dev.c
index 4f53a6d..756c31b 100644
--- a/mm/backing-dev.c
+++ b/mm/backing-dev.c
@@ -614,6 +616,18 @@ static void bdi_wb_shutdown(struct backing_dev_info *bdi)
kthread_stop(wb->task);
}

+static void bdi_prune_sb(struct backing_dev_info *bdi)
+{
+ struct super_block *sb;
+
+ spin_lock(&sb_lock);
+ list_for_each_entry(sb, &super_blocks, s_list) {
+ if (sb->s_bdi == bdi)
+ sb->s_bdi = NULL;
+ }
+ spin_unlock(&sb_lock);
+}
+
void bdi_unregister(struct backing_dev_info *bdi)
{
if (bdi->dev) {
@@ -624,6 +638,8 @@ void bdi_unregister(struct backing_dev_info *bdi)
device_unregister(bdi->dev);
bdi->dev = NULL;
}
+
+ bdi_prune_sb(bdi);
}
EXPORT_SYMBOL(bdi_unregister);


--
Jens Axboe

2009-11-15 09:46:30

by Heinz Diehl

[permalink] [raw]
Subject: Re: 2.6.32-rc5: surprise removal of USB mass storage, and whole system goes to hell

On 29.10.2009, Jens Axboe wrote:

I had the same problem which has been discussed in this thread,
and can confirm that this patch from Jens Axboe (which is already merged into 2.6.32-rc7)
fixes it for me.

> diff --git a/mm/backing-dev.c b/mm/backing-dev.c
> index 4f53a6d..756c31b 100644
> --- a/mm/backing-dev.c
> +++ b/mm/backing-dev.c
> @@ -614,6 +616,18 @@ static void bdi_wb_shutdown(struct backing_dev_info *bdi)
> kthread_stop(wb->task);
> }
>
> +static void bdi_prune_sb(struct backing_dev_info *bdi)
> +{
> + struct super_block *sb;
> +
> + spin_lock(&sb_lock);
> + list_for_each_entry(sb, &super_blocks, s_list) {
> + if (sb->s_bdi == bdi)
> + sb->s_bdi = NULL;
> + }
> + spin_unlock(&sb_lock);
> +}
> +
> void bdi_unregister(struct backing_dev_info *bdi)
> {
> if (bdi->dev) {
> @@ -624,6 +638,8 @@ void bdi_unregister(struct backing_dev_info *bdi)
> device_unregister(bdi->dev);
> bdi->dev = NULL;
> }
> +
> + bdi_prune_sb(bdi);
> }
> EXPORT_SYMBOL(bdi_unregister);