High IO wait on qube start

I’ve got an intermittent issue with my system massively slowing down or hanging when I start a qube - usually sys-usb, sometimes sys-net, occasionally something else.

It’s possible this only happens after an unclean shutdown. I can reproduce it around 50% of the time by holding down the power button.

I’m not sure what fixes it. Sometimes I can hard-shutdown again, then do a clean reboot without starting any qubes, and then it’ll immediately be okay, but that doesn’t always work. Occasionally I’ve seen the wait times go away by themselves after many minutes, but again, sometimes not.

My diagnostics are pretty much limited to running top/vmstat in dom0. I generally can’t get a terminal or console in the affected qubes, and I don’t know what I’m doing with monitoring CPUs at the Xen level - xentop doesn’t seem to be useful in this context and I’m not sure what else there is. I recall looking at long-running blkdiscards with a previous issue, but that could have been a previous installation and I don’t remember where I was looking. There’s also nothing I can identify as obviously relevant in dmesg/journalctl.

I wouldn’t be surprised if it was a hardware issue - I’m on a Framework 11 Intel - but other than this and running a bit hot with some applications, it seems to be doing okay.

sys-net and sys-usb are both disposable. I also created a separate disposable sys-usb2 dedicated to specific PCI devices and get the same problem with that. They’re both configured without strict PCI reset.

Investigating further needs dedicated testing time - since when the issue happens, I typically lose the following hour to recovery attempts and it’s my daily driver.

Appreciate being pointed to any known issues (I’ve searched here but might have missed something), theories and diagnostic ideas. Thanks.

You can connect to the qube’s console using this command in dom0 terminal when it’s hanging to check what’s going on:

qvm-console-dispvm vmname

Or in Qube Manager Right mouse click on qube → Open console in qube.

The qube console’s included in what’s hanging, so I haven’t been able to access it when there’s a problem.

I’ve also checked files under /var/log/qubes but can’t see much logged at the relevant times.

Are you’re talking about qube’s terminal app or qube’s console specifically?
When connecting to qube’s console you at least should see the log of what was going on before it hanged.
qvm-console-dispvm is basically connecting to qube’s serial console that is accessible from xen using xl console from dom0, but running it in disposable instead.

The console specifically - I haven’t been able to access it.

Ah, more detail on that - I get what looks like the same behaviour now, when the system’s “good”.

A dispvm starts and immediately stops. I get a flash of a console and that’s it. No messages displayed when running qvm-console-dispvm from the terminal.

EDIT: this applies to sys-usb. sys-net I can now view the console for.

Maybe it’s a problem with PCI devices?
Do you have the same problem with qubes without PCI devices attached?
Try to reproduce the problem on HVM with netvm set to none and without PCI devices attached.

I’ve had one instance of hanging today that had no PCI devices attached (vpn-proxy ← sys-firewall ← sys-net).
sys-net and sys-usb are both set to HVM already.
I can try and reproduce the problem just with qubes with no PCI devices attached - it’ll be in a few hours.

I haven’t reproduced the problem with qubes with no PCI devices attached.
I’ve reproduced it with fresh disposable HVMs attached to the same PCI devices as sys-net and sys-usb (which are off). the USB controller seems worse - I think I’ve only seen the network vm fail directly after a USB vm failure.

Because of the system hanging, I usually can’t spin up new vms, which stops me accessing the console. I’ll keep trying this though.

I don’t have a reliable recovery method. I’m either hard-resetting and rebooting, or waiting.

Did you check the stubdom logs sys-net-dm.log and sys-usb-dm.log? Maybe there will be some info.
You can also check the Xen log with xl dmesg or check the /var/log/xen/console/hypervisor.log* files.

Good to know about those places to look, thanks.

I didn’t find anything differing there between good and bad boots. There are some warnings in zl dmesg about temperature and about nvme timeouts, but they don’t correlate with the problem.

It does seem to be the one USB PCI device linked to the issue. Unfortunately it’s coupled to the wifi in the BIOS so I can’t disable it and have a useful system.

I also reproduced the issue restarting after dual booting (which I’d like to move away from, but I want this and some other issues to go away first), so it’s not only unclean shutdowns that set it off.

Missed a bit of initial context:
This seems likely to be the same issue I’ve had since soon after my first Qubes install. Every so often, it would fail to reach the login screen after taking the disk password, and the console showed it was waiting for the initial qubes to start. I “fixed” that by stopping sys-usb booting automatically at startup.

The impact of not running sys-usb (or a smaller sys-usb with only the affected PCI devices attached) is not being able to use the built-in mic+camera, and whatever else is attached to that controller. It doesn’t affect connecting external USB devices to the extension modules.

I installed a service wrapping iotop and logging output into the default template and made sys-usb into an AppVM, then left it to recover overnight. That wasn’t too painful, so I could try logging from other tools if there are suggestions.

It did recover overnight.

No smoking gun in the iotop output. I wonder where the wait time’s coming from, then. Previously I’d managed to run vmstat inside sys-usb and confirmed it was seeing a constant 99% wait.

In dom0 the idle:wait ratio varies during the issue - it’s always around one of 25:75, 50:50, 75:25. I’m on 4 cores and sys-usb only has 2 allocated, so maybe there’s something I could try with CPU affinity, or it’s some shared resource in constant use like the nmve disk.

Some more details from using iostat on the vm and vmstat disk stats on dom0 this time (this has more features than I remember). Took about 30mins to recover.

In short, there’s constantly high iowait, but iostat shows that none of the block devices is reading or writing at a remotely high rate - tops out around 3MB/s and generally much lower.

From vmstat on dom0, the four affected block devices are the root+private snap LVs for sys-usb, and the tdata+tmeta LVs from the containing thin pool.

As I had a clear event window and a recovery I went collecting data from other sources again:
sys-usb journal:

wireplumber[663]: Failed to get percentage from UPower: org.freedesktop.DBus.E>
wireplumber[663]: GetManagedObjects() failed: org.freedesktop.DBus.Error.NameH>
gnome-keyring-daemon[891]: couldn't access control socket: /run/user/1000/keyr>
gnome-keyring-daemon[891]: discover_other_daemon: 0
gnome-keyring-daemon[897]: discover_other_daemon: 1
gnome-keyring-daemon[918]: discover_other_daemon: 1

otherwise only sysstat service entries every 10 mins.

Nothing in hypervisor.log, qpm-proxy-sys-usb-dm.log, guest-sys-usb.log appears to be the local journal again.

Dom0 journal and dmesg contain dom0 kernel: nvme nvme0: I/O 112 QID 2 timeout, completion polled messages only during the problem window. The journal also contains dom0 libvirtd[1985]: internal error: connection closed due to keepalive timeout messages in the same window. The only other thing I can see is, before the window: dom0 libvirtd[1985]: internal error: Unable to reset PCI device 0000:00:14.0: no FLR, PM reset or bus reset available.

Dom0 dmesg errors and warnings at system boot:

hid_bpf: error while preloading HID BPF dispatcher: -22
cros-usbpd-charger cros-usbpd-charger.5.auto: Unexpected number of charge port count
cros-usbpd-charger: probe of cros-usbpd-charger.5.auto failed with error -71
systemd-journald[980]: File /var/log/journal/8bcfec70b8704873845cadb0a1178a15/user-1000.journal corrupted or uncleanly shut down, renaming and replacing.

So now I’m wondering how to pin down what the NVMe/LVM devices are doing. The “completion polled” message I couldn’t find any details on. I can’t see anything concrete saying it’s a hardware issue yet, but I’d take ideas about trying to replicate the issue on a live boot of some other OS.

Try to disable SMT in BIOS.
If it won’t help then try to change storage mode in bios to AHCI from RAID or disable VMD.

It’s worth giving the kernel-latest and kernel-latest-qubes-vm dom0 packages a try if you haven’t already.

I went to town in the BIOS, didn’t manage to get rid of the issue.
SMT - hyperthreading was enabled, so disabled it.
AHCI - couldn’t find anything, not sure it applies to my NVMe, and generally couldn’t find much about the storage.
VMD - again, couldn’t find anything.
I toggled several of the Intel-specific things I could see like turbo boost, speedstep, speed shift, and more or less anything else I could find.

I’ve been on Linux fedora-38-xfce 6.6.9-1.qubes.fc37.x86_64 #1 SMP PREEMPT_DYNAMIC Sun Jan 7 17:14:59 GMT 2024 x86_64 GNU/Linux (via those dom0 packages) for maybe a month. Fairly sure I had the (same) problem with sys-usb not starting at boot with the non-latest kernels before that.

I’m going to do some stress benchmarking of the NVMe drive from a couple of different contexts but for interest rather than expecting to find anything. I think I’m out of ideas for today.

The current-testing repo has 6.8.4. Probably won’t make a difference anyway, but who knows?

1 Like

Do you have RAID device in lspci output in dom0?

lspci | grep -i RAID

I’m not sure it’s related to your problem but I remember some posts about the same nvme errors appearing if RAID was enabled.

No output to that command and I don’t recall seeing anything about RAID for this machine. Nothing in the BIOS.

I’m currently looking at bumping to the 6.8 kernel branch. Using qubes-dom0-update --enablerepo=qubes-dom0-current-testing kernel-latest kernel-latest-qubes-vm it seems to be downloading the right version but not installing. Maybe I need to disable the other repo where it gets these names.