[cc linux-scsi]

quoted text
> Hi,
> 
> On a SMP system I've hit a race condition between suspend and hddtemp
> checking disk's temperature.
> 
> System details:
> - Dual-core AMD Turion CPU
> - 00:12.0 SATA controller [0106]: ATI Technologies Inc SB600 Non-Raid-5 SATA [1002:4380]
> - hddtemp-0.3_beta15 (Gentoo package app-admin/hddtemp-0.3_beta15-r3)
> - Linus' tree shortly after v2.6.34-rc6, at commit
>   be1066bbcd443a65df312fdecea7e4959adedb45 with some drm updates on
>   top of it.
> 
> 
> It looked like hddtemp had sent the SMART request to disk right before
> suspend and during suspend process ata2 did complain without aborting
> suspend (see below).
> After resume access to that disk was dead-locked (any further
> attempt to suspend timed-out freezing hddtemp and any access attempt
> towards that disk did put userspace tasks in uninterruptible state and
> caused soft-raid to mark the disk failed).
> 
> Is suspend not waiting on SG_IO ioctls to complete (at ata host level)?
> 
> To get best luck in reproducing it something like the following is probably
> needed:
>                    sync
>   ioctl(SG_IO)      //      echo mem > /sys/power/state
> 
> Thanks,
> Bruno
> 
> 
> 
> 
> Kernel log extract relating to this issue:
> ... boot, zero or more s2ram, start suspend
> [  142.241048] ahci 0000:00:12.0: suspend
> [  142.660041] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [  147.660046] ata2.00: qc timeout (cmd 0xec)
> [  147.664449] ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
> [  147.670978] ata2.00: revalidation failed (errno=-5)
> [  148.022541] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [  158.022520] ata2.00: qc timeout (cmd 0xec)
> [  158.026923] ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
> [  158.033467] ata2.00: revalidation failed (errno=-5)
> [  158.038695] ata2: limiting SATA link speed to 1.5 Gbps
> [  158.390042] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
> [  188.390023] ata2.00: qc timeout (cmd 0xec)
> [  188.394426] ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
> [  188.400953] ata2.00: revalidation failed (errno=-5)
> [  188.406170] ata2.00: disabled
> [  188.420366] ahci 0000:00:12.0: PCI INT A disabled
> ... resuming
> [  200.672629] sd 1:0:0:0: [sdb] Unhandled error code
> [  200.672632] sd 1:0:0:0: [sdb] Result: hostbyte=0x04 driverbyte=0x00
> [  200.672635] sd 1:0:0:0: [sdb] CDB: cdb[0]=0x2a: 2a 00 00 81 8f c1 00 00 08 00
> [  200.672641] end_request: I/O error, dev sdb, sector 8490945
> [  200.672646] end_request: I/O error, dev sdb, sector 8490945
> [  200.672649] md: super_written gets error=-5, uptodate=0
> [  200.672653] raid1: Disk failure on sdb3, disabling device.
> [  200.672654] raid1: Operation continuing on 1 devices.
> ... finish resuming, start next suspend
> [  249.291920] sd 2:0:0:0: legacy suspend
> [  249.291924] sd 2:0:0:0: [sdc] Synchronizing SCSI cache
> [  249.292076] sd 2:0:0:0: [sdc] Stopping disk
> [  250.316996] scsi target2:0:0: legacy suspend
> [  250.324040] sd 1:0:0:0: legacy suspend
> [  250.330415] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
> [  250.338435] sd 1:0:0:0: [sdb] Result: hostbyte=0x04 driverbyte=0x00
> [  250.347830] legacy_suspend(): scsi_bus_suspend+0x0/0x70 returns -5
> [  250.357082] PM: Device 1:0:0:0 failed to suspend: error -5
> [  250.365534] PM: Some devices failed to suspend
> [  250.372901] scsi target2:0:0: legacy resume
> [  250.379835] sd 2:0:0:0: legacy resume
> [  250.386081] sd 2:0:0:0: [sdc] Starting disk
> ... resume from aborted suspend
> ... for each subsequent suspend attempt:
> [  333.626278] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze):
> [  333.637718] hddtemp       D 0000000000000000     0  1889      1 0x00800004
> [  333.648048]  ffff88007abe3908 0000000000000082 ffff88007abe3fd8 ffff88007cec4820
> [  333.658986]  ffff88007abe3fd8 ffff88007abe3fd8 00000000000129c0 00000000000129c0
> [  333.669921]  ffff88007cec4820 ffff88007cda2820 00000000ffffeda8 0000000000000002
> [  333.680901] Call Trace:
> [  333.685892]  [<ffffffff8146c65d>] schedule_timeout+0x19d/0x230
> [  333.694938]  [<ffffffff8146bc31>] wait_for_common+0xe1/0x170
> [  333.703779]  [<ffffffff81037820>] ? default_wake_function+0x0/0x10
> [  333.713234]  [<ffffffff811add9d>] ? __generic_unplug_device+0x2d/0x40
> [  333.723069]  [<ffffffff8146bd58>] wait_for_completion+0x18/0x20
> [  333.732255]  [<ffffffff811b3597>] blk_execute_rq+0x67/0xb0
> [  333.740800]  [<ffffffff811aecd0>] ? freed_request+0x30/0x60
> [  333.749487]  [<ffffffff810485ed>] ? capable+0x2d/0x60
> [  333.757471]  [<ffffffff811b6f85>] sg_io+0x1c5/0x3e0
> [  333.764566]  [<ffffffff810c6340>] ? pollwake+0x0/0x60
> [  333.771808]  [<ffffffff811b77cf>] scsi_cmd_ioctl+0x27f/0x450
> [  333.779715]  [<ffffffff813e0080>] ? ip_output+0xa0/0xb0
> [  333.787134]  [<ffffffff813dee30>] ? ip_local_out+0x20/0x30
> [  333.794936]  [<ffffffff81322d0a>] sd_ioctl+0x8a/0xd0
> [  333.802134]  [<ffffffff811b4ac2>] __blkdev_driver_ioctl+0xa2/0xc0
> [  333.810568]  [<ffffffff811b4cf2>] blkdev_ioctl+0x202/0xa00
> [  333.818296]  [<ffffffff8146e040>] ? _raw_spin_unlock_bh+0x10/0x20
> [  333.826714]  [<ffffffff81398a48>] ? release_sock+0xb8/0xd0
> [  333.834461]  [<ffffffff8146e0c1>] ? _raw_spin_lock_bh+0x11/0x40
> [  333.842807]  [<ffffffff81398b15>] ? lock_sock_nested+0xb5/0xd0
> [  333.851003]  [<ffffffff8146e040>] ? _raw_spin_unlock_bh+0x10/0x20
> [  333.859534]  [<ffffffff81398a48>] ? release_sock+0xb8/0xd0
> [  333.867379]  [<ffffffff810e0b45>] block_ioctl+0x35/0x40
> [  333.874943]  [<ffffffff810c4605>] vfs_ioctl+0x35/0xd0
> [  333.882238]  [<ffffffff810c4b03>] do_vfs_ioctl+0x3d3/0x560
> [  333.889997]  [<ffffffff810c4cda>] sys_ioctl+0x4a/0x80
> [  333.897321]  [<ffffffff81002d6b>] system_call_fastpath+0x16/0x1b
> 
> 
> 
> Strace of hddtemp querying a disk:
> ...
> open("/dev/sda", O_RDONLY|O_NONBLOCK)   = 3
> ioctl(3, SCSI_IOCTL_GET_BUS_NUMBER, 0x7fff11f034fc) = 0
> ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[6]=[12, 00, 00, 00, 24, 00], mx_sb_len=0, iovec_count=0, dxfer_len=36, timeout=3000, flags=0, data[36]=["__PLACEHOLDER__0___PLACEHOLDER__0_[__PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0_ATA     FUJITSU MHW2160B"...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=0, duration=0, info=0}) = 0
> ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[16]=[85, 08, 2e, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, ec, 00], mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=3000, flags=0, data[512]=["Z7?70__PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0_?__PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0_        1K20"...], status=02, masked_status=01, sb[22]=[72, 00, 00, 00, 00, 00, 00, 0e, 09, 0c, 00, 00, 00, 00, 00, 09, 00, 27, 00, 64, 40, 40], host_status=0, driver_status=0x8, resid=0, duration=0, info=0x1}) = 0
> ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[16]=[85, 08, 2e, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, ec, 00], mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=3000, flags=0, data[512]=["Z7?70__PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0_?__PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0_        1K20"...], status=02, masked_status=01, sb[22]=[72, 00, 00, 00, 00, 00, 00, 0e, 09, 0c, 00, 00, 00, 00, 00, 09, 00, 27, 00, 64, 40, 40], host_status=0, driver_status=0x8, resid=0, duration=0, info=0x1}) = 0
> ... (checking its disk DB)
> ioctl(3, SG_IO, {'S', SG_DXFER_NONE, cmd[16]=[85, 06, 20, 00, d8, 00, 00, 00, 00, 00, 4f, 00, c2, 00, b0, 00], mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=3000, flags=0, status=02, masked_status=01, sb[22]=[72, 00, 00, 00, 00, 00, 00, 0e, 09, 0c, 00, 00, 00, 00, 00, 00, 00, 4f, 00, c2, 00, 50], host_status=0, driver_status=0x8, resid=0, duration=0, info=0x1}) = 0
> ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[16]=[85, 08, 2e, 00, d0, 00, 01, 00, 00, 00, 4f, 00, c2, 00, b0, 00], mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=3000, flags=0, data[512]=["__PLACEHOLDER__0___PLACEHOLDER__0_dd>__PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0_dd__PLACEHOLDER__0___PLACEHOLDER__0_P__PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0___PLACEHOLDER__0_dd"...], status=02, masked_status=01, sb[22]=[72, 00, 00, 00, 00, 00, 00, 0e, 09, 0c, 00, 00, 00, 00, 00, 00, 00, 4f, 00, c2, 00, 50], host_status=0, driver_status=0x8, resid=0, duration=120, info=0x1}) = 0
> ... (printing result)
--
unsubscribe notice
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/