Messages in this thread | | | Date | Fri, 22 Sep 2023 21:41:01 +0200 | Subject | Re: [RFC] ata: libata: increase PMP SRST timeout to 10s | From | Matthias Schiffer <> |
| |
On 22/09/2023 20:59, Damien Le Moal wrote: > On 2023/09/22 11:47, Matthias Schiffer wrote: >> On 22/09/2023 18:36, Damien Le Moal wrote: >>> On 2023/09/22 9:18, Matthias Schiffer wrote: >>>> On certain devices(*), this device probe failures for SATA disks after >>>> wakeup from S2RAM, which often led to the disks not to be detected again. >>>> >>>> ata1: softreset failed (1st FIS failed) >>>> >>>> (*) Observed for disks connected to the internal SATA controller of the >>>> QNAP TS-453B, which is a "SATA controller: Intel Corporation >>>> Celeron/Pentium Silver Processor SATA Controller (rev 06)". >>>> >>>> Signed-off-by: Matthias Schiffer <mschiffer@universe-factory.net> >>>> --- >>>> >>>> I'm sending this as an RFC, as I don't think it makes sense to increase the >>>> timeout unconditionally - maybe it should be some kind of device quirk, if >>>> there isn't any better fix. >>>> >>>> See text below for more information. >>>> >>>> include/linux/libata.h | 2 +- >>>> 1 file changed, 1 insertion(+), 1 deletion(-) >>>> >>>> diff --git a/include/linux/libata.h b/include/linux/libata.h >>>> index be2f0cee1601..9194030527b6 100644 >>>> --- a/include/linux/libata.h >>>> +++ b/include/linux/libata.h >>>> @@ -256,7 +256,7 @@ enum { >>>> * advised to wait only for the following duration before >>>> * doing SRST. >>>> */ >>>> - ATA_TMOUT_PMP_SRST_WAIT = 5000, >>>> + ATA_TMOUT_PMP_SRST_WAIT = 10000, >>>> >>>> /* When the LPM policy is set to ATA_LPM_MAX_POWER, there might >>>> * be a spurious PHY event, so ignore the first PHY event that >>>> --- >>>> >>>> I'm running plain Debian 12 rather than the QNAP OS (I believe the original >>>> software does not support S2RAM at all). The issue I'm describing exists at >>>> least since kernel 5.15; I've never run older kernels on this hardware. The >>>> mainboard has 2 SATA controllers, both handled by the ahci driver: >>>> >>>> # lspci | grep SATA >>>> 00:12.0 SATA controller: Intel Corporation Celeron/Pentium Silver Processor SATA Controller (rev 06) >>>> 02:00.0 SATA controller: ASMedia Technology Inc. 106x SATA/RAID Controller (rev 01) >>>> >>>> The first two channels ata1 and ata2 are connected to the Intel controller, >>>> while the ASMedia is responsible for ata3 through ata14. I have the same hard >>>> drives connected to ata2, ata3, and ata4 (ata1 has a different model), and I'm >>>> seeing the timeout issue after suspend only on ata1 and ata2, so it is specific >>>> to the Intel controller rather than the drive model. >>>> >>>> On Debian's default 6.1.52 kernel, a wakeup looks like the following *in the >>>> good case*, where all disks are successfully brought up again (unfortunately, >>>> journald doesn't seem to have recorded correct timing information; roughly >>>> 22 seconds pass between the "starting disk" and final "link up"). I have >>>> redacted lines for the unused ata{5..14} ports for conciseness. >>>> >>>> ACPI: PM: Waking up from system sleep state S3 >>>> sd 2:0:0:0: [sdc] Starting disk >>>> sd 3:0:0:0: [sdd] Starting disk >>>> sd 1:0:0:0: [sdb] Starting disk >>>> sd 0:0:0:0: [sda] Starting disk >>>> ata3: link is slow to respond, please be patient (ready=0) >>>> ata4: link is slow to respond, please be patient (ready=0) >>>> ata2: found unknown device (class 0) >>>> ata1: found unknown device (class 0) >>>> ata1: softreset failed (1st FIS failed) >>>> ata2: softreset failed (1st FIS failed) >>>> ata3: COMRESET failed (errno=-16) >>>> ata4: COMRESET failed (errno=-16) >>>> ata1: found unknown device (class 0) >>>> ata2: found unknown device (class 0) >>>> ata3: link is slow to respond, please be patient (ready=0) >>>> ata4: link is slow to respond, please be patient (ready=0) >>>> ata3: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> ata3.00: configured for UDMA/133 >>>> ata4: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> ata4.00: configured for UDMA/133 >>>> ata1: softreset failed (1st FIS failed) >>>> ata2: softreset failed (1st FIS failed) >>>> ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> ata2.00: configured for UDMA/133 >>>> ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> ata1.00: configured for UDMA/133 >>>> >>>> On the same kernel, another wakeup might look like this: >>>> >>>> ACPI: PM: Waking up from system sleep state S3 >>>> sd 2:0:0:0: [sdd] Starting disk >>>> sd 3:0:0:0: [sdc] Starting disk >>>> sd 0:0:0:0: [sda] Starting disk >>>> sd 1:0:0:0: [sdb] Starting disk >>>> ata2: SATA link down (SStatus 0 SControl 300) >>>> ata3: link is slow to respond, please be patient (ready=0) >>>> ata4: link is slow to respond, please be patient (ready=0) >>>> ata1: SATA link down (SStatus 0 SControl 300) >>>> ata3: COMRESET failed (errno=-16) >>>> ata4: COMRESET failed (errno=-16) >>>> ata1: SATA link down (SStatus 0 SControl 300) >>>> ata1: limiting SATA link speed to <unknown> >>>> ata3: link is slow to respond, please be patient (ready=0) >>>> ata4: link is slow to respond, please be patient (ready=0) >>>> ata2: SATA link down (SStatus 0 SControl 300) >>>> ata2: limiting SATA link speed to <unknown> >>>> ata4: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> ata3: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> ata3.00: configured for UDMA/133 >>>> ata4.00: configured for UDMA/133 >>>> ata1: SATA link down (SStatus 0 SControl 3F0) >>>> ata1.00: disable device >>>> ata2: SATA link down (SStatus 0 SControl 3F0) >>>> ata2.00: disable device >>>> sd 1:0:0:0: rejecting I/O to offline device >>>> sd 0:0:0:0: rejecting I/O to offline device >>>> ata2.00: detaching (SCSI 1:0:0:0) >>>> ata1.00: detaching (SCSI 0:0:0:0) >>>> sd 0:0:0:0: [sda] Start/Stop Unit failed: Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK >>>> sd 1:0:0:0: [sdb] Start/Stop Unit failed: Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK >>>> sd 0:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 [scsi_mod] returns -5 >>>> sd 1:0:0:0: PM: dpm_run_callback(): scsi_bus_resume+0x0/0x90 [scsi_mod] returns -5 >>>> sd 0:0:0:0: PM: failed to resume async: error -5 >>>> sd 1:0:0:0: PM: failed to resume async: error -5 >>>> >>>> With my patch applied, the following log is generated instead: >>>> >>>> [ 63.748299] ACPI: PM: Waking up from system sleep state S3 >>>> [ 63.767111] sd 2:0:0:0: [sdc] Starting disk >>>> [ 63.767181] sd 3:0:0:0: [sdd] Starting disk >>>> [ 63.776402] sd 0:0:0:0: [sdb] Starting disk >>>> [ 63.776500] sd 1:0:0:0: [sda] Starting disk >>>> [ 69.121513] ata4: link is slow to respond, please be patient (ready=0) >>>> [ 69.125531] ata3: link is slow to respond, please be patient (ready=0) >>>> [ 69.133538] ata2: link is slow to respond, please be patient (ready=0) >>>> [ 69.133557] ata1: link is slow to respond, please be patient (ready=0) >>>> [ 73.803763] ata4: COMRESET failed (errno=-16) >>>> [ 73.807805] ata3: COMRESET failed (errno=-16) >>>> [ 73.815780] ata2: found unknown device (class 0) >>>> [ 73.815800] ata1: found unknown device (class 0) >>>> [ 73.975799] ata2: softreset failed (device not ready) >>>> [ 73.975813] ata1: softreset failed (device not ready) >>>> [ 79.157124] ata4: link is slow to respond, please be patient (ready=0) >>>> [ 79.161116] ata3: link is slow to respond, please be patient (ready=0) >>>> [ 79.329119] ata1: link is slow to respond, please be patient (ready=0) >>>> [ 79.329129] ata2: link is slow to respond, please be patient (ready=0) >>>> [ 80.781376] ata3: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> [ 80.792790] ata3.00: configured for UDMA/133 >>>> [ 80.837437] ata4: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> [ 80.843358] ata4.00: configured for UDMA/133 >>>> [ 82.309565] ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> [ 82.334217] ata2.00: configured for UDMA/133 >>>> [ 84.009745] ata1: found unknown device (class 0) >>>> [ 84.169743] ata1: softreset failed (device not ready) >>>> [ 85.425859] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> [ 85.486518] ata1.00: configured for UDMA/133 >>>> >>>> Compared to the previous "good" log >>>> - ata1 and ata2 got "link is slow to respond" messages >>>> - the "softreset failed" error changed from "1st FIS failed" to "device not >>>> ready" >>>> - I haven't seen any failures to bring up drives in 10+ wakeups, where it would >>>> fail in roughly 1 out of 3 tries without the increased timeout >>>> >>>> I also saw the resume improvements going on in >>>> https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.git/, so next I >>>> took kernel 6.5.4 and applied all patches from the for-6.6 and for-6.7 branches >>>> from that repo on top. The first thing I noticed with this new kernel was a >>>> regression: >>>> >>>> 16:24:25 : PM: suspend exit >>>> 16:24:25 : ata2: SATA link down (SStatus 0 SControl 300) >>>> 16:24:25 : ata2.00: Entering active power mode >>>> 16:24:25 : ata1: SATA link down (SStatus 0 SControl 300) >>>> 16:24:25 : ata1.00: Entering active power mode >>>> 16:24:30 : ata3: link is slow to respond, please be patient (ready=0) >>>> 16:24:30 : ata4: link is slow to respond, please be patient (ready=0) >>>> 16:24:35 : ata2.00: qc timeout after 10000 msecs (cmd 0x40) >>>> 16:24:35 : ata1.00: qc timeout after 10000 msecs (cmd 0x40) >>>> 16:24:35 : ata1.00: VERIFY failed (err_mask=0x4) >>>> 16:24:35 : ata2.00: VERIFY failed (err_mask=0x4) >>>> 16:24:35 : ata2: SATA link down (SStatus 0 SControl 300) >>>> 16:24:35 : ata2: limiting SATA link speed to <unknown> >>>> 16:24:41 : ata4: link is slow to respond, please be patient (ready=0) >>>> 16:24:41 : ata3: link is slow to respond, please be patient (ready=0) >>>> 16:24:41 : ata4: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> 16:24:41 : ata4.00: Entering active power mode >>>> 16:24:41 : ata3: SATA link up 6.0 Gbps (SStatus 133 SControl 300) >>>> 16:24:41 : ata3.00: Entering active power mode >>>> 16:24:41 : ata4.00: configured for UDMA/133 >>>> 16:24:41 : ata3.00: configured for UDMA/133 >>>> 16:24:41 : ata1: SATA link down (SStatus 0 SControl 300) >>>> 16:24:41 : ata1: limiting SATA link speed to <unknown> >>>> 16:24:47 : ata1: SATA link down (SStatus 0 SControl 3F0) >>>> 16:24:47 : ata1.00: disable device >>>> 16:24:47 : ata2: SATA link down (SStatus 0 SControl 3F0) >>>> 16:24:47 : ata2.00: disable device >>>> 16:24:47 : ata1.00: detaching (SCSI 0:0:0:0) >>>> 16:24:47 : ata2.00: detaching (SCSI 1:0:0:0) >>>> >>>> For the ASMedia controller, the new kernel fixes the "COMRESET failed" messages, >>>> but on the Intel controller, two new errors have appeared ("qc timeout" and >>>> "VERIFY failed"), and my drives are missing again. >>> >>> These errors are being address by a series that is about to be applied: >>> >>> https://lore.kernel.org/linux-ide/yq134z7577n.fsf@ca-mkp.ca.oracle.com/T/#m255ef5cc9b64b971765e8b6551aacee860fd1325 >>> >>> This series addresses various issues with libata resume, including what you are >>> seeing above, which causes the drives to fail resume and disappear, or worth, a >>> hang on resume. Could you please try to apply these patches and test with them ? >>> The "link is slow to respond" message is fairly normal and overall, there is up >>> to 1min timeout before giving up on the drive. So this should not be an issue. >>> >>> If you still see a problem with your system, we can increase the timeout to >>> avoid that "1st FIS failed" error. >> >> Thanks for your quick reply! >> >> My previous test contained an older version of that patch series (from your >> for-6.7 branch), I've updated to v5 now. >> >> I've not seen the "qc timeout" or "VERIFY failed" again with the new build >> even if I don't set libata.ata_probe_timeout=30. I'm not sure whether that >> was a one-time fluke or it was fixed between versions of the patch series; >> I'll report back if I ever see that error again. >> >> Your series definitely improves wakeup behavior - I'm still seeing the "1st >> FIS failed", but the drives seem to come up reliably regardless. >> >> Feel free to add >> Tested-by: Matthias Schiffer <mschiffer@universe-factory.net> >> for the whole series. >> >> Even with the latest series applied, I still need my >> ATA_TMOUT_PMP_SRST_WAIT change to avoid the "softreset failed (1st FIS >> failed)" message (and get "softreset failed (device not ready)" instead). > > OK. Thank you for testing. > For increasing the timeout, please send a proper patch. I will queue it. > >
Will do. Do you see any downsides to the increased timeout? Otherwise, I'd simply add a Fixes: tag for the last time the timeout was touched in e7d3ef13d52a126438f687a1a32da65ff926ed57. [unhandled content-type:application/pgp-signature] | |