Re: INFO: task umount:1524 blocked for more than 120 seconds

From: Justin P. Mattock
Date: Mon May 10 2010 - 19:40:57 EST

Next message: Greg KH: "[031/117] ocfs2: Update VFS inodes id info after reflink."
Previous message: Greg KH: "[035/117] powernow-k8: Fix frequency reporting"
In reply to: Stefan Richter: "Re: INFO: task umount:1524 blocked for more than 120 seconds"
Next in thread: Jan Kara: "Re: INFO: task umount:1524 blocked for more than 120 seconds"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On 05/10/2010 04:04 PM, Stefan Richter wrote:

Justin P. Mattock wrote:
On 05/10/2010 02:46 PM, Justin Mattock wrote:
I have a reproduceable problem happening over here
with unmount and ext4
if I sudo cp -R xserver(all libs/apps from git)
to an external
SmartDsk FireLite
then after the cp is done
sudo umount /dev/sdb1

I get this:

type=1400 audit(1273526248.814:27): avc: denied { unmount } for
pid=1524 comm="umount" scontext=justin:staff_r:staff_sudo_t:s0
tcontext=system_u:object_r:fs_t:s0 tclass=filesystem
[ 360.669140] INFO: task umount:1524 blocked for more than 120 seconds.
[ 360.685771] "echo 0> /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 360.702221] umount D 0000000000000000 0 1524 1472
0x00000080
[ 360.702227] ffff880080909c88 0000000000000086 ffff880080909da8
0000000000000000
[ 360.702233] ffff880080909fd8 ffff88013845c4a0 0000000000013fc0
ffff880080909fd8
[ 360.702238] 0000000000013fc0 0000000000013fc0 0000000000013fc0
0000000000013fc0
[ 360.702243] Call Trace:
[ 360.702252] [<ffffffff8106e3f4>] ? spin_unlock_irqrestore+0x9/0xb
[ 360.702266] [<ffffffff810fb214>] ? bdi_sched_wait+0x0/0xd
[ 360.702270] [<ffffffff810fb21d>] bdi_sched_wait+0x9/0xd
[ 360.702276] [<ffffffff813e2126>] __wait_on_bit+0x43/0x76
[ 360.702342] [<ffffffff813e21c2>] out_of_line_wait_on_bit+0x69/0x74
[ 360.702346] [<ffffffff810fb214>] ? bdi_sched_wait+0x0/0xd
[ 360.702350] [<ffffffff8106e3bd>] ? wake_bit_function+0x0/0x2e
[ 360.702356] [<ffffffff81051599>] ? wake_up_process+0x10/0x12
[ 360.702360] [<ffffffff810fc00b>] T.732+0x19/0x1b
[ 360.702364] [<ffffffff810fc06c>] bdi_sync_writeback+0x5f/0x66
[ 360.702368] [<ffffffff810fc090>] sync_inodes_sb+0x1d/0xde
[ 360.702373] [<ffffffff810ff04b>] __sync_filesystem+0x47/0x7e
[ 360.702377] [<ffffffff810ff229>] sync_filesystem+0x47/0x4b
[ 360.702382] [<ffffffff810e2df4>] generic_shutdown_super+0x22/0xf4
[ 360.702386] [<ffffffff810e2ee8>] kill_block_super+0x22/0x3a
[ 360.702390] [<ffffffff810e35f4>] deactivate_super+0x4c/0x64
[ 360.702394] [<ffffffff810f6221>] mntput_no_expire+0xb0/0xde
[ 360.702397] [<ffffffff810f679a>] sys_umount+0x2d9/0x304
[ 360.702402] [<ffffffff810e899e>] ? path_put+0x1d/0x21
[ 360.702408] [<ffffffff81024502>] system_call_fastpath+0x16/0x1b
[ 400.536564] ieee1394: Node changed: 0-01:1023 -> 0-00:1023
[ 400.536587] ieee1394: Node paused: ID:BUS[0-00:1023] GUID[00d0010d0001eaa9]
[ 403.551124] ieee1394: Node removed: ID:BUS[0-00:1023] GUID[00d0010d0001eaa9]
[ 403.551263] end_request: I/O error, dev sdb, sector 54795503
[ 403.564505] Aborting journal on device sdb1-8.
[ 403.577816] JBD2: I/O error detected when updating journal superblock for sdb1-8.
[ 403.591168] journal commit I/O error

disk just sits there with the light on.

if I disconnect, then re execute mount,cp,umount
I can get this again:

[...]

maybe this is cable related i.g.
using a firewire cable from the apple
store($40big ones),on an imac gives this
message., but if I use the
cable from the firewire(slighty thicker), on
a macbook, I can do the above mount,cp,unmount
with the kernel, and hit nothing.

It is strange then that you don't get any I/O error messages from sbp2
or from scsi. Or do you?

the above happens when I umount /dev/sdb1
seems to only happen on my imac9,1,with large files
i.g. umounting after transferring small packages
works o.k.

Was the "Node paused" message in the log above from when you actually
unplugged or switched off the disk, or didn't do you anything to it at
that moment?

this happens after I umount(but I'll double check
to make sure).

(both xserver
and all its libs etc.. and the kernel both seem to
be pretty large to transfer).

Depends on how much RAM you have. Could be that there isn't a lot of IO
going on until umount.

Perhaps there is a bug in the disk's IDE-to-FireWire bridge that went
unnoticed with older kernels but is now exhibited due to different
kernel behaviour (writeback related changes, larger requests...).
Several SmartDisk products have an old Symbios chip that require
requests limited to 128 kB each. When sbp2 logs in to the device, does
it print a "Workarounds for node "... message? If yes, do the
workaround flags contain 0x1?

yes, after echoing..

If not, run "echo 1> /sys/module/sbp2/parameters/workarounds" before
you plug in the disk. *If* this fixes the issue, we should add the
device IDs to sbp2's and firewire-sbp2's hardcoded quirks lists.

here is what dmesg shows after doing the echo call to workarounds
(before doing so the workarounds is not present)
this is plugging, and un-plugging the device a few times:

[ 806.109104] ieee1394: Error parsing configrom for node 0-00:1023
[ 806.109259] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[ 809.877527] ieee1394: Node added: ID:BUS[0-00:1023] GUID[00d0010d0001eaa9]
[ 809.879303] scsi9 : SBP-2 IEEE-1394
[ 809.879459] ieee1394: sbp2: Workarounds for node 0-00:1023: 0x1 (firmware_revision 0x000470, vendor_id 0x00d001, model_id 0x000000)
[ 810.881090] ieee1394: sbp2: Logged into SBP-2 device
[ 810.881181] ieee1394: sbp2: Node 0-00:1023: Max speed [S400] - Max payload [2048]
[ 810.882537] scsi 9:0:0:0: Direct-Access SmartDsk FireLite 4.70 PQ: 0 ANSI: 0
[ 810.882958] sd 9:0:0:0: Attached scsi generic sg2 type 0
[ 810.885443] sd 9:0:0:0: [sdb] 117210240 512-byte logical blocks: (60.0 GB/55.8 GiB)
[ 810.886699] sd 9:0:0:0: [sdb] Write Protect is off
[ 810.886703] sd 9:0:0:0: [sdb] Mode Sense: 86 0b 00 02
[ 810.888146] sd 9:0:0:0: [sdb] Missing header in MODE_SENSE response
[ 810.889415] sd 9:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 810.893453] sd 9:0:0:0: [sdb] Missing header in MODE_SENSE response
[ 810.894696] sdb: sdb1
[ 810.972390] sd 9:0:0:0: [sdb] Missing header in MODE_SENSE response
[ 810.973927] sd 9:0:0:0: [sdb] Attached SCSI disk
[ 834.638222] ieee1394: Node changed: 0-01:1023 -> 0-00:1023
[ 834.638241] ieee1394: Node paused: ID:BUS[0-00:1023] GUID[00d0010d0001eaa9]
[ 837.653064] ieee1394: Node removed: ID:BUS[0-00:1023] GUID[00d0010d0001eaa9]
[ 837.656224] sd 9:0:0:0: [sdb] Synchronizing SCSI cache
[ 837.656278] sd 9:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
[ 837.656281] sd 9:0:0:0: [sdb] Stopping disk
[ 837.656292] sd 9:0:0:0: [sdb] START_STOP FAILED
[ 837.656294] sd 9:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
[ 840.493108] ieee1394: Error parsing configrom for node 0-00:1023
[ 840.493268] ieee1394: Node changed: 0-00:1023 -> 0-01:1023
[ 844.261523] ieee1394: Node added: ID:BUS[0-00:1023] GUID[00d0010d0001eaa9]
[ 844.261962] scsi10 : SBP-2 IEEE-1394
[ 844.262126] ieee1394: sbp2: Workarounds for node 0-00:1023: 0x1 (firmware_revision 0x000470, vendor_id 0x00d001, model_id 0x000000)
[ 845.264030] ieee1394: sbp2: Logged into SBP-2 device
[ 845.264108] ieee1394: sbp2: Node 0-00:1023: Max speed [S400] - Max payload [2048]
[ 845.265477] scsi 10:0:0:0: Direct-Access SmartDsk FireLite 4.70 PQ: 0 ANSI: 0
[ 845.265906] sd 10:0:0:0: Attached scsi generic sg2 type 0
[ 845.267651] sd 10:0:0:0: [sdb] 117210240 512-byte logical blocks: (60.0 GB/55.8 GiB)
[ 845.268925] sd 10:0:0:0: [sdb] Write Protect is off
[ 845.268929] sd 10:0:0:0: [sdb] Mode Sense: 86 0b 00 02
[ 845.270196] sd 10:0:0:0: [sdb] Missing header in MODE_SENSE response
[ 845.271406] sd 10:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 845.275385] sd 10:0:0:0: [sdb] Missing header in MODE_SENSE response
[ 845.276686] sdb: sdb1
[ 845.350665] sd 10:0:0:0: [sdb] Missing header in MODE_SENSE response
[ 845.351927] sd 10:0:0:0: [sdb] Attached SCSI disk

(By the way, ieee1394/ ohci1394/ sbp2 are kind of end-of-life products;
firewire-core/ firewire-ohci/ firewire-sbp2 are more actively
maintained. OTOH there shouldn't be regressions in the 1394 stack.)

I'll remove ieee1394.ko and use firewire to see if I hit this

Justin P. Mattock

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Greg KH: "[031/117] ocfs2: Update VFS inodes id info after reflink."
Previous message: Greg KH: "[035/117] powernow-k8: Fix frequency reporting"
In reply to: Stefan Richter: "Re: INFO: task umount:1524 blocked for more than 120 seconds"
Next in thread: Jan Kara: "Re: INFO: task umount:1524 blocked for more than 120 seconds"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]