lkml.org 
[lkml]   [2010]   [May]   [7]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    Subjectlibata, hddtemp + s2ram is racy
    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)


    \
     
     \ /
      Last update: 2010-05-07 23:11    [W:3.030 / U:0.448 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site