Re: [PATCH v8 04/23] scsi: sd: Differentiate system and runtime start/stop management

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Damien Le Moal <dlemoal@xxxxxxxxxx> writes:

> On my system, I see:
>
> cat /sys/class/ata_port/ata1/power/runtime_active_kids
> 0

I see a 1 there, which is the single scsi_host.  The scsi_host has 2
active kids; the two disks.  When I enabled runtime pm, only when the
second disk was suspended did that allow the scsi_host to suspend, which
then allowed the port to suspend.  Everything looked fine there so far.
Then I tried:

echo 1 > /sys/block/sdf/device/delete

And the SCSI EH appears to have tried to wake up the disk, and hung in
the process.

[  314.246282] sd 7:0:0:0: [sde] Synchronizing SCSI cache
[  314.246445] sd 7:0:0:0: [sde] Stopping disk

First disk suspends.

[  388.518295] sd 7:1:0:0: [sdf] Synchronizing SCSI cache
[  388.518519] sd 7:1:0:0: [sdf] Stopping disk

Second disk suspends some time later.

[  388.930428] ata8.00: Entering standby power mode
[  389.330651] ata8.01: Entering standby power mode

That allowed the port to suspend.  This is when I tried to detach the
disk driver, which I think tried to resume the disk before detaching,
which resumed the port.

[  467.511878] ata8.15: SATA link down (SStatus 0 SControl 310)
[  468.142726] ata8.15: failed to read PMP GSCR[0] (Emask=0x100)
[  468.142741] ata8.15: PMP revalidation failed (errno=-5)

I ran hdparm -C on the other disk at this point.  I just noticed that
the ata8.15 that represents the PMP itself was NOT suspended along with
the two drive links, and then maybe was not resumed before trying to
revalidate the PMP?  And that's why it failed?

[  473.172792] ata8.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[  473.486860] ata8.00: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[  473.802139] ata8.01: SATA link up 1.5 Gbps (SStatus 113 SControl 310)

It seems like it ended up recovering here though?  And yet the scsi_eh
remained hung, as did the hdparm -C:

[  605.566814] INFO: task scsi_eh_7:173 blocked for more than 120 seconds.
[  605.566829]       Not tainted 6.6.0-rc5+ #5
[  605.566834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  605.566838] task:scsi_eh_7       state:D stack:0     pid:173   ppid:2      flags:0x00004000
[  605.566850] Call Trace:
[  605.566853]  <TASK>
[  605.566860]  __schedule+0x37c/0xb70
[  605.566878]  schedule+0x61/0xd0
[  605.566888]  rpm_resume+0x156/0x760
[  605.566896]  ? sched_energy_aware_handler+0xb0/0xb0
[  605.566907]  rpm_resume+0x255/0x760
[  605.566915]  rpm_resume+0x255/0x760
[  605.566923]  rpm_resume+0x255/0x760
[  605.566931]  __pm_runtime_resume+0x4e/0x80
[  605.566941]  ata_eh_recover+0x695/0x1060 [libata]
[  605.567001]  ? ata_port_pm_suspend+0x50/0x50 [libata]
[  605.567048]  ? ahci_do_softreset+0x2d0/0x2d0 [libahci]
[  605.567067]  ? ata_host_release+0x80/0x80 [libata]
[  605.567108]  ? ata_port_runtime_idle+0x110/0x110 [libata]
[  605.567151]  ? sata_pmp_configure+0x72/0x210 [libata]
[  605.567204]  sata_pmp_error_handler+0x357/0xac0 [libata]
[  605.567249]  ? ata_port_pm_suspend+0x50/0x50 [libata]
[  605.567291]  ? ahci_stop_engine+0xe0/0xe0 [libahci]
[  605.567309]  ? ahci_do_hardreset+0x140/0x140 [libahci]
[  605.567325]  ? ahci_do_softreset+0x2d0/0x2d0 [libahci]
[  605.567344]  ? _raw_spin_unlock_irqrestore+0x27/0x40
[  605.567355]  ahci_error_handler+0x36/0x60 [libahci]
[  605.567373]  ata_scsi_port_error_handler+0x3de/0x8a0 [libata]
[  605.567424]  ? scsi_eh_get_sense+0x250/0x250 [scsi_mod]
[  605.567464]  ata_scsi_error+0x95/0xc0 [libata]
[  605.567511]  scsi_error_handler+0xb9/0x580 [scsi_mod]
[  605.567547]  ? preempt_count_add+0x6c/0xa0
[  605.567556]  ? scsi_eh_get_sense+0x250/0x250 [scsi_mod]
[  605.567587]  kthread+0xf2/0x120
[  605.567594]  ? kthread_complete_and_exit+0x20/0x20
[  605.567602]  ret_from_fork+0x31/0x50
[  605.567611]  ? kthread_complete_and_exit+0x20/0x20
[  605.567617]  ret_from_fork_asm+0x11/0x20
[  605.567630]  </TASK>
[  605.567663] INFO: task bash:1305 blocked for more than 120 seconds.
[  605.567670]       Not tainted 6.6.0-rc5+ #5
[  605.567675] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  605.567678] task:bash            state:D stack:0     pid:1305  ppid:1300   flags:0x00004004
[  605.567687] Call Trace:
[  605.567689]  <TASK>
[  605.567693]  __schedule+0x37c/0xb70
[  605.567703]  ? try_to_wake_up+0xb2/0x5e0
[  605.567715]  schedule+0x61/0xd0
[  605.567725]  ata_port_wait_eh+0x7c/0xf0 [libata]
[  605.567776]  ? sched_energy_aware_handler+0xb0/0xb0
[  605.567784]  ? ata_sas_port_resume+0x30/0x30 [libata]
[  605.567829]  ata_port_runtime_resume+0x27/0x30 [libata]
[  605.567870]  __rpm_callback+0x41/0x110
[  605.567879]  ? ata_sas_port_resume+0x30/0x30 [libata]
[  605.567917]  rpm_callback+0x35/0x70
[  605.567925]  rpm_resume+0x513/0x760
[  605.567931]  ? _raw_read_lock_irqsave+0x28/0x50
[  605.567938]  ? _raw_read_unlock_irqrestore+0x2a/0x40
[  605.567944]  ? ep_poll_callback+0x269/0x2d0
[  605.567955]  rpm_resume+0x255/0x760
[  605.567962]  ? __slab_free+0xc7/0x320
[  605.567972]  rpm_resume+0x255/0x760
[  605.567978]  ? kernfs_should_drain_open_files+0x38/0x50
[  605.567989]  rpm_resume+0x255/0x760
[  605.567994]  ? kernfs_should_drain_open_files+0x38/0x50
[  605.568002]  ? kernfs_drain+0xec/0x120
[  605.568010]  __pm_runtime_resume+0x4e/0x80
[  605.568018]  device_release_driver_internal+0xa8/0x200
[  605.568028]  bus_remove_device+0xc0/0x120
[  605.568035]  device_del+0x158/0x3d0
[  605.568045]  ? mutex_lock+0x12/0x30
[  605.568051]  __scsi_remove_device+0x12b/0x180 [scsi_mod]
[  605.568095]  sdev_store_delete+0x6a/0xd0 [scsi_mod]
[  605.568132]  kernfs_fop_write_iter+0x129/0x1c0
[  605.568141]  vfs_write+0x2d3/0x3f0
[  605.568155]  ksys_write+0x63/0xe0
[  605.568165]  do_syscall_64+0x5a/0xb0
[  605.568173]  ? syscall_exit_to_user_mode+0x2b/0x40
[  605.568178]  ? do_syscall_64+0x67/0xb0
[  605.568184]  entry_SYSCALL_64_after_hwframe+0x46/0xb0
[  605.568193] RIP: 0033:0x7f0c1e9b6473
[  605.568200] RSP: 002b:00007ffe01b0bd28 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[  605.568208] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f0c1e9b6473
[  605.568213] RDX: 0000000000000002 RSI: 000056115e4b86f0 RDI: 0000000000000001
[  605.568216] RBP: 000056115e4b86f0 R08: 000000000000000a R09: 00007f0c1ea5a0c0
[  605.568220] R10: 00007f0c1ea59fc0 R11: 0000000000000246 R12: 0000000000000002
[  605.568224] R13: 00007f0c1ea9a6a0 R14: 0000000000000002 R15: 00007f0c1ea95880
[  605.568232]  </TASK>



[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Index of Archives]     [SCSI Target Devel]     [Linux SCSI Target Infrastructure]     [Kernel Newbies]     [IDE]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Linux ATA RAID]     [Linux IIO]     [Samba]     [Device Mapper]

  Powered by Linux