On 8/31/23 10:48, Vivi, Rodrigo wrote: > On Thu, 2023-08-31 at 09:32 +0900, Damien Le Moal wrote: >> On 8/31/23 07:14, Rodrigo Vivi wrote: >>> On Tue, Aug 29, 2023 at 03:17:38PM +0900, Damien Le Moal wrote: >>>> On 8/26/23 02:09, Rodrigo Vivi wrote: >>>>>>> So, maybe we have some kind of disks/configuration out >>>>>>> there where this >>>>>>> start upon resume is needed? Maybe it is just a matter of >>>>>>> timming to >>>>>>> ensure some firmware underneath is up and back to life? >>>>>> >>>>>> I do not think so. Suspend will issue a start stop unit >>>>>> command to put the drive >>>>>> to sleep and resume will reset the port (which should wake up >>>>>> the drive) and >>>>>> then issue an IDENTIFY command (which will also wake up the >>>>>> drive) and other >>>>>> read logs etc to rescan the drive. >>>>>> In both cases, if the commands do not complete, we would see >>>>>> errors/timeout and >>>>>> likely port reset/drive gone events. So I think this is >>>>>> likely another subtle >>>>>> race between scsi suspend and ata suspend that is causing a >>>>>> deadlock. >>>>>> >>>>>> The main issue I think is that there is no direct ancestry >>>>>> between the ata port >>>>>> (device) and scsi device, so the change to scsi async pm ops >>>>>> made a mess of the >>>>>> suspend/resume operations ordering. For suspend, scsi device >>>>>> (child of ata port) >>>>>> should be first, then ata port device (parent). For resume, >>>>>> the reverse order is >>>>>> needed. PM normally ensures that parent/child ordering, but >>>>>> we lack that >>>>>> parent/child relationship. I am working on fixing that but it >>>>>> is very slow >>>>>> progress because I have been so far enable to recreate any of >>>>>> the issues that >>>>>> have been reported. I am patching "blind"... >>>>> >>>>> I believe your suspicious makes sense. And on these lines, that >>>>> patch you >>>>> attached earlier would fix that. However my initial tries of >>>>> that didn't >>>>> help. I'm going to run more tests and get back to you. >>>> >>>> Rodrigo, >>>> >>>> I pushed the resume-v2 branch to libata tree: >>>> >>>> git@xxxxxxxxxxxxxxxxxxx:pub/scm/linux/kernel/git/dlemoal/libata >>>> (or >>>> https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.gi >>>> t) >>>> >>>> This branch adds 13 patches on top of 6.5.0 to cleanup libata >>>> suspend/resume and >>>> other device shutdown issues. The first 4 patches are the main >>>> ones to fix >>>> suspend resume. I tested that on 2 different machines with >>>> different drives and >>>> with qemu. All seems fine. >>>> >>>> Could you try to run this through your CI ? I am very interested >>>> in seeing if it >>>> survives your suspend/resume tests. >>> >>> well, in the end this didn't affect the CI machinery as I was >>> afraid. >>> it is only in my local DG2. >>> >>> https://intel-gfx-ci.01.org/tree/intel-xe/bat- >>> all.html?testfilter=suspend >>> (bat-dg2-oem2 one) >>> >>> I just got these 13 patches and applied to my branch and tested it >>> again >>> and it still *fails* for me. >> >> That is annoying... But I think the messages give us a hint as to >> what is going >> on. See below. >> >>> >>> [ 79.648328] [IGT] kms_pipe_crc_basic: finished subtest pipe-A- >>> DP-2, SUCCESS >>> [ 79.657353] [IGT] kms_pipe_crc_basic: starting dynamic subtest >>> pipe-B-DP-2 >>> [ 80.375042] PM: suspend entry (deep) >>> [ 80.380799] Filesystems sync: 0.002 seconds >>> [ 80.386476] Freezing user space processes >>> [ 80.392286] Freezing user space processes completed (elapsed >>> 0.001 seconds) >>> [ 80.399294] OOM killer disabled. >>> [ 80.402536] Freezing remaining freezable tasks >>> [ 80.408335] Freezing remaining freezable tasks completed >>> (elapsed 0.001 seconds) >>> [ 80.439372] sd 5:0:0:0: [sdb] Synchronizing SCSI cache >>> [ 80.439716] serial 00:01: disabled >>> [ 80.448011] sd 4:0:0:0: [sda] Synchronizing SCSI cache >>> [ 80.448014] sd 7:0:0:0: [sdc] Synchronizing SCSI cache >>> [ 80.453600] ata6.00: Entering standby power mode >> >> This is sd 5:0:0:0. All good, ordered properly with the >> "Synchronizing SCSI cache". >> >>> [ 80.464217] ata5.00: Entering standby power mode >> >> Same here for sd 4:0:0:0. >> >>> [ 80.812294] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl >>> 300) >>> [ 80.818520] ata8.00: Entering active power mode >>> [ 80.842989] ata8.00: configured for UDMA/133 >> >> Arg ! sd 7:0:0:0 is resuming ! But the above "Synchronizing SCSI >> cache" tells >> us that it was suspending and libata EH did not yet put that drive to >> standby... >> >>> [ 80.847660] ata8.00: Entering standby power mode >> >> ... which happens here. So it looks like libata EH had both the >> suspend and >> resume requests at the same time, which is totally weird. > > although it looks weird, it totally matches the 'use case'. > I mean, if I suspend, resume, and wait a bit before suspend and resume > again, it will work 100% of the time. > The issue is really only when another suspend comes right after the > resume, in a loop without any wait. > >> >>> [ 81.119426] xe 0000:03:00.0: [drm] GT0: suspended >>> [ 81.800508] PM: suspend of devices complete after 1367.829 msecs >>> [ 81.806661] PM: start suspend of devices complete after 1390.859 >>> msecs >>> [ 81.813244] PM: suspend devices took 1.398 seconds >>> [ 81.820101] PM: late suspend of devices complete after 2.036 >>> msecs >> >> ...and PM suspend completes here. Resume "starts" now (but clearly it >> started >> earlier already given that sd 7:0:0:0 was reactivated. > > that is weird. > >> >>> �[ 82.403857] serial 00:01: activated >>> [ 82.489612] nvme nvme0: 16/0/0 default/read/poll queues >>> [ 82.563318] r8169 0000:07:00.0 enp7s0: Link is Down >>> [ 82.581444] xe REG[0x223a8-0x223af]: allow read access >>> [ 82.586704] xe REG[0x1c03a8-0x1c03af]: allow read access >>> [ 82.592071] xe REG[0x1d03a8-0x1d03af]: allow read access >>> [ 82.597423] xe REG[0x1c83a8-0x1c83af]: allow read access >>> [ 82.602765] xe REG[0x1d83a8-0x1d83af]: allow read access >>> [ 82.608113] xe REG[0x1a3a8-0x1a3af]: allow read access >>> [ 82.613281] xe REG[0x1c3a8-0x1c3af]: allow read access >>> [ 82.618454] xe REG[0x1e3a8-0x1e3af]: allow read access >>> [ 82.623634] xe REG[0x263a8-0x263af]: allow read access >>> [ 82.628816] xe 0000:03:00.0: [drm] GT0: resumed >>> [ 82.728005] ata7: SATA link down (SStatus 4 SControl 300) >>> [ 82.733531] ata5: SATA link up 6.0 Gbps (SStatus 133 SControl >>> 300) >>> [ 82.739773] ata5.00: Entering active power mode >>> [ 82.744398] ata6: SATA link up 6.0 Gbps (SStatus 133 SControl >>> 300) >>> [ 82.750618] ata6.00: Entering active power mode >>> [ 82.755961] ata5.00: configured for UDMA/133 >>> [ 82.760479] ata5.00: Enabling discard_zeroes_data >>> [ 82.836266] ata6.00: configured for UDMA/133 >>> [ 84.460081] ata8: SATA link up 6.0 Gbps (SStatus 133 SControl >>> 300) >>> [ 84.466354] ata8.00: Entering active power mode >>> [ 84.497256] ata8.00: configured for UDMA/133 >>> ... >> >> And this looks all normal, the drives have all been transitioned to >> active >> power mode as expected. And yet, your system is stuck after this, >> right ? > > yes I think I have now figured it out, and fixed. I could reliably recreate the same hang both with qemu using a failed suspend (using a device not supporting suspend) and real hardware with a short rtc wake. It turns out that the root cause of the hang is ata_scsi_dev_rescan(), which is scheduled asynchronously from PM context on resume. With quick suspend after a resume, suspend may win the race against that ata_scsi_dev_rescan() task execution and we endup calling scsi_rescan_device() on a suspended device, causing that function to wait with the device_lock() held, which causes PM to deadlock when it needs to resume the scsi device. The recent commit 6aa0365a3c85 ("ata: libata-scsi: Avoid deadlock on rescan after device resume") was intended to fix that, but it did so less than ideally and the fix has a race on the scsi power state check, thus not always preventing the resume hang. I pushed a new patch series that goes on top of 6.5.0: resume-v3 branch in the libata tree: https://git.kernel.org/pub/scm/linux/kernel/git/dlemoal/libata.git This works very well for me. Using this script on real hardware: for (( i=0; i<20; i++ )); do echo "+2" > /sys/class/rtc/rtc0/wakealarm echo mem > /sys/power/state done The system repeatedly suspends and resumes and comes back OK. Of note is that if I set the delay to +1 second, then I sometime do not see the system resume and the script stops. But using wakeup-on-lan (wol command) from another machine to wake it up, the machine resumes normally and continues executing the script. So it seems that setting the rtc alarm unreasonably early result in it being lost and the system suspending wating to be woken up. I also tested this in qemu. As mentioned before, I cannot get rtc alarm to wake up the VM guest though. However, using a virtio device that does not support suspend, resume strats in the middle of the suspend operation due to the suspend error reported by that device. And it turns out that systemd really insists on suspending the system despite the error, so when running "systemctl suspend" I see a retry for suspend right after the first failed one. That is enough to trigger the issue without the patches. Please test ! Thanks. -- Damien Le Moal Western Digital Research
