Windows Server 2019 - vioscsi Warning (129) - locking up data drive

[spaceEATER]

Hello all,

Having a problem with the data drive on a Windows 2019 system. It will work perfectly fine for 30 minutes or even up to 4 hours, then I will begin to have vioscsi warnings, then the drive will just lock up completely, requiring a reboot to come back online.

The system is a supermicro board with an integrated LSI3008 (used for HDDs) - which has been flashed to IT firmware, it also has an onboard C622 controller which is used in ACHI mode for an SSD array.
The VM in question has 2 disks, one on a ZFS Raid10 (SSD) for boot, and the data drive is also a ZFS Raid10 (HDD).
The disk on the SSD array does not seem to have any issues, whereas all the issues are with the large disk on the HDD array.

The initial entry in event viewer is always:

Reset to device, \Device\RaidPort1, was issued.

If I leave the system alone, windows event viewer also presents a couple other entries:

The IO operation at logical block address 0x8e4fc7618 for Disk 1 (PDO name: \Device\0000002d) was retried.

The system failed to flush data to the transaction log. Corruption may occur in VolumeId: D:, DeviceName: \Device\HarddiskVolume6.
(The I/O device reported an I/O error.)

The problem was really bad with latest virtio drivers, so I downgraded to version 204, as per: https://github.com/virtio-win/kvm-guest-drivers-windows/issues/623

After the downgrade, the problem did not immediately return in the 30-45 minute window, but did after 2 hours.

Hopefully this is useful data:

root@pve:~# zfs list
NAME                        USED  AVAIL     REFER  MOUNTPOINT
RECpool-zfs                29.6T  19.4T       96K  /RECpool-zfs
RECpool-zfs/vm-101-disk-0  29.6T  19.4T     29.6T  -
Tnvme-zfs                  1.32M   231G       96K  /Tnvme-zfs
rpool                      60.4G   397G      104K  /rpool
rpool/ROOT                 6.99G   397G       96K  /rpool/ROOT
rpool/ROOT/pve-1           6.99G   397G     6.99G  /
rpool/data                 53.4G   397G       96K  /rpool/data
rpool/data/vm-101-disk-0    152K   397G      152K  -
rpool/data/vm-101-disk-1   53.4G   397G     53.4G  -
root@pve:~# zpool list
NAME          SIZE  ALLOC   FREE  CKPOINT  EXPANDSZ   FRAG    CAP  DEDUP    HEALTH  ALTROOT
RECpool-zfs  49.1T  29.6T  19.5T        -         -     0%    60%  1.00x    ONLINE  -
Tnvme-zfs     238G  1.32M   238G        -         -     0%     0%  1.00x    ONLINE  -
rpool         472G  60.5G   412G        -         -     7%    12%  1.00x    ONLINE  -
root@pve:~# df -h
Filesystem        Size  Used Avail Use% Mounted on
udev               32G     0   32G   0% /dev
tmpfs             6.3G  1.6M  6.3G   1% /run
rpool/ROOT/pve-1  404G  7.0G  397G   2% /
tmpfs              32G   49M   32G   1% /dev/shm
tmpfs             5.0M     0  5.0M   0% /run/lock
Tnvme-zfs         231G  128K  231G   1% /Tnvme-zfs
rpool             397G  128K  397G   1% /rpool
rpool/ROOT        397G  128K  397G   1% /rpool/ROOT
rpool/data        397G  128K  397G   1% /rpool/data
RECpool-zfs        20T  128K   20T   1% /RECpool-zfs
/dev/fuse         128M   16K  128M   1% /etc/pve
tmpfs             6.3G     0  6.3G   0% /run/user/0
root@pve:~# qm show 101
/usr/bin/kvm -id 101 -name 'ACS,debug-threads=on' -no-shutdown -chardev 'socket,id=qmp,path=/var/run/qemu-server/101.qmp,server=on,wait=off' -mon 'chardev=qmp,mode=control' -chardev 'socket,id=qmp-event,path=/var/run/qmeventd.sock,reconnect=5' -mon 'chardev=qmp-event,mode=control' -pidfile /var/run/qemu-server/101.pid -daemonize -smbios 'type=1,uuid=c94c05e9-315b-427f-8913-b8d29c474d70' -drive 'if=pflash,unit=0,format=raw,readonly=on,file=/usr/share/pve-edk2-firmware//OVMF_CODE_4M.fd' -drive 'if=pflash,unit=1,id=drive-efidisk0,format=raw,file=/dev/zvol/rpool/data/vm-101-disk-0,size=540672' -smp '16,sockets=1,cores=16,maxcpus=16' -nodefaults -boot 'menu=on,strict=on,reboot-timeout=1000,splash=/usr/share/qemu-server/bootsplash.jpg' -vnc 'unix:/var/run/qemu-server/101.vnc,password=on' -no-hpet -cpu 'kvm64,+aes,enforce,hv_ipi,hv_relaxed,hv_reset,hv_runtime,hv_spinlocks=0x1fff,hv_stimer,hv_synic,hv_time,hv_vapic,hv_vpindex,+kvm_pv_eoi,+kvm_pv_unhalt,+lahf_lm,+sep' -m 16384 -object 'iothread,id=iothread-virtioscsi0' -object 'iothread,id=iothread-virtioscsi1' -device 'pci-bridge,id=pci.1,chassis_nr=1,bus=pci.0,addr=0x1e' -device 'pci-bridge,id=pci.2,chassis_nr=2,bus=pci.0,addr=0x1f' -device 'pci-bridge,id=pci.3,chassis_nr=3,bus=pci.0,addr=0x5' -device 'vmgenid,guid=42e96f7f-d469-4ac4-a392-662c8ff902fb' -device 'piix3-usb-uhci,id=uhci,bus=pci.0,addr=0x1.0x2' -device 'usb-tablet,id=tablet,bus=uhci.0,port=1' -device 'vfio-pci,host=0000:67:00.0,id=hostpci0,bus=pci.0,addr=0x10' -device 'VGA,id=vga,bus=pci.0,addr=0x2' -chardev 'socket,path=/var/run/qemu-server/101.qga,server=on,wait=off,id=qga0' -device 'virtio-serial,id=qga0,bus=pci.0,addr=0x8' -device 'virtserialport,chardev=qga0,name=org.qemu.guest_agent.0' -iscsi 'initiator-name=iqn.1993-08.org.debian:01:ef828b78221' -device 'virtio-scsi-pci,id=virtioscsi0,bus=pci.3,addr=0x1,iothread=iothread-virtioscsi0' -drive 'file=/dev/zvol/rpool/data/vm-101-disk-1,if=none,id=drive-scsi0,discard=on,format=raw,cache=none,aio=io_uring,detect-zeroes=unmap' -device 'scsi-hd,bus=virtioscsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0,id=scsi0,rotation_rate=1,bootindex=100' -device 'virtio-scsi-pci,id=virtioscsi1,bus=pci.3,addr=0x2,iothread=iothread-virtioscsi1' -drive 'file=/dev/zvol/RECpool-zfs/vm-101-disk-0,if=none,id=drive-scsi1,format=raw,cache=none,aio=io_uring,detect-zeroes=on' -device 'scsi-hd,bus=virtioscsi1.0,channel=0,scsi-id=0,lun=1,drive=drive-scsi1,id=scsi1' -netdev 'type=tap,id=net0,ifname=tap101i0,script=/var/lib/qemu-server/pve-bridge,downscript=/var/lib/qemu-server/pve-bridgedown,vhost=on' -device 'virtio-net-pci,mac=B2:B9:CB:0F:BF:9E,netdev=net0,bus=pci.0,addr=0x12,id=net0,rx_queue_size=1024,tx_queue_size=1024,bootindex=101' -rtc 'driftfix=slew,base=localtime' -machine 'type=pc-i440fx-7.1+pve0' -global 'kvm-pit.lost_tick_policy=discard'

Package Versions:

proxmox-ve: 7.3-1 (running kernel: 5.15.83-1-pve)
pve-manager: 7.3-3 (running version: 7.3-3/c3928077)
pve-kernel-helper: 7.3-2
pve-kernel-5.15: 7.3-1
pve-kernel-5.15.83-1-pve: 5.15.83-1
pve-kernel-5.15.74-1-pve: 5.15.74-1
ceph-fuse: 15.2.17-pve1
corosync: 3.1.7-pve1
criu: 3.15-1+pve-1
glusterfs-client: 9.2-1
ifupdown2: 3.1.0-1+pmx3
ksm-control-daemon: 1.4-1
libjs-extjs: 7.0.0-1
libknet1: 1.24-pve2
libproxmox-acme-perl: 1.4.2
libproxmox-backup-qemu0: 1.3.1-1
libpve-access-control: 7.2-5
libpve-apiclient-perl: 3.2-1
libpve-common-perl: 7.3-1
libpve-guest-common-perl: 4.2-3
libpve-http-server-perl: 4.1-5
libpve-storage-perl: 7.3-1
libspice-server1: 0.14.3-2.1
lvm2: 2.03.11-2.1
lxc-pve: 5.0.0-3
lxcfs: 4.0.12-pve1
novnc-pve: 1.3.0-3
proxmox-backup-client: 2.3.1-1
proxmox-backup-file-restore: 2.3.1-1
proxmox-mini-journalreader: 1.3-1
proxmox-widget-toolkit: 3.5.3
pve-cluster: 7.3-1
pve-container: 4.4-2
pve-docs: 7.3-1
pve-edk2-firmware: 3.20220526-1
pve-firewall: 4.2-7
pve-firmware: 3.6-2
pve-ha-manager: 3.5.1
pve-i18n: 2.8-1
pve-qemu-kvm: 7.1.0-4
pve-xtermjs: 4.16.0-1
qemu-server: 7.3-2
smartmontools: 7.2-pve3
spiceterm: 3.2-2
swtpm: 0.8.0~bpo11+2
vncterm: 1.7-1
zfsutils-linux: 2.1.7-pve3

I may try version 215 of the virtio drivers, as per here: https://github.com/virtio-win/kvm-guest-drivers-windows/issues/756

Interestingly (or not) "df -h" shows a different capacity than on "zfs list" or "zpool list" - whereas the capacities for rpool match.
I admit I'm not well-versed enough to know if this means anything or not, but it did make me wonder.

I've seen a couple posts about downgrading the proxmox kernel, but I'm not sure how that will ultimately help?

But this is quite frustrating. I'm really at a loss, not sure where to go from here.

Thank you for any and all help.

 

[Chris]

Hi,
are there any errors in the systemd journal around the time when the IO errors arise in the Windows VM? Check journalctl -r -b

 

[spaceEATER]

Only obvious error around the time of issues is:
Jan 31 15:22:41 pve pveproxy[3088156]: got inotify poll request in wrong process - disabling inotify

But then interestingly during boot I found:

Jan 31 08:51:10 pve systemd[1]: Reached target Local File Systems.
Jan 31 08:51:10 pve systemd[1]: Finished Mount ZFS filesystems.
Jan 31 08:51:09 pve systemd[1]: Reached target ZFS volumes are ready.
Jan 31 08:51:09 pve systemd[1]: Finished Wait for ZFS Volume (zvol) links in /dev.
Jan 31 08:51:09 pve zvol_wait[3884]: All zvol links are now present.
Jan 31 08:51:09 pve zvol_wait[3884]: Testing 3 zvol links
Jan 31 08:51:09 pve systemd[1]: Starting Wait for ZFS Volume (zvol) links in /dev...
Jan 31 08:51:09 pve systemd[1]: Starting Mount ZFS filesystems...
Jan 31 08:51:09 pve systemd[1]: Reached target ZFS pool import target.
Jan 31 08:51:09 pve systemd[1]: Finished Import ZFS pools by cache file.
Jan 31 08:51:09 pve kernel:  zd32: p1 p2
Jan 31 08:51:09 pve systemd[1]: Finished Import ZFS pool Tnvme\x2dzfs.
Jan 31 08:51:02 pve systemd[1]: Failed to start Import ZFS pool RECpool\x2dzfs.
Jan 31 08:51:02 pve systemd[1]: zfs-import@RECpool\x2dzfs.service: Failed with result 'exit-code'.
Jan 31 08:51:02 pve systemd[1]: zfs-import@RECpool\x2dzfs.service: Main process exited, code=exited, status=1/FAILURE
Jan 31 08:51:02 pve zpool[2616]: cannot import 'RECpool-zfs': no such pool available
Jan 31 08:51:02 pve systemd[1]: Failed to start Import ZFS pool TEMPvme\x2dpool.
Jan 31 08:51:02 pve systemd[1]: zfs-import@TEMPvme\x2dpool.service: Failed with result 'exit-code'.
Jan 31 08:51:02 pve systemd[1]: zfs-import@TEMPvme\x2dpool.service: Main process exited, code=exited, status=1/FAILURE
Jan 31 08:51:02 pve zpool[2617]: cannot import 'TEMPvme-pool': no such pool available
Jan 31 08:51:02 pve kernel: power_meter ACPI000D:00: Ignoring unsafe software power cap!
Jan 31 08:51:02 pve kernel: power_meter ACPI000D:00: Found ACPI power meter.
Jan 31 08:51:02 pve systemd[1]: Starting Import ZFS pool Tnvme\x2dzfs...
Jan 31 08:51:02 pve systemd[1]: Starting Import ZFS pool TEMPvme\x2dpool...
Jan 31 08:51:02 pve systemd[1]: Starting Import ZFS pool RECpool\x2dzfs...
Jan 31 08:51:02 pve systemd[1]: Condition check resulted in Import ZFS pools by device scanning being skipped.
Jan 31 08:51:02 pve systemd[1]: Starting Import ZFS pools by cache file...
Jan 31 08:51:02 pve systemd[1]: Finished Wait for udev To Complete Device Initialization.
Jan 31 08:51:02 pve systemd[1]: Finished Helper to synchronize boot up for ifupdown.
Jan 31 08:51:01 pve kernel: power_meter ACPI000D:00: hwmon_device_register() is deprecated. Please convert the driver to use hwmon_device_register_with_info().
Jan 31 08:51:01 pve kernel: power_meter ACPI000D:00: Found ACPI power meter.

the TEMPvme-pool was removed, not sure why it's still trying to import/mount it?

And it's saying that it's failing to import RECpool, but it's very much there, and very much working (except for Window Server's error).

But then again, it's also not throwing errors when ZED launches:

Jan 31 08:51:10 pve systemd[1]: Reached target ZFS startup target.
Jan 31 08:51:10 pve systemd[1]: Finished ZFS file system shares.
Jan 31 08:51:10 pve smartd[4017]: Configuration file /etc/smartd.conf was parsed, found DEVICESCAN, scanning devices
Jan 31 08:51:10 pve smartd[4017]: Drive: DEVICESCAN, implied '-a' Directive on line 21 of file /etc/smartd.conf
Jan 31 08:51:10 pve smartd[4017]: Opened configuration file /etc/smartd.conf
Jan 31 08:51:10 pve smartd[4017]: Copyright (C) 2002-20, Bruce Allen, Christian Franke, www.smartmontools.org
Jan 31 08:51:10 pve smartd[4017]: smartd 7.2 2020-12-30 r5155 [x86_64-linux-5.15.83-1-pve] (local build)
Jan 31 08:51:10 pve zed[4104]: eid=15 class=config_sync pool='RECpool-zfs'
Jan 31 08:51:10 pve zed[4103]: eid=13 class=config_sync pool='Tnvme-zfs'
Jan 31 08:51:10 pve zed[4101]: eid=12 class=pool_import pool='RECpool-zfs'
Jan 31 08:51:10 pve zed[4099]: eid=11 class=config_sync pool='RECpool-zfs'
Jan 31 08:51:10 pve zed[4089]: eid=8 class=pool_import pool='Tnvme-zfs'
Jan 31 08:51:10 pve zed[4085]: eid=7 class=config_sync pool='Tnvme-zfs'
Jan 31 08:51:10 pve zed[4082]: eid=5 class=config_sync pool='rpool'
Jan 31 08:51:10 pve zed[4072]: eid=3 class=pool_import pool='rpool'
Jan 31 08:51:10 pve zed[4069]: eid=2 class=config_sync pool='rpool'
Jan 31 08:51:10 pve dbus-daemon[3998]: [system] AppArmor D-Bus mediation is enabled
Jan 31 08:51:10 pve zed[4046]: Processing events since eid=0
Jan 31 08:51:10 pve zed[4046]: ZFS Event Daemon 2.1.7-pve3 (PID 4046)
Jan 31 08:51:10 pve kernel: softdog:              soft_reboot_cmd=<not set> soft_active_on_boot=0
Jan 31 08:51:10 pve kernel: softdog: initialized. soft_noboot=0 soft_margin=60 sec soft_panic=0 (nowayout=0)
Jan 31 08:51:10 pve systemd[1]: Started PVE Qemu Event Daemon.
Jan 31 08:51:10 pve systemd[1]: Started Kernel Samepage Merging (KSM) Tuning Daemon.
Jan 31 08:51:10 pve systemd[1]: Finished Remove Stale Online ext4 Metadata Check Snapshots.
Jan 31 08:51:10 pve systemd[1]: e2scrub_reap.service: Succeeded.
Jan 31 08:51:10 pve systemd[1]: Started System Logging Service.
Jan 31 08:51:10 pve watchdog-mux[4040]: Watchdog driver 'Software Watchdog', version 0
Jan 31 08:51:10 pve rsyslogd[4010]: [origin software="rsyslogd" swVersion="8.2102.0" x-pid="4010" x-info="https://www.rsyslog.com"] start
Jan 31 08:51:10 pve rsyslogd[4010]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2102.0]
Jan 31 08:51:10 pve systemd[1]: Started Proxmox VE LXC Syscall Daemon.
Jan 31 08:51:10 pve systemd[1]: Started ZFS Event Daemon (zed).
Jan 31 08:51:10 pve systemd[1]: Starting ZFS file system shares...

 

[spaceEATER]

Couple more pieces of info that were requested on the reddit discussion:

After normal boot log (/var/log/kern.log), these are the only lines:

Jan 31 12:56:54 pve kernel: [14761.021171] perf: interrupt took too long (2550 > 2500), lowering kernel.perf_event_max_sample_rate to 78250
Jan 31 15:51:43 pve kernel: [25249.668493]  zd16: p1 p2 p3 p4
Jan 31 15:51:43 pve kernel: [25249.799350]  zd32: p1 p2
Jan 31 15:51:43 pve kernel: [25249.988458] vmbr0: port 2(tap101i0) entered disabled state
Jan 31 15:52:23 pve kernel: [25289.881284] device tap101i0 entered promiscuous mode
Jan 31 15:52:23 pve kernel: [25289.901250] vmbr0: port 2(tap101i0) entered blocking state
Jan 31 15:52:23 pve kernel: [25289.901254] vmbr0: port 2(tap101i0) entered disabled state
Jan 31 15:52:23 pve kernel: [25289.901369] vmbr0: port 2(tap101i0) entered blocking state
Jan 31 15:52:23 pve kernel: [25289.901371] vmbr0: port 2(tap101i0) entered forwarding state
Jan 31 15:56:26 pve kernel: [25532.365660]  zd16: p1 p2 p3 p4
Jan 31 15:56:26 pve kernel: [25532.626135]  zd32: p1 p2
Jan 31 15:56:26 pve kernel: [25532.845744] vmbr0: port 2(tap101i0) entered disabled state
Jan 31 15:57:12 pve kernel: [25578.584443] device tap101i0 entered promiscuous mode
Jan 31 15:57:12 pve kernel: [25578.602429] vmbr0: port 2(tap101i0) entered blocking state
Jan 31 15:57:12 pve kernel: [25578.602433] vmbr0: port 2(tap101i0) entered disabled state
Jan 31 15:57:12 pve kernel: [25578.602557] vmbr0: port 2(tap101i0) entered blocking state
Jan 31 15:57:12 pve kernel: [25578.602559] vmbr0: port 2(tap101i0) entered forwarding state
Jan 31 16:01:14 pve kernel: [25820.379477] perf: interrupt took too long (3196 > 3187), lowering kernel.perf_event_max_sample_rate to 62500
Jan 31 17:35:39 pve kernel: [31485.839830]  zd16: p1 p2 p3 p4
Jan 31 17:35:42 pve kernel: [31489.070319] vmbr0: port 2(tap101i0) entered disabled state
Jan 31 17:35:44 pve kernel: [31490.328895]  zd32: p1 p2
Jan 31 17:35:47 pve kernel: [31493.868753] device tap101i0 entered promiscuous mode
Jan 31 17:35:47 pve kernel: [31493.888641] vmbr0: port 2(tap101i0) entered blocking state
Jan 31 17:35:47 pve kernel: [31493.888645] vmbr0: port 2(tap101i0) entered disabled state
Jan 31 17:35:47 pve kernel: [31493.888765] vmbr0: port 2(tap101i0) entered blocking state
Jan 31 17:35:47 pve kernel: [31493.888767] vmbr0: port 2(tap101i0) entered forwarding state
Jan 31 21:29:20 pve kernel: [45506.750988] perf: interrupt took too long (4054 > 3995), lowering kernel.perf_event_max_sample_rate to 49250

And then the output of zpool status:

  pool: RECpool-zfs
 state: ONLINE
config:

        NAME                                    STATE     READ WRITE CKSUM
        RECpool-zfs                             ONLINE       0     0     0
          mirror-0                              ONLINE       0     0     0
            ata-WDC_WD180EDGZ-11B2DA0_*SERIALNUMBER*  ONLINE       0     0     0
            ata-WDC_WD180EDGZ-11B2DA0_*SERIALNUMBER*  ONLINE       0     0     0
          mirror-1                              ONLINE       0     0     0
            ata-WDC_WD180EDGZ-11B2DA0_*SERIALNUMBER*  ONLINE       0     0     0
            ata-WDC_WD180EDGZ-11B2DA0_*SERIALNUMBER*  ONLINE       0     0     0
          mirror-2                              ONLINE       0     0     0
            ata-WDC_WD180EDGZ-11B2DA0_*SERIALNUMBER*  ONLINE       0     0     0
            ata-WDC_WD180EDGZ-11B2DA0_*SERIALNUMBER*  ONLINE       0     0     0

errors: No known data errors

  pool: Tnvme-zfs
 state: ONLINE
config:

        NAME                                                STATE     READ WRITE CKSUM
        Tnvme-zfs                                           ONLINE       0     0     0
          nvme-KBG40ZNS256G_NVMe_KIOXIA_256GB_*SERIALNUMBER*  ONLINE       0     0     0

errors: No known data errors

  pool: rpool
 state: ONLINE
config:

        NAME                                                     STATE     READ WRITE CKSUM
        rpool                                                    ONLINE       0     0     0
          mirror-0                                               ONLINE       0     0     0
            ata-Samsung_SSD_860_PRO_256GB_*SERIALNUMBER*-part3  ONLINE       0     0     0
            ata-Samsung_SSD_860_PRO_256GB_*SERIALNUMBER*-part3  ONLINE       0     0     0
          mirror-1                                               ONLINE       0     0     0
            ata-Samsung_SSD_860_PRO_256GB_*SERIALNUMBER*-part3  ONLINE       0     0     0
            ata-Samsung_SSD_860_PRO_256GB_*SERIALNUMBER*-part3  ONLINE       0     0     0

errors: No known data errors

 

[Chris]

the TEMPvme-pool was removed, not sure why it's still trying to import/mount it?

This is probably because there is still the systemd service trying to import it hanging around, try to disable it systemctl disable --now zfs-import@TEMPvme\x2dpool.service.
Regarding the other pool I suspect it to be imported via the zfs-scan service, since the import via cache file fails? What is the output of systemctl status zfs-import.target zfs-import-scan.service zfs-import-cache.service?

Regarding your Windows VM problem: Is this error in the Windows VM related to a high IO event on the pool? Any backups running around the time when this happens? If there is a backup, you might consider to limit it's bandwidth to get rid of an IO bottleneck.
According to the bug report you posted in your initial comment, this is probably related to such an event.

Have you tried to switch from AIO io_uring to native and checked if a cache setting on the VM has influence on the behavior?

 

[spaceEATER]

What is the output of systemctl status zfs-import.target zfs-import-scan.service zfs-import-cache.service?

root@pve:~# systemctl status zfs-import.target zfs-import-scan.service zfs-import-cache.service
● zfs-import.target - ZFS pool import target
     Loaded: loaded (/lib/systemd/system/zfs-import.target; enabled; vendor preset: enabled)
     Active: active since Tue 2023-01-31 08:51:09 PST; 1 day 23h ago

Jan 31 08:51:09 pve systemd[1]: Reached target ZFS pool import target.

● zfs-import-scan.service - Import ZFS pools by device scanning
     Loaded: loaded (/lib/systemd/system/zfs-import-scan.service; enabled; vendor preset: disabled)
     Active: inactive (dead)
  Condition: start condition failed at Tue 2023-01-31 08:51:02 PST; 1 day 23h ago
       Docs: man:zpool(8)

Jan 31 08:51:02 pve systemd[1]: Condition check resulted in Import ZFS pools by device scanning being skipped.

● zfs-import-cache.service - Import ZFS pools by cache file
     Loaded: loaded (/lib/systemd/system/zfs-import-cache.service; enabled; vendor preset: enabled)
     Active: active (exited) since Tue 2023-01-31 08:51:09 PST; 1 day 23h ago
       Docs: man:zpool(8)
   Main PID: 2615 (code=exited, status=0/SUCCESS)
      Tasks: 0 (limit: 76687)
     Memory: 0B
        CPU: 0
     CGroup: /system.slice/zfs-import-cache.service

Regarding your Windows VM problem: Is this error in the Windows VM related to a high IO event on the pool? Any backups running around the time when this happens? If there is a backup, you might consider to limit it's bandwidth to get rid of an IO bottleneck.
According to the bug report you posted in your initial comment, this is probably related to such an event.

There are a lot of writes to the disk, but if anything, they are highest when the server starts, and are like that for about 10 minutes, and then they go down to maybe average around 4-8MB/s.
Any high sustained load (~80MB/s) is finished within the first 10 minutes or so.

Have you tried to switch from AIO io_uring to native and checked if a cache setting on the VM has influence on the behavior?

When problems began, I initially disabled cache (after having it one write-back, per the recommended windows practices), and it seemed like performance actually improved, I have since left that.

I've just now set the AIO to native, but left cache untouched (disabled).

If it's potentially an IO problem from all the writes, could be the case where an nvme SLOG would be beneficial?

 

[Chris]

Okay, so from the output it seems that the pools are all imported by cache file, which is fine.

Reading trough this [0] MS Blog post I suspect the timeout value in the SRB might be to low, could you check what values are configured in the registry. Maybe the registry value is not the default anymore?

If it's potentially an IO problem from all the writes, could be the case where an nvme SLOG would be beneficial?

What software are you running within the VM? A SLOG is only really usefull for IO loads with sync writes.

[0] https://learn.microsoft.com/en-us/a...tanding-storage-timeouts-and-event-129-errors

 

[Chris]

Followup: if the HKLM\System\CurrentControlSet\Services\Disk\TimeOutValue is not set, the default is 10 seconds according to https://learn.microsoft.com/en-us/w...ge/registry-entries-for-scsi-miniport-drivers

 

[spaceEATER]

Okay, so from the output it seems that the pools are all imported by cache file, which is fine.

Reading trough this [0] MS Blog post I suspect the timeout value in the SRB might be to low, could you check what values are configured in the registry. Maybe the registry value is not the default anymore?

[0] https://learn.microsoft.com/en-us/a...tanding-storage-timeouts-and-event-129-errors

Followup: if the HKLM\System\CurrentControlSet\Services\Disk\TimeOutValue is not set, the default is 10 seconds according to https://learn.microsoft.com/en-us/w...ge/registry-entries-for-scsi-miniport-drivers

The TimeOutValue is set to 60, and the IoTimeoutValue is also set to 60.
Based on some posts on information from other platforms (VMware, in particular), this is the recommended value: https://docs.vmware.com/en/VMware-v...UID-EA1E1AAD-7130-457F-8894-70A63BD0623A.html

Considering I'm having these problems, it would seem counter-intuitive to set it back to the default (10), as it might just cause the errors to happen faster?
What would you suggest?

What software are you running within the VM? A SLOG is only really usefull for IO loads with sync writes.

It's primarily a CCTV system. I'm not aware whether it's sync or async writes (manual doesn't say), but I've contacted their support team to find out.

 

[Chris]

Considering I'm having these problems, it would seem counter-intuitive to set it back to the default (10), as it might just cause the errors to happen faster?
What would you suggest?

Well, you could verify that by setting the default (removing the custom value) the event occurs indeed more often. But yes, setting it lower is probably not the best shot.

It's primarily a CCTV system. I'm not aware whether it's sync or async writes (manual doesn't say), but I've contacted their support team to find out.

I would assume that for this cases the writes are mostly async, so no benefit from a SLOG for write performance.

 

[spaceEATER]

Well, it's still early, but changing the following settings has had a positive improvement (where the data drive has not locked up in 4 days):
- AIO -> "native"
- IO thread -> checked
- Cache -> "default"

I'm going to update the VirtIO drivers to the newest Stable release, and see what happens.

Still waiting to hear back from the CCTV software support team, but it currently seems as though the above settings have solved my issue.

Thanks for your help!

 

[spaceEATER]

I'm going to update the VirtIO drivers to the newest Stable release, and see what happens.

Well, that didn't go well.

Latest VirtIO drivers (0.1.229) re-introduced the original issue, at least in part.

For whatever reason, the event log was full of the same warnings/errors, but the machine didn't actually lock up.
The machine was noticeably slower than before, but it was still working.

I've now downgraded to version 215 of the VirtIO driver, and if the problems persist, I will go back to 204 which was working properly.

 

[MyThoughts]

Just ran into this exact issue.

Was using VirtIO drivers 0.1.229 and everything was fine and no issues until I added a 3rd virtual disk that was a local LVM mechanical HD.

I did not have any issue prior to adding this virtual disk and removing it would restore stability.

The virtual disks were as follows:

EFI -> on ZFS mirror (SSDs)
VirtIO SCSI0 -> on ZFS mirror (SSDs)
VirtIO SCSI1 -> on LVM-thin (SSD)
VirtIO SCSI2 -> on LVM-thin (HDD)

I downgraded the VirtIO SCSI driver within the VM (Windows 10 Pro 22H2) to v0.1.215 and the problem has not occurred since.

 

[spaceEATER]

I've really neglected updating this thread, so thanks for the bump, causing my email alerts.

Ultimately 0.1.215 was not the answer, nor was going back to 0.1.204.

Latest 0.1.229 has turned out to be the one to cause the least "catastrophic" errors when they do occur - in that, I'm still able to access the VM, and restart it. Other drivers would just completely lock up the system entirely.

On the topic of "error when they do occur" - I've found it odd, but (for me at least) the VM will work for ~6 days completely normally, then the errors will start up, and if left unchecked, eventually the secondary drive (the HDD pool) will then lock up.
Starting with old faithful:
Event 129 - vioscsi - Reset to device, \Device\RaidPort1, was issued.
Then adding these:
Event 140 - Ntfs (Microsoft-Windows-Ntfs) - The system failed to flush data to the transaction log. Corruption may occur in VolumeId: D:, DeviceName: \Device\HarddiskVolume6. (The I/O device reported an I/O error.)
And then finally adding these:
Event 153 - Disk - The IO operation at logical block address 0x1104d43a30 for Disk 1 (PDO name: \Device\0000002d) was retried.

Typically the disk errors will only start at least 1 hour after the viosci errors begin, which is when the drive locks up.
I haven't had the chance to try and flesh out a proper response to the github open issues I've linked, but perhaps one day I will.

My band-aid solution has been to create a scheduled task to reboot the server when Event 129 pops up in the System Log.
Obviously not an actual solution, but, it keeps me going at least.

 

[markusmaximus]

I've really neglected updating this thread, so thanks for the bump, causing my email alerts.

Ultimately 0.1.215 was not the answer, nor was going back to 0.1.204.

Latest 0.1.229 has turned out to be the one to cause the least "catastrophic" errors when they do occur - in that, I'm still able to access the VM, and restart it. Other drivers would just completely lock up the system entirely.

On the topic of "error when they do occur" - I've found it odd, but (for me at least) the VM will work for ~6 days completely normally, then the errors will start up, and if left unchecked, eventually the secondary drive (the HDD pool) will then lock up.
Starting with old faithful:
Event 129 - vioscsi - Reset to device, \Device\RaidPort1, was issued.
Then adding these:
Event 140 - Ntfs (Microsoft-Windows-Ntfs) - The system failed to flush data to the transaction log. Corruption may occur in VolumeId: D:, DeviceName: \Device\HarddiskVolume6. (The I/O device reported an I/O error.)
And then finally adding these:
Event 153 - Disk - The IO operation at logical block address 0x1104d43a30 for Disk 1 (PDO name: \Device\0000002d) was retried.

Typically the disk errors will only start at least 1 hour after the viosci errors begin, which is when the drive locks up.
I haven't had the chance to try and flesh out a proper response to the github open issues I've linked, but perhaps one day I will.

My band-aid solution has been to create a scheduled task to reboot the server when Event 129 pops up in the System Log.
Obviously not an actual solution, but, it keeps me going at least.

Try VirtIO Block instead of SCSI. I found better performance with that. I can pretty much force the crash with crystaldiskmark on scsi

 

[_gabriel]

why not try regular sata.
cctv doesn't require high perf

 

[davemcl]

Did you see any of the following in your host syslog

QEMU[2174]: kvm: virtio: zero sized buffers are not allowed

QEMU[2198]: kvm: Desc next is 3

 

[Max2048]

Same issue here, Had weeks without this message in my MSSQL 2019 Windows Server 2022 VM, now it's been happening every day. did anyone try out VirtIO Block instead of Virtio SCSI to see if it helps or found any other solution yet?

 

[davemcl]

I have done a few things which seemed to have reduced the occurrences, but not eliminated the issue.
- Im using SATA Enterprise SSD, RAID-10 based local storage
- VM is q35 with Virtio SCSI single controller
- Disks are No cache, Discard, IO Thread, Async is io_uring - separate disk for data, logs & tempdb
- Latest VirtIO drivers .229
Within the VM Ive set these 2 registry entries.
* HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\vioscsi\Parameters
IoTimeoutValue = 0x5a (90)

* HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\vioscsi\Parameters\Device
PhysicalBreaks = 0x3f (63)

Ive also tried all the kernels - 6.2 seems best for me but I dont think its getting updates in 7.4.
Fiona from Proxmox has referenced a fix in PVE8 but my upgrade failed and I had to rollback.

Have you tried the new PVE 8?

 

[Max2048]

No, didn't try PVE 8 yet and it's too fresh for production imho, but I'm thinking about switching the disks from type SCSI to SATA, honestly I'm fine with the lower performance this will cause. Does that make sense to work-around the problem or is it not working as I'm still having the VirtIO SCSI single controller in use?