QEMU/WSL: Boot slows to a crawl when WHPX acceleration is enabled

[1player]

I'm using the recommended settings from the WSL documentation:

export SERENITY_EXTRA_QEMU_ARGS="-accel whpx"
export SERENITY_QEMU_CPU="max,vmx=off"
export SERENITY_KERNEL_CMDLINE=disable_virtio

If I disable WHPX acceleration, everything works, if I enable it, as soon as the following message is printed in the console:

[#0 Kernel]: Framebuffer Console: taking 3145728 bytes

the boot process slows to a crawl, so much that following log messages are printed at ~10 characters per second, as if it were a very slow BBS modem. UHCI gets initialised, then E1000, then it seems to hang.

Using qemu 6.0.0 20210505

[gunnarbeutner]

I'm seeing the same problem here. Tested with QEMU 6.0.0, 5.2.0 and 5.1.0.

Windows version: Windows 10 21H1 (19043.1023)
CPU: AMD Ryzen 9 3900X 12-Core Processor

whpx.mp4

[ADKaster]

Works all right for me for Qemu 5.1.0, and 6.0.0 with the kernel-irqchip=off argument.

Windows 10 20H2, Build 19042.985
CPU: Intel(R) Core(TM) i7-8700K CPU @ 3.70GHz

without the kernel-irqchip=off argument, QEMU 6.0.0 hangs at

[init_stage2(2:2)]: UHCI: Interrupt line: 11
[#0 init_stage2(2:2)]: UHCI: Allocated framelist at physical address P0x00f1d000

But I'm not seeing the sudden regression to 9600 Baud (or less) on the serial console with these args

serenity$ env | grep SERENITY
SERENITY_QEMU_BIN=/mnt/c/Program Files/qemu-6/qemu-system-i386.exe
SERENITY_KERNEL_CMDLINE=disable_virtio
SERENITY_DISK_IMAGE=\\wsl$\Ubuntu\home\andrew\serenity\Build\i686\_disk_image
SERENITY_VIRT_TECH_ARG=-accel whpx,kernel-irqchip=off
SERENITY_QEMU_CPU=max,vmx=off

Where the qemu-system-i386.exe is from this exact version:

https://qemu.weilnetz.de/w64/2021/qemu-w64-setup-20210505.exe

Boot Log

[0/1] cd /home/andrew/serenity/Build/i686 && /home/andrew/serenity/Meta/run.sh
Windows Hypervisor Platform accelerator is operational
qemu-system-i386.exe: warning: '-soundhw pcspk' is deprecated, please set a backend using '-machine pcspk-audiodev=<name>' instead
[Kernel]: CPU[0]: Supported features: nx pae pge rdrand rdseed smap smep sse tsc rdtscp constant_tsc sep syscall mmx sse2 sse3 ssse3 sse4.1 sse4.2 xsave avx
[Kernel]: CPU[0]: Physical address bit width: 39
[#0 Kernel]: Initializing unhandled interrupt handlers
[Kernel]: Kernel Commandline: Kernel/Kernel disable_virtio
[Kernel]: MM: boot_pdpt @ P0x0010a000
[Kernel]: MM: boot_pd0 @ P0x0010b000
[Kernel]: MM: boot_pd3 @ P0x0010c000
[Kernel]: MM: Low memory range @ P0x00000000 - P0x00100000
[Kernel]: MM: Kernel range @ P0x00100000 - P0x0101d000
[Kernel]: MM: Multiboot mmap: address=0x00000000, length=654336, type=1
[Kernel]: MM: Got an unaligned physical_region from the bootloader; correcting length 654336 by 3072 bytes
[Kernel]: MM: Multiboot mmap: address=0x0009fc00, length=1024, type=2
[Kernel]: MM: Multiboot mmap: address=0x000f0000, length=65536, type=2
[Kernel]: MM: Multiboot mmap: address=0x00100000, length=535691264, type=1
[Kernel]: MM: Multiboot mmap: address=0x1ffe0000, length=131072, type=2
[Kernel]: MM: Multiboot mmap: address=0xfffc0000, length=262144, type=2
[Kernel]: MM: Super physical region: P0x00f1d000 - P0x0101d000
[Kernel]: MM: User physical region: P0x0101e000 - P0x1ffe0000
[Kernel]: MM: Contiguous reserved range from P0x0009fc00, length is 394240
[Kernel]: MM: Contiguous reserved range from P0x1ffe0000, length is 3758227456
[#0 Kernel]: Early access to ACPI tables for interrupt setup
[Kernel]: Interrupts: Switch to Legacy PIC mode
[Kernel]: PIC: Cascading mode, vectors 0x50-0x5f
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Interrupts: Detected Dual i8259
[Kernel]: ACPI: Using RSDP @ P0x000f5850
[Kernel]: ACPI: Main Description Table valid? true
[Kernel]: ACPI: Using RSDT, enumerating tables @ P0x1ffe3898
[Kernel]: ACPI: RSDT revision 1, total length: 52
[Kernel]: ACPI: Initializing Fixed ACPI data
[Kernel]: ACPI: Searching for the Fixed ACPI Data Table
[Kernel]: ACPI: Fixed ACPI data, Revision 1, length: 116 bytes
[Kernel]: ACPI: DSDT P0x1ffe0040
[Kernel]: ACPI: Dynamic Parsing Enabled, Can parse AML
[Kernel]: PCI: Using I/O instructions for PCI configuration space access
[Kernel]: PCI [0000:00:00:00] PCI::ID [8086:1237]
[Kernel]: PCI [0000:00:01:00] PCI::ID [8086:7000]
[Kernel]: PCI [0000:00:01:01] PCI::ID [8086:7010]
[Kernel]: PCI [0000:00:01:02] PCI::ID [8086:7020]
[Kernel]: PCI [0000:00:01:03] PCI::ID [8086:7113]
[Kernel]: PCI [0000:00:02:00] PCI::ID [1234:1111]
[Kernel]: PCI [0000:00:03:00] PCI::ID [1af4:1003]
[Kernel]: PCI [0000:00:04:00] PCI::ID [1af4:1005]
[Kernel]: PCI [0000:00:05:00] PCI::ID [1b36:0001]
[Kernel]: PCI [0000:01:00:00] PCI::ID [1000:0060]
[Kernel]: PCI [0000:01:01:00] PCI::ID [8086:244e]
[Kernel]: PCI [0000:02:00:00] PCI::ID [1b36:0007]
[Kernel]: PCI [0000:00:06:00] PCI::ID [8086:244e]
[Kernel]: PCI [0000:03:00:00] PCI::ID [1b36:0007]
[Kernel]: PCI [0000:03:01:00] PCI::ID [8086:2922]
[Kernel]: PCI [0000:00:07:00] PCI::ID [8086:100e]
[Kernel]: Starting SerenityOS...
[Kernel]: RTC: Year: 2021, month: 6, day: 1, hour: 11, minute: 42, second: 0
[Kernel]: HPET @ P0x1ffe3838
[Kernel]: HPET: Minimum clock tick - 0
[Kernel]: HPET: Timers count - 3
[Kernel]: HPET: Main counter size: 64-bit
[Kernel]: HPET: Timer[0] comparator size: 64-bit, mode: 64-bit
[Kernel]: HPET: Timer[1] comparator size: 64-bit, mode: 64-bit
[Kernel]: HPET: Timer[2] comparator size: 64-bit, mode: 64-bit
[Kernel]: HPET: frequency 100000000 Hz (100 MHz) resolution: 10 ns
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: HPET: Setting appropriate functions to timers.
[#0 Kernel]: Time: Scanning for periodic timers
[#0 Kernel]: Time: Scanning for non-periodic timers
[Kernel]: KernelRng: Using RDSEED or RDRAND as entropy source
[#0 Kernel]: I8042: Dual channel controller
[Kernel]: PS2MouseDevice: Mouse wheel enabled!
[Kernel]: PS2MouseDevice: 5 buttons enabled!
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Framebuffer Console: taking 3145728 bytes
[#0 Kernel]: BochsGraphicsAdapter: resolution set to 1024x768
[#0 Kernel]: Framebuffer Console: taking 3145728 bytes
[#0 Kernel]: Graphics adapter @ PCI [0000:00:02:00] is operating in VGA mode
[#0 Kernel]: Framebuffer 0: address=P0xf8000000, pitch=4096, width=1024, height=768
[#0 Kernel]: VC 0: Resized to 128 x 96
[#0 Kernel]: VC 1: Resized to 128 x 96
[#0 Kernel]: VC 2: Resized to 128 x 96
[#0 Kernel]: VC 3: Resized to 128 x 96
[#0 Kernel]: VC 4: Resized to 128 x 96
[#0 Kernel]: VC 5: Resized to 128 x 96
[#0 colonel(0:0)]: Scheduler[0]: idle loop running
[init_stage2(2:2)]: UHCI: Controller found PCI::ID [8086:7020] @ PCI [0000:00:01:02]
[init_stage2(2:2)]: UHCI: I/O base IO e080
[#0 SyncTask(3:3)]: SyncTask is running
[init_stage2(2:2)]: UHCI: Interrupt line: 11
[#0 init_stage2(2:2)]: UHCI: Allocated framelist at physical address P0x00f1d000
[#0 init_stage2(2:2)]: UHCI: Framelist is at virtual address V0xc23a5000
[#0 init_stage2(2:2)]: UHCI: QH(0xc23a7000) @ 15851520: link_ptr=15851554, element_link_ptr=1
[#0 init_stage2(2:2)]: UHCI: QH(0xc23a7020) @ 15851552: link_ptr=15851586, element_link_ptr=1
[#0 init_stage2(2:2)]: UHCI: QH(0xc23a7040) @ 15851584: link_ptr=15851618, element_link_ptr=1
[#0 init_stage2(2:2)]: UHCI: QH(0xc23a7060) @ 15851616: link_ptr=15851650, element_link_ptr=1
[#0 init_stage2(2:2)]: UHCI: QH(0xc23a7080) @ 15851648: link_ptr=15863809, element_link_ptr=1
[#0 init_stage2(2:2)]: UHCI: Reset completed
[#0 init_stage2(2:2)]: UHCI: Started
[#0 init_stage2(2:2)]: DMIExpose: SMBIOS 32bit Entry point @ P0x000f5870
[#0 init_stage2(2:2)]: DMIExpose: Data table @ P0x000f5890
[init_stage2(2:2)]: E1000: Found @ PCI [0000:00:07:00]
[init_stage2(2:2)]: E1000: port base: IO e040
[init_stage2(2:2)]: E1000: MMIO base: P0xfea40000
[init_stage2(2:2)]: E1000: MMIO base size: 131072 bytes
[init_stage2(2:2)]: E1000: Interrupt line: 11
[init_stage2(2:2)]: E1000: Has EEPROM? true
[init_stage2(2:2)]: E1000: MAC address: 52:54:00:12:34:56
[#0 init_stage2(2:2)]: Trying to unregister unused handler (?)
[init_stage2(2:2)]: SB16: Found version 4.5
[init_stage2(2:2)]: SB16: IRQ 5
[#0 init_stage2(2:2)]: IDE controller @ PCI [0000:00:01:01]: bus master base was set to IO e0c0
[#0 init_stage2(2:2)]: IDE controller @ PCI [0000:00:01:01]: interrupt line was set to 0
[#0 init_stage2(2:2)]: IDE controller @ PCI [0000:00:01:01]: ISA Compatibility mode-only controller, supports bus mastering
[#0 init_stage2(2:2)]: IDE controller @ PCI [0000:00:01:01]: primary channel DMA capable? 0
[#0 init_stage2(2:2)]: IDE controller @ PCI [0000:00:01:01]: secondary channel DMA capable? 0
[#0 init_stage2(2:2)]: IDEChannel: Primary master ATA device found: Name=QEMU HARDDISK, Capacity=295698432, Capabilities=0x0b00
[#0 init_stage2(2:2)]: Trying to unregister unused handler (?)
[init_stage2(2:2)]: PCI [0000:03:01:00]: AHCI controller reset
[#0 init_stage2(2:2)]: PCI [0000:03:01:00]: AHCI command list entries count - 32
[init_stage2(2:2)]: AHCI Port 1: Device not detected, Phy not enabled
[init_stage2(2:2)]: AHCI Port 2: Device not detected, Phy not enabled
[init_stage2(2:2)]: AHCI Port 3: Device not detected, Phy not enabled
[init_stage2(2:2)]: AHCI Port 4: Device not detected, Phy not enabled
[init_stage2(2:2)]: AHCI Port 5: Device not detected, Phy not enabled
[init_stage2(2:2)]: AHCI Port 6: Device not detected, Phy not enabled
[#0 init_stage2(2:2)]: Master Boot Record: invalid signature
[init_stage2(2:2)]: VFS: mounted root from Ext2FS (device:3,0 (PATADiskDevice))
[init_stage2(2:2)]: Loading kernel symbol table...
[init_stage2(2:2)]: Unmapped 408 KiB of kernel text after init! :^)
[NetworkTask(7:7)]: NetworkTask: E1000NetworkAdapter network adapter found: hw=52:54:00:12:34:56
[NetworkTask(7:7)]: NetworkTask: LoopbackAdapter network adapter found: hw=13:55:02:09:55:aa
[#0 SystemServer(6:6)]: mount dev @ /dev
[#0 SystemServer(6:6)]: VFS: Mounting DevFS at /dev (inode: 1:272) with flags 0
[#0 SystemServer(6:6)]: mount: successfully mounted /dev
[#0 SystemServer(6:6)]: mount devpts @ /dev/pts
[#0 SystemServer(6:6)]: VFS: Mounting DevPtsFS at /dev/pts (inode: 2:24) with flags 0
[#0 SystemServer(6:6)]: mount: successfully mounted /dev/pts
SystemServer(6:6): Spawning mount -a to mount all filesystems.
mount(8:8): Mounting all filesystems...
mount(8:8): Skipping mounting root
mount(8:8): Mounting /bin (bind) on /bin
[#0 mount(8:8)]: mount bind: source fd 4 @ /bin
[#0 mount(8:8)]: VFS: Bind-mounting /bin at /bin
mount(8:8): Mounting /etc (bind) on /etc
[#0 mount(8:8)]: mount bind: source fd 5 @ /etc
[#0 mount(8:8)]: VFS: Bind-mounting /etc at /etc
mount(8:8): Mounting /home (bind) on /home
[#0 mount(8:8)]: mount bind: source fd 6 @ /home
[#0 mount(8:8)]: VFS: Bind-mounting /home at /home
mount(8:8): Mounting /root (bind) on /root
[#0 mount(8:8)]: mount bind: source fd 7 @ /root
[#0 mount(8:8)]: VFS: Bind-mounting /root at /root
mount(8:8): Mounting /var (bind) on /var
[#0 mount(8:8)]: mount bind: source fd 8 @ /var
[#0 mount(8:8)]: VFS: Bind-mounting /var at /var
mount(8:8): Mounting /www (bind) on /www
[#0 mount(8:8)]: mount bind: source fd 9 @ /www
[#0 mount(8:8)]: VFS: Bind-mounting /www at /www
mount(8:8): Mounting none (proc) on /proc
[#0 mount(8:8)]: mount proc @ /proc
[#0 mount(8:8)]: VFS: Mounting ProcFS at /proc (inode: 1:266) with flags 4
[#0 mount(8:8)]: mount: successfully mounted /proc
mount(8:8): Mounting none (tmp) on /tmp
[#0 mount(8:8)]: mount tmp @ /tmp
[#0 mount(8:8)]: VFS: Mounting TmpFS at /tmp (inode: 1:268) with flags 5
[#0 mount(8:8)]: mount: successfully mounted /tmp
SystemServer(6:6): Creating /tmp/coredump directory
SystemServer(6:6): Read command line: Kernel/Kernel disable_virtio
SystemServer(6:6): Booting in graphical mode
SystemServer(6:6): Activating 23 services...

[gunnarbeutner]

This is definitely weird, but if you enable tabs in QEMU's View menu and then switch to one of the other tabs (e.g. serial0) the VM runs at full speed. While it's on the VGA tab it's (almost) stuck though.

[gunnarbeutner]

It gets even weirder: If I resize the QEMU window to about 50-60% of the size it also works while on the VGA tab.

[1player]

I don't think it's a QEMU 6 regression, I tried the latest 5.x with the same result. kernel-irqchip=off doesn't do anything, and I've never seen it hang on the UHCI initialisation phase either. I tried a few cpu options as well, no change.

I'm on @ADKaster same Windows version, 20H2 19042.985 on a Core i9 10900k. WSL2 is running Arch Linux.

[ADKaster]

@gunnarbeutner Yep I see that resize thing. If I have it the best fit size (ctrl + alt + 0) on my 2k monitor everything is fine, but zooming in 2x (ctrl + alt + +) causes it to freeze up. And resizing back causes normal behavior again.

[bgianfo]

If someone wants to debug qemu with windbg to check what's going on, looks like it's possible to generate PDBs form the mingw dwarf. Directions are here: https://ourwindowsman.wordpress.com/2021/01/23/windows-qemu-and-windbg/

[paulirwin]

I can reproduce this as well. Windows 10 19043, Core i7-10875H, WSL 2 with Ubuntu 20.04, QEMU 6.0.0 from the weilnetz.de site. Same results - fast on serial0 or if I do Zoom to Fit and shrink down small (on a 4k 15" laptop monitor this is barely legible it's so tiny), but slows to a crawl if resized larger. Bummer, I was so excited when I finally found the kernel-irqchip=off solution to get WHPX working 😄

env vars:

SERENITY_QEMU_BIN=/mnt/c/Program Files/qemu/qemu-system-i386.exe
SERENITY_EXTRA_QEMU_ARGS=-accel whpx,kernel-irqchip=off
SERENITY_KERNEL_CMDLINE=disable_virtio
SERENITY_DISK_IMAGE=\\wsl$\Ubuntu\home\paul\git\serenity\Build\i686\_disk_image
SERENITY_QEMU_CPU=max,vmx=off

[1player]

Yes, it's definitely something to do with 200% scaling, perhaps a GTK bug?

As a quick workaround, changing the settings for qemu-system-i386.exe, Compatibility -> Change DPI settings -> Enabling "scaling performed by system" shows a renders a correctly sized window that boots and runs at acceptable speeds and you don't have to squint to read it. Thankfully, SerenityOS is going for a classic pixelated look so no quality is lost.

[bgianfo]

Yes, it's definitely something to do with 200% scaling, perhaps a GTK bug?

As a quick workaround, changing the settings for qemu-system-i386.exe, Compatibility -> Change DPI settings -> Enabling "scaling performed by system" shows a renders a correctly sized window that boots and runs at acceptable speeds and you don't have to squint to read it. Thankfully, SerenityOS is going for a classic pixelated look so no quality is lost.

Nice find!

[gunnarbeutner]

An even easier workaround is -display sdl which was added to Meta/run.sh for unrelated reasons but seems to solve the scaling problem for me without having to modify any properties for the QEMU binary.

[jcrben]

@kleinesfilmroellchen how was this addressed? were you unable to replicate?

[kleinesfilmroellchen]

There are numerous workarounds listed, and newer QEMUs should be better at this. Only open a new issue if you have tried these and updated to the newest version.