[cc linux-scsi] > 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]=["\0\0\5\2[\0\0\0ATA 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]=["Z\4\377?7\310\20\0\0\0\0\0?\0\0\0\0\0\0\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]=["Z\4\377?7\310\20\0\0\0\0\0?\0\0\0\0\0\0\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]=["\20\0\1\17\0dd>\3\1\0\0\0\0\2\5\0dd\0\0P\2\0\0\0\3\3\0dd\1"...], 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) -- To unsubscribe from this list: send the line "unsubscribe linux-ide" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html