Hello!

We've identified an issue with OVMF that causes the boot time of VMs to be considerably slower (taking 10+ minutes) under the following conditions:
 * CPU passthrough is used
 * Host has phys-bits > 40
 * GPU PCI passthrough is used

This issue was introduced in commit https://github.com/tianocore/edk2/commit/ecb778d0ac62560aa172786ba19521f27bc3f650 and is still present in the latest upstream version. Without this patch, we are only able to utilize passed-through Nvidia GPUs when the kernel options `pci=nocrs pci=realloc` are set in the guest. With the patch, we no longer need those kernel opts, but PCI enumeration and BAR assignment of the passed-through GPUs (and some other boot steps that may or may not be related) proceed extremely slowly.

The following is from a test of the following virt-install command, running upstream OVMF @ https://github.com/tianocore/edk2/commit/ef4f3aa3f7e3c28c7f0e1a3c35711f1a85becd71 built with verbose debugging enabled on a DGX H100 host.

#!/bin/bash

if [ -z "$1" ]; then
	echo "Error: No GPU index provided"
	echo "Usage: $0 <GPU index>"
	exit 1
fi

VM=testbox$1

virsh destroy $VM
virsh undefine $VM --nvram
rm -f *.qcow2

cat > user-data <<EOF
#cloud-config
password: passw0rd
chpasswd: { expire: False }
hostname: ${VM}
package_update: true
ssh_import_id: [mitchellaugustin]
version: 2
EOF

cloud-localds ${VM}-seed.qcow2 user-data -d qcow2
qemu-img create -b jammy-server-cloudimg-amd64.img -F qcow2 -f qcow2 ${VM}-vda.qcow2 30G


virt-install --name 4gpu-vm-2 --vcpus vcpus=16,maxvcpus=16 --memory 943616 --numatune 0,mode=strict --iothreads 1,iothreadids.iothread0.id=1 --cputune emulatorpin.cpuset=55,167,iothreadpin0.iothread=1,iothreadpin0.cpuset=54,166,vcpupin0.vcpu=0,vcpupin0.cpuset=16,vcpupin1.vcpu=1,vcpupin1.cpuset=128,vcpupin2.vcpu=2,vcpupin2.cpuset=17,vcpupin3.vcpu=3,vcpupin3.cpuset=129,vcpupin4.vcpu=4,vcpupin4.cpuset=18,vcpupin5.vcpu=5,vcpupin5.cpuset=130,vcpupin6.vcpu=6,vcpupin6.cpuset=19,vcpupin7.vcpu=7,vcpupin7.cpuset=131,vcpupin8.vcpu=8,vcpupin8.cpuset=20,vcpupin9.vcpu=9,vcpupin9.cpuset=132,vcpupin10.vcpu=10,vcpupin10.cpuset=21,vcpupin11.vcpu=11,vcpupin11.cpuset=133,vcpupin12.vcpu=12,vcpupin12.cpuset=22,vcpupin13.vcpu=13,vcpupin13.cpuset=134,vcpupin14.vcpu=14,vcpupin14.cpuset=23,vcpupin15.vcpu=15,vcpupin15.cpuset=135 --os-variant ubuntu22.04 --graphics none --noautoconsole --boot loader=/usr/share/OVMF/OVMF_CODE.fd,loader_ro=yes,loader_type=pflash --console pty,target_type=serial --network network:default --import --disk ${VM}-vda.qcow2 --disk ${VM}-seed.qcow2,format=qcow2,driver.queues=16,driver.iothread=1 --host-device 1b:00.0,address.type=pci --host-device 61:00.0,address.type=pci --host-device c3:00.0,address.type=pci --host-device df:00.0,address.type=pci

virsh console 4gpu-vm-2
Initially froze before showing anything for a couple minutes, then there was lots of output over the span of about a second.
Output then froze at this for about 20 seconds:
ConvertRange: 7EBA3000-7EBA3FFF to type 4
AddRange: 7EBA3000-7EBA3FFF to 4
AllocatePoolI: Type 4, Addr 7EBA3018 (len 30) 8,372,048
AllocatePoolI: Type 4, Addr 7EBA3F18 (len 30) 8,372,136
AllocatePoolI: Type 4, Addr 7EBA3F98 (len 30) 8,372,224
AllocatePoolI: Type 4, Addr 7EBA3B18 (len 30) 8,372,312
AllocatePoolI: Type 4, Addr 7EBA3E18 (len 30) 8,372,400
AllocatePoolI: Type 4, Addr 7EBA3E98 (len 30) 8,372,488


Then froze at this for about another 40 seconds
AllocatePoolI: Type 4, Addr 7EBA3B98 (len 30) 8,372,576
AllocatePoolI: Type 4, Addr 7EBA3D98 (len 30) 8,372,664


Took a minute or two, then printed out more of these
AllocatePoolI: Type 4, Addr 7EBA3C18 (len 30) 8,372,752
AllocatePoolI: Type 4, Addr 7EBA3C98 (len 30) 8,372,840

About a minute later, printed some of these:
AllocatePoolI: Type 4, Addr 7EBA3D18 (len 30) 8,372,928
AllocatePoolI: Type 4, Addr 7EBA3098 (len 30) 8,373,016

About a minute or two later, it spit out everything after the above and including this:
 Code Section: 0x7FAB4000 - 0x7FAB6000
PcRtc.efi: 0x7FAB7000 - 0x7FABD000
  Code Section: 0x7FAB8000 - 0x7FABC000
StatusCodeHandlerRuntimeDxe.efi: 0x7FABD000 - 0x7FAC2000
  Code Section: 0x7FABE000 - 0x7FAC1000
VariableRuntimeDxe.efi: 0x7FAC2000 - 0x7FAD2000
  Code Section: 0x7FAC3000 - 0x7FAD0000
ResetSystemRuntimeDxe.efi: 0x7FAD2000 - 0x7FAD9000
  Code Section: 0x7FAD3000 - 0x7FAD7000
RuntimeDxe.efi: 0x7FAD9000 - 0x7FADF000
  Code Section: 0x7FADA000 - 0x7FADD000
ReportStatusCodeRouterRuntimeDxe.efi: 0x7FADF000 - 0x7FAE5000
  Code Section: 0x7FAE0000 - 0x7FAE3000
FvbServicesRuntimeDxe.efi: 0x7FAE5000 - 0x7FAED000
  Code Section: 0x7FAE6000 - 0x7FAEB000
[Variable]END_OF_DXE is signaled
AllocatePoolI: Type 4, Addr 7F119898 (len 70) 8,371,168
FreePool: 7F119898 (len 70) 8,371,016
AllocatePoolI: Type 4, Addr 7F119898 (len 68) 8,371,160
FreePool: 7F119898 (len 68) 8,371,016
AllocatePoolI: Type 6, Addr 7F940818 (len 138) 673,080
Initialize variable error flag (FF)
FreePool: 7F128998 (len B8) 8,370,792
FreePool: 7EBA6618 (len B8) 8,370,568
AllocatePoolI: Type 4, Addr 7EBA2798 (len E8) 8,370,840
Found virtio serial device
AllocatePoolI: Type 4, Addr 7EBA3618 (len 10) 8,370,896
AllocatePoolI: Type 4, Addr 7EBA3698 (len 28) 8,370,976
FreePool: 7EBA3618 (len 10) 8,370,920
AllocatePoolI: Type 4, Addr 7EBA3618 (len 18) 8,370,984
AllocatePoolI: Type 4, Addr 7EC69798 (len 40) 8,371,088
FreePool: 7EBA3618 (len 18) 8,371,024
AllocatePoolI: Type 4, Addr 7EBA3618 (len 18) 8,371,088
AllocatePoolI: Type 4, Addr 7EBA6198 (len 50) 8,371,208
FreePool: 7EBA3618 (len 18) 8,371,144
AllocatePoolI: Type 4, Addr 7EBA3618 (len 50) 8,371,264
ValidateSetVariable - Variable (8BE4DF61-93CA-11D2-AA0D-00E098032B8C:ConOut) returning Success.
FreePool: 7EBA3618 (len 50) 8,371,144
AllocatePoolI: Type 4, Addr 7EBA3618 (len 50) 8,371,264
ValidateSetVariable - Variable (8BE4DF61-93CA-11D2-AA0D-00E098032B8C:ConIn) returning Success.
FreePool: 7EBA3618 (len 50) 8,371,144
AllocatePoolI: Type 4, Addr 7EBA3618 (len 50) 8,371,264
ValidateSetVariable - Variable (8BE4DF61-93CA-11D2-AA0D-00E098032B8C:ErrOut) returning Success.
FreePool: 7EBA3618 (len 50) 8,371,144


30 seconds later, up to this:
FreePool: 7EBA5018 (len 1A8) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5018 (len 1A8) 8,372,072
FreePool: 7EBA5018 (len 1A8) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
FreePool: 7EBA5F98 (len 30) 8,371,608
AllocatePoolI: Type 4, Addr 7EBA5F98 (len 30) 8,371,696
AllocatePoolI: Type 4, Addr 7EBA3618 (len 30) 8,371,784
AllocatePoolI: Type 4, Addr 7EBA6398 (len 30) 8,371,872
FreePool: 7EBA6398 (len 30) 8,371,784
AllocatePoolI: Type 4, Addr 7EBA6398 (len 30) 8,371,872
AllocatePoolI: Type 4, Addr 7EBA6218 (len 30) 8,371,960
AllocatePoolI: Type 4, Addr 7EBA6298 (len 30) 8,372,048
FreePool: 7EBA6298 (len 30) 8,371,960
AllocatePoolI: Type 4, Addr 7EBA6298 (len 30) 8,372,048
FreePool: 7EBA5D18 (len 1A8) 8,371,584
AllocatePoolI: Type 4, Addr 7EC69818 (len 50) 8,371,704
AllocatePoolI: Type 4, Addr 7EC69898 (len 50) 8,371,824
FreePool: 7EC69898 (len 50) 8,371,704
AllocatePoolI: Type 4, Addr 7EC69898 (len 50) 8,371,824
AllocatePoolI: Type 4, Addr 7EBA2F98 (len 50) 8,371,944
FreePool: 7EC69898 (len 50) 8,371,824
AllocatePoolI: Type 4, Addr 7EBA2918 (len 70) 8,371,976
FreePool: 7EBA2F98 (len 50) 8,371,856
ValidateSetVariable - Variable (8BE4DF61-93CA-11D2-AA0D-00E098032B8C:ConOut) returning Success.
FreePool: 7EC69818 (len 50) 8,371,736
FreePool: 7EBA2918 (len 70) 8,371,584

After this point, I didn't see any more OVMF debug logs - only linux info

After a couple more like this, it sped up, then reached pci device enumeration, which happened slowly but steadily over about 5 minutes:
[    4.191929] pci 0000:00:00.0: [8086:29c0] type 00 class 0x060000
[    4.193175] pci 0000:00:01.0: [1b36:000c] type 01 class 0x060400
[    4.196743] pci 0000:00:01.0: reg 0x10: [mem 0x81c8e000-0x81c8efff]
[    4.202716] pci 0000:00:01.1: [1b36:000c] type 01 class 0x060400
[    4.206055] pci 0000:00:01.1: reg 0x10: [mem 0x81c8d000-0x81c8dfff]
[    4.210124] pci 0000:00:01.2: [1b36:000c] type 01 class 0x060400
[    4.212743] pci 0000:00:01.2: reg 0x10: [mem 0x81c8c000-0x81c8cfff]
[    4.219495] pci 0000:00:01.3: [1b36:000c] type 01 class 0x060400
[    4.221260] pci 0000:00:01.3: reg 0x10: [mem 0x81c8b000-0x81c8bfff]
[    4.225688] pci 0000:00:01.4: [1b36:000c] type 01 class 0x060400
[    4.230325] pci 0000:00:01.4: reg 0x10: [mem 0x81c8a000-0x81c8afff]
[    4.233982] pci 0000:00:01.5: [1b36:000c] type 01 class 0x060400
[    4.240753] pci 0000:00:01.5: reg 0x10: [mem 0x81c89000-0x81c89fff]
[    4.266807] pci 0000:00:01.6: [1b36:000c] type 01 class 0x060400
[    4.272751] pci 0000:00:01.6: reg 0x10: [mem 0x81c88000-0x81c88fff]

These outputs progressed slowly
[    4.600758] pci 0000:07:00.0: reg 0x10: [mem 0x386002000000-0x386002ffffff 64bit pref]
[    4.608751] pci 0000:07:00.0: reg 0x18: [mem 0x384000000000-0x385fffffffff 64bit pref]
[    4.616751] pci 0000:07:00.0: reg 0x20: [mem 0x386000000000-0x386001ffffff 64bit pref]

and about 40 seconds later, I saw these
[    4.624800] pci 0000:07:00.0: Max Payload Size set to 128 (was 256, max 256)
[    4.626377] pci 0000:07:00.0: Enabling HDA controller
[    4.627522] pci 0000:07:00.0: 252.048 Gb/s available PCIe bandwidth, limited by 16.0 GT/s PCIe x16 link at 0000:00:01.6 (capable of 504.112 Gb/s with 32.0 GT/s PCIe x16 link)
[    4.638757] pci 0000:00:01.6: PCI bridge to [bus 07]
[    4.639272] pci 0000:00:01.6:   bridge window [mem 0x80e00000-0x80ffffff]
[    4.639961] pci 0000:00:01.6:   bridge window [mem 0x384000000000-0x386002ffffff 64bit pref]
[    4.641519] acpiphp: Slot [0-8] registered
[    4.642066] pci 0000:08:00.0: [10de:2330] type 00 class 0x030200

I want to reiterate that the kernel timestamps are not even close to wall clock time - as mentioned, the event at 4.616751 sec and that at 4.624800 sec were in reality nearly 40 seconds apart

On the host machine, I also see lots of lockups of the CPU running this KVM process during this entire boot sequence:
[ 9627.869824] watchdog: BUG: soft lockup - CPU#16 stuck for 52s! [CPU 0/KVM:265391]
[ 9667.872497] watchdog: BUG: soft lockup - CPU#16 stuck for 26s! [CPU 0/KVM:265391]
[ 9695.874538] watchdog: BUG: soft lockup - CPU#16 stuck for 52s! [CPU 0/KVM:265391]

(dmesg only shows that one CPU getting stuck (and this is a VM with many cores, all pinned))

After a few more minutes, BAR assignment occurred (this step took a couple minutes as well):
[    5.016068] pci 0000:00:01.3: BAR 13: assigned [io  0x4000-0x4fff]
[    5.016679] pci 0000:00:01.4: BAR 13: assigned [io  0x5000-0x5fff]
[    5.017295] pci 0000:00:01.5: BAR 13: assigned [io  0x7000-0x7fff]
[    5.017905] pci 0000:00:01.6: BAR 13: assigned [io  0x8000-0x8fff]
[    5.018516] pci 0000:00:01.7: BAR 13: assigned [io  0x9000-0x9fff]
[    5.019138] pci 0000:00:02.0: BAR 13: assigned [io  0xa000-0xafff]
[    5.019752] pci 0000:00:02.1: BAR 13: assigned [io  0xb000-0xbfff]
[    5.020364] pci 0000:00:02.2: BAR 13: assigned [io  0xc000-0xcfff]
[    5.020974] pci 0000:00:02.3: BAR 13: assigned [io  0xd000-0xdfff]
[    5.021597] pci 0000:00:02.4: BAR 13: assigned [io  0xe000-0xefff]
[    5.022223] pci 0000:00:02.5: BAR 13: assigned [io  0xf000-0xffff]
[    5.022845] pci 0000:01:00.0: BAR 6: assigned [mem 0x81a80000-0x81afffff pref]
[    5.023569] pci 0000:00:01.0: PCI bridge to [bus 01]
[    5.024074] pci 0000:00:01.0:   bridge window [io  0x1000-0x1fff]
[    5.026195] pci 0000:00:01.0:   bridge window [mem 0x81a00000-0x81bfffff]
[    5.027803] pci 0000:00:01.0:   bridge window [mem 0x38e800000000-0x38efffffffff 64bit pref]
[    5.030462] pci 0000:00:01.1: PCI bridge to [bus 02]
[    5.030968] pci 0000:00:01.1:   bridge window [io  0x2000-0x2fff]
[    5.032894] pci 0000:00:01.1:   bridge window [mem 0x81800000-0x819fffff]
[    5.034425] pci 0000:00:01.1:   bridge window [mem 0x38f000000000-0x38f7ffffffff 64bit pref]
[    5.037036] pci 0000:00:01.2: PCI bridge to [bus 03]
[    5.040876] pci 0000:00:01.2:   bridge window [io  0x3000-0x3fff]
[    5.042483] pci 0000:00:01.2:   bridge window [mem 0x81600000-0x817fffff]
[    5.043712] pci 0000:00:01.2:   bridge window [mem 0x38f800000000-0x38ffffffffff 64bit pref]
[    5.045570] pci 0000:00:01.3: PCI bridge to [bus 04]
[    5.046081] pci 0000:00:01.3:   bridge window [io  0x4000-0x4fff]
[    5.047462] pci 0000:00:01.3:   bridge window [mem 0x81400000-0x815fffff]
[    5.048844] pci 0000:00:01.3:   bridge window [mem 0x390000000000-0x3907ffffffff 64bit pref]
[    5.054233] pci 0000:00:01.4: PCI bridge to [bus 05]
[    5.054734] pci 0000:00:01.4:   bridge window [io  0x5000-0x5fff]
[    5.056113] pci 0000:00:01.4:   bridge window [mem 0x81200000-0x813fffff]
[    5.057274] pci 0000:00:01.4:   bridge window [mem 0x390800000000-0x390fffffffff 64bit pref]
[    5.058981] pci 0000:00:01.5: PCI bridge to [bus 06]
[    5.059501] pci 0000:00:01.5:   bridge window [io  0x7000-0x7fff]
[    5.060824] pci 0000:00:01.5:   bridge window [mem 0x81000000-0x811fffff]
[    5.479160] pci 0000:00:01.5:   bridge window [mem 0x380000000000-0x382002ffffff 64bit pref]
[    8.340342] pci 0000:00:01.6: PCI bridge to [bus 07]
[    8.341589] pci 0000:00:01.6:   bridge window [io  0x8000-0x8fff]
[    8.343094] pci 0000:00:01.6:   bridge window [mem 0x80e00000-0x80ffffff]
[    8.761736] pci 0000:00:01.6:   bridge window [mem 0x384000000000-0x386002ffffff 64bit pref]



Then the rest of the boot sequence proceeded at normal speed, and the VM was able to use its passed-through devices