Re: [RFC] ata: libata: increase PMP SRST timeout to 10s

From: Damien Le Moal
Date: Fri Sep 22 2023 - 14:59:25 EST

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@xxxxxxxxxxxxxxxxxxxx>
>>> ---
>>>
>>> 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@xxxxxxxxxxxxxxxxxxxx/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@xxxxxxxxxxxxxxxxxxxx>
> 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.


--
Damien Le Moal
Western Digital Research