OpenZFS and Nvidia drivers frequently trigger resilvering when wakeing-up from suspend

[cgs-labs]

This is a rather odd issue, that is plaguing me for a while now.

I am using

• Debian 12 stable
• OpenZFS 2.1.11-1
• kernel 6.1.0-23-amd64
• nvidia proprietary driver 535.183.01

This is a Debian standard installation, nothing special.

The Problem

In about 20% of cases when the PC is waking up from suspend to RAM, there is an issue that the HDDs don't come up quickly enough, the log prints out messages that soft-reset has failed, it varies a bit. Consequently a re-silvering is triggered. In most cases this is all what happens. However on some cases ZFS takes one or more drives OFFLINE. ZFS does its thing, but running a smart-test returns no errors.

I searched the internet, and it seems that quite a few people have this problem. The usual solution is to use a HBA, which seems to fix the issue.

For me this only happens when using the proprietary Nvidia Driver.

I just want to document this issue here. I do not expect it getting fixed, since OpenZFS, Nvidia and the kernel are involved.

[n0xena]

I can see a relation between wake up from suspend to and hardware not fast enough to "report back for duty" - but I don't see a connection with the nvidia driver
also you use both an old kernel and an old zfs version - do you have the option to upgrade both to more recent versions?

[cgs-labs]

Thanks for the quick reply. Yes I am aware that I am not using the latest software version.

I'd like add some more info:

• it is gaming PC hardware
• AMD Ryzen 7 2700X
• Nvidia GTX 960
• MSI Mortar Max AMD B450M chipset
• 32 GB non-ECC RAM

I've used this setup using the nouveau GPU driver for 2 week with no issues, installed the nvidia-driver and the problem came back.
It affects different HDDs not just one specific one, e.g. it changes all the time.

Some people, who use Proxmox (which is based on Debian) have seen this issue as well. However Proxmox does not support suspend and also uses newer kernel and zfs versions. Some people say they have seen it only when the IO load is high. Some blame the AMD chipset. It is all very confusing and unscientific, but there seems to be some kind of issue.

Log messages:

Jul 26 22:26:18 cube kernel: ACPI: PM: Waking up from system sleep state S3
Jul 26 22:26:18 cube kernel: mlx4_core 0000:25:00.0: resume was called
Jul 26 22:26:18 cube kernel: xhci_hcd 0000:03:00.0: xHC error in resume, USBSTS 0x401, Reinit
Jul 26 22:26:18 cube kernel: usb usb1: root hub lost power or was reset
Jul 26 22:26:18 cube kernel: usb usb2: root hub lost power or was reset
Jul 26 22:26:18 cube kernel: parport_pc 00:03: activated
Jul 26 22:26:18 cube kernel: serial 00:04: activated
Jul 26 22:26:18 cube kernel: nvme nvme0: Shutdown timeout set to 10 seconds
Jul 26 22:26:18 cube kernel: nvme nvme0: 32/0/0 default/read/poll queues
Jul 26 22:26:18 cube kernel: ata9: SATA link down (SStatus 0 SControl 300)
Jul 26 22:26:18 cube kernel: usb 1-10: reset low-speed USB device number 3 using xhci_hcd
Jul 26 22:26:18 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:18 cube kernel: ata1: SATA link down (SStatus 0 SControl 300)
Jul 26 22:26:18 cube kernel: ata1.00: Entering active power mode
Jul 26 22:26:18 cube kernel: ata1.00: VERIFY failed (err_mask=0x100)
Jul 26 22:26:18 cube kernel: ata1.00: failed to IDENTIFY (I/O error, err_mask=0x40)
Jul 26 22:26:18 cube kernel: ata1.00: revalidation failed (errno=-5)
Jul 26 22:26:18 cube kernel: usb 1-7: reset low-speed USB device number 2 using xhci_hcd
Jul 26 22:26:18 cube kernel: usb 2-1: reset SuperSpeed USB device number 2 using xhci_hcd
Jul 26 22:26:18 cube kernel: ata5: link is slow to respond, please be patient (ready=0)
Jul 26 22:26:18 cube kernel: ata2: link is slow to respond, please be patient (ready=0)
Jul 26 22:26:18 cube kernel: ata6: link is slow to respond, please be patient (ready=0)
Jul 26 22:26:18 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:18 cube kernel: ata1: SATA link down (SStatus 0 SControl 300)
...
Jul 26 22:26:18 cube kernel: ata1: limiting SATA link speed to <unknown>
Jul 26 22:26:18 cube kernel: ata1: found unknown device (class 0)
...
Jul 26 22:26:18 cube systemd[1]: Started zfs-zed.service - ZFS Event Daemon (zed).
Jul 26 22:26:18 cube zed[12645]: ZFS Event Daemon 2.1.11-1 (PID 12645)
Jul 26 22:26:18 cube zed[12645]: Processing events since eid=5
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0): Setting mode "HDMI-0: 2560x1440_120 @2560x1440 +0+0 {ViewPortIn=2560x1440, ViewPortOut=2560x1440+0+0}"
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0): ACPI: failed to connect to the ACPI event daemon; the daemon
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0):     may not be running or the "AcpidSocketPath" X
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0):     configuration option may not be set correctly.  When the
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0):     ACPI event daemon is available, the NVIDIA X driver will
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0):     try to use it to receive ACPI event notifications.  For
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0):     details, please see the "ConnectToAcpid" and
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0):     "AcpidSocketPath" X configuration options in Appendix B: X
Jul 26 22:26:18 cube /usr/libexec/gdm-x-session[3979]: (II) NVIDIA(0):     Config Options in the README.
Jul 26 22:26:18 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:18 cube kernel: ata1: SATA link down (SStatus 0 SControl 3F0)
Jul 26 22:26:18 cube kernel: ata1: illegal qc_active transition (00000000->00000001)
Jul 26 22:26:18 cube kernel: ata1.00: disable device
...
Jul 26 22:26:21 cube kernel: ata2: found unknown device (class 0)
Jul 26 22:26:21 cube kernel: ata6: found unknown device (class 0)
Jul 26 22:26:21 cube kernel: ata5: found unknown device (class 0)
Jul 26 22:26:21 cube kernel: ata2: softreset failed (device not ready)
Jul 26 22:26:21 cube kernel: ata6: found unknown device (class 0)
Jul 26 22:26:21 cube kernel: ata6: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jul 26 22:26:21 cube kernel: ata6.00: Entering active power mode
Jul 26 22:26:21 cube kernel: ata5: softreset failed (device not ready)
Jul 26 22:26:21 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:21 cube kernel: ata1: SATA link down (SStatus 0 SControl 300)
Jul 26 22:26:22 cube kernel: ata1: limiting SATA link speed to 1.5 Gbps
...
Jul 26 22:26:26 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:26 cube kernel: ata1: SATA link down (SStatus 0 SControl 310)
Jul 26 22:26:26 cube kernel: ata1: illegal qc_active transition (00000000->00000001)
Jul 26 22:26:26 cube kernel: ata2: link is slow to respond, please be patient (ready=0)
Jul 26 22:26:26 cube kernel: ata5: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jul 26 22:26:26 cube kernel: ata5.00: Entering active power mode
Jul 26 22:26:26 cube kernel: ata5.00: configured for UDMA/133
Jul 26 22:26:26 cube kernel: ata1: limiting SATA link speed to 1.5 Gbps
...
Jul 26 22:26:27 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:27 cube kernel: ata1: SATA link down (SStatus 0 SControl 310)
Jul 26 22:26:28 cube kernel: ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jul 26 22:26:28 cube kernel: ata2.00: Entering active power mode
Jul 26 22:26:28 cube kernel: ata2.00: supports DRM functions and may not be fully accessible
Jul 26 22:26:29 cube kernel: ata1: limiting SATA link speed to 1.5 Gbps
Jul 26 22:26:30 cube kernel: ata1: SATA link down (SStatus 0 SControl 310)
Jul 26 22:26:30 cube kernel: ata1: limiting SATA link speed to 1.5 Gbps
Jul 26 22:26:30 cube kernel: ata2.00: supports DRM functions and may not be fully accessible
Jul 26 22:26:30 cube kernel: ata2.00: configured for UDMA/133
Jul 26 22:26:31 cube kernel: ata6.00: qc timeout after 10000 msecs (cmd 0x40)
Jul 26 22:26:31 cube kernel: ata6.00: VERIFY failed (err_mask=0x4)
Jul 26 22:26:31 cube kernel: ata6.00: failed to IDENTIFY (I/O error, err_mask=0x40)
Jul 26 22:26:31 cube kernel: ata6.00: revalidation failed (errno=-5)
Jul 26 22:26:31 cube kernel: ata6: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jul 26 22:26:31 cube kernel: ata6.00: configured for UDMA/133
Jul 26 22:26:31 cube kernel: ata6.00: Entering active power mode
Jul 26 22:26:32 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:32 cube kernel: ata1: SATA link down (SStatus 0 SControl 310)
Jul 26 22:26:32 cube kernel: zio pool=zz vdev=/dev/disk/by-id/ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 error=5 type=5 offset=0 size=0 flags=100480
Jul 26 22:26:32 cube kernel: zio pool=zz vdev=/dev/disk/by-id/ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 error=5 type=5 offset=0 size=0 flags=100480
Jul 26 22:26:32 cube kernel: zio pool=zz vdev=/dev/disk/by-id/ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 error=5 type=5 offset=0 size=0 flags=100480
Jul 26 22:26:32 cube kernel: zio pool=zz vdev=/dev/disk/by-id/ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 error=5 type=5 offset=0 size=0 flags=100480
Jul 26 22:26:32 cube zed[12827]: eid=6 class=statechange pool='zz' vdev=ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 vdev_state=REMOVED
Jul 26 22:26:32 cube zed[12828]: eid=7 class=removed pool='zz' vdev=ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 vdev_state=REMOVED
Jul 26 22:26:32 cube zed[12963]: eid=8 class=config_sync pool='zz'
Jul 26 22:26:32 cube kernel: ata1: limiting SATA link speed to 1.5 Gbps
Jul 26 22:26:33 cube kernel: ata1: found unknown device (class 0)
Jul 26 22:26:38 cube kernel: ata1: link is slow to respond, please be patient (ready=0)
Jul 26 22:26:42 cube kernel: ata1: softreset failed (device not ready)
Jul 26 22:26:47 cube kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
Jul 26 22:26:47 cube kernel: ata1.00: supports DRM functions and may not be fully accessible
Jul 26 22:26:47 cube kernel: ata1.00: ATA-9: WDC WD100EZAZ-11TDBA0, 83.H0A83, max UDMA/133
Jul 26 22:26:48 cube kernel: ata1.00: 19532873728 sectors, multi 0: LBA48 NCQ (depth 32), AA
Jul 26 22:26:49 cube kernel: ata1.00: Features: Trust NCQ-sndrcv NCQ-prio
Jul 26 22:26:49 cube kernel: ata1.00: supports DRM functions and may not be fully accessible
Jul 26 22:26:49 cube kernel: ata1.00: configured for UDMA/133
Jul 26 22:26:49 cube kernel: scsi 0:0:0:0: Direct-Access     ATA      WDC WD100EZAZ-11 0A83 PQ: 0 ANSI: 5
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: [sda] 19532873728 512-byte logical blocks: (10.0 TB/9.10 TiB)
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: [sda] 4096-byte physical blocks
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: [sda] Write Protect is off
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: [sda] Preferred minimum I/O size 4096 bytes
Jul 26 22:26:49 cube kernel:  sda: sda1 sda9
Jul 26 22:26:49 cube kernel: sd 0:0:0:0: [sda] Attached SCSI disk
Jul 26 22:26:49 cube zed[12992]: eid=9 class=statechange pool='zz' vdev=ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 vdev_state=ONLINE
Jul 26 22:26:49 cube zed[13004]: eid=10 class=vdev_online pool='zz' vdev=ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ-part1 vdev_state=ONLINE
Jul 26 22:26:50 cube zed[13132]: eid=11 class=resilver_start pool='zz'
Jul 26 22:26:50 cube zed[13347]: eid=14 class=resilver_finish pool='zz'
Jul 26 22:26:50 cube zed[13388]: eid=15 class=config_sync pool='zz'

and

$ zpool status
  pool: zz
 state: ONLINE
  scan: resilvered 312K in 00:00:00 with 0 errors on Fri Jul 26 22:26:50 2024
config:

	NAME                                      STATE     READ WRITE CKSUM
	zz                                        ONLINE       0     0     0
	  raidz2-0                                ONLINE       0     0     0
	    ata-WDC_WD100EZAZ-11TDBA0_2YJXT5ND    ONLINE       0     0     0
	    ata-TOSHIBA_MG07ACA12TE_X1B0A2MBF95G  ONLINE       0     0     0
	    ata-ST10000NM0016-1TT101_ZA2BT8TA     ONLINE       0     0     0
	    ata-WDC_WD100EZAZ-11TDBA0_1EGKNMYZ    ONLINE       0     0     0

errors: No known data errors

Since I have decided to reinstall this PC anyway, I can try a newer version, but it'll take a day or two.

[n0xena]

an array of HDDs might not be a good mix with suspension/hibernation - but it's very interesting that changing the driver for an unrelated device causes such issues
wonder how it's related?