On 2023/09/29 15:56, Geert Uytterhoeven wrote:
> Hi Damien,
>
> On Fri, Sep 29, 2023 at 3:37 PM Damien Le Moal <dlemoal@xxxxxxxxxx> wrote:
>> On 2023/09/28 14:26, Geert Uytterhoeven wrote:
>>> On Tue, Sep 26, 2023 at 10:15 AM Damien Le Moal <dlemoal@xxxxxxxxxx> wrote:
>>>> The first 9 patches of this series fix several issues with suspend/resume
>>>> power management operations in scsi and libata. The most significant
>>>> changes introduced are in patch 4 and 5, where the manage_start_stop
>>>> flag of scsi devices is split into the manage_system_start_stop and
>>>> manage_runtime_start_stop flags to allow keeping scsi runtime power
>>>> operations for spining up/down ATA devices but have libata do its own
>>>> system suspend/resume device power state management using EH.
>>>>
>>>> The remaining patches are code cleanup that do not introduce any
>>>> significant functional change.
>>>>
>>>> This series was tested on qemu and on various PCs and servers. I am
>>>> CC-ing people who recently reported issues with suspend/resume.
>>>> Additional testing would be much appreciated.
>>>
>>> JFTR, with current libata/for-next[*], I saw the following with
>>> rcar-sata, once (interesting lines marked with "!"):
>>>
>>> PM: suspend entry (s2idle)
>>> Filesystems sync: 0.026 seconds
>>> Freezing user space processes
>>> ! ata1.00: qc timeout after 10000 msecs (cmd 0x40)
>>> Freezing user space processes completed (elapsed 0.007 seconds)
>>> ! ata1.00: VERIFY failed (err_mask=0x4)
>>> OOM killer disabled.
>>> ! ata1.00: failed to IDENTIFY (I/O error, err_mask=0x40)
>>> Freezing remaining freezable tasks
>>> ! ata1.00: revalidation failed (errno=-5)
>>> Freezing remaining freezable tasks completed (elapsed 0.002 seconds)
>>> sd 0:0:0:0: [sda] Synchronizing SCSI cache
>>> ata1: link resume succeeded after 1 retries
>>> ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>>> ata1.00: configured for UDMA/133
>>> ata1.00: Entering active power mode
>>> ata1.00: Entering standby power mode
>>> ravb e6800000.ethernet eth0: Link is Down
>>> Micrel KSZ9031 Gigabit PHY e6800000.ethernet-ffffffff:00: attached
>>> PHY driver (mii_bus:phy_addr=e6800000.ethernet-ffffffff:00, irq=136)
>>> OOM killer enabled.
>>> Restarting tasks ... done.
>>> random: crng reseeded on system resumption
>>> PM: suspend exit
>>> ata1: link resume succeeded after 1 retries
>>> ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>>> ata1.00: Entering active power mode
>>> ata1.00: configured for UDMA/133
>>> ravb e6800000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off
>>>
>>> Regardless, the disk worked fine after resume.
>>>
>>> Note that I saw this only once.
>>
>> I think I found the reason for this, but to confirm, were you doing a suspend
>> right after resuming the system ? If yes, that I think I exactly understand the
>> issue and why you saw it only once (it is a subtle race with scheduling
>> libata-EH suspend/resume operations). I will send a fix next week.
>
> Now you ask that, yes there was a system suspend before.
>
> Relevant log with timing info:
>
> [ 130.177616] PM: suspend exit
> [ 130.257981] ata1: link resume succeeded after 1 retries
> [ 130.376714] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ 130.388525] ata1.00: Entering active power mode
>
> so the drive should have been ready here.
yep.
>
> [ 140.452669] PM: suspend entry (s2idle)
Then suspend again 10s later.
> [ 140.488313] Filesystems sync: 0.026 seconds
> [ 140.515957] Freezing user space processes
> [ 140.518209] ata1.00: qc timeout after 10000 msecs (cmd 0x40)
> [ 140.523384] Freezing user space processes completed (elapsed
> 0.007 seconds)
> [ 140.527718] ata1.00: VERIFY failed (err_mask=0x4)
But that verify sent 10s earlier to spinup the drive failed... Hmmm... That is
not exactly what I was thinking of. While the race between scheduling suspend
while resume is still on-going does exist, it is likely not what is happening
here given the time interval with suspend entry. Need to dig further.
Do you perhaps have "Power-up in Standby" (PUIS) enabled on that drive ?
> [ 140.532541] OOM killer disabled.
> [ 140.537270] ata1.00: failed to IDENTIFY (I/O error, err_mask=0x40)
> [ 140.542069] Freezing remaining freezable tasks
> [ 140.546784] ata1.00: revalidation failed (errno=-5)
>
> Gr{oetje,eeting}s,
>
> Geert
>
--
Damien Le Moal
Western Digital Research
