search

newsnowlabs / runcvm

RunCVM (Run Container VM) is an experimental open-source Docker container runtime, for launching standard container workloads - as well as Systemd, Docker, even OpenWrt - in VMs using 'docker run`
Apache License 2.0
211 stars 7 forks source link

Inconsistent container startup time #14

Open SmylerMC opened 8 months ago

SmylerMC commented 8 months ago

I am using RuncVM to study kernel vulnerabilities by building vulnerable container images. I am noticing different startup times from one computer to another, often very long, and the container never finishes booting in some cases.

Computer 1

Containers take around 2 minutes to start. Most of that time is spent after the Qemu process is started but seemingly before the kernel starts. The Qemu process uses 100% of a CPU core during that time. A similar waiting time exists when the container exists, also maxing out a CPU core. The exact same behavior is reproduced when running RuncVM in a Fedora VM on that host (Libvirt, with nested virtualization enabled and tested).

CPU: Intel i7-12700H Host kernel: 6.6.10-1-MANJARO Docker version: 24.0.7, build afdd53b4e3

Asciinema recording: https://asciinema.org/a/iixER5qw6fSiLnslM1NW2z9d1

Computer 2

Running a vanilla Ubuntu container image works flawlessly.

Asciinema recoding: https://asciinema.org/a/wc0nQL5sFQ4hNUXkQMjApGxsq

Trying to run a Debian image with a custom kernel hangs the shell forever. Trying to run a second container with the same image after that returns immediately. This may be a different issue. Qemu is running and doesn't appear to be using much CPU.

Dockerfile:

FROM debian:bullseye

ARG KERNEL=linux-image-5.10.0-27-amd64

# Install kernel and generate initramfs.
# The virtiofs module is mandatory for Linux to find the root file system at boot.
# It wouldn't be included if we didn't add it to /etc/initramfs-tools/modules.
RUN apt update && \
    apt install -y "$KERNEL" initramfs-tools && \
    echo "virtiofs" >> /etc/initramfs-tools/modules && \
    update-initramfs -u

CPU: Intel i7-5600U Host kernel: 6.5.0-kali3-amd64 Docker version: 20.10.25+dfsg1, build b82b9f3

struanb commented 8 months ago

Hi @SmylerMC. I think we've got too separate issues here.

Let's take the Debian custom kernel first. The issue here is you also need the virtio_console module added to /etc/initramfs-tools/modules too. I've tested with this change and your Dockerfile then works. (Please note RunCVM changed from using serial to using virtio_console recently. The logic for using serial is still present but disabled pending addition of new command-line option. Until then if you change CONSOLE_MONITOR="0" to read CONSOLE_MONITOR="1" in /opt/runcvm/scripts/runcvm-ctr-qemu RunCVM will use serial instead of virtio_console, and your original Dockerfile will work unchanged).

struanb commented 8 months ago

Now looking at the slow-start issue. This symptom is one I haven't seen and I don't yet know what's going on.

I agree it does look like QEMU taking nearly 2 minutes to load the kernel, but let's be sure.

The option --env=RUNCVM_BREAK can help us work out exactly where the delay is. Begin with adding --env=RUNCVM_BREAK=preqemu. This will print the intended QEMU command and then run a shell in the container before launching QEMU. (When you get to the shell, type CTRL-D or type exit to proceed with QEMU launch).

docker run --rm -it --runtime=runcvm --env=RUNCVM_BIOS_DEBUG=1 --env=RUNCVM_KERNEL_DEBUG=1 --env=RUNCVM_RUNTIME_DEBUG=1 --env=RUNCVM_BREAK=preqemu ubuntu:latest

Please run this and share another screen recording. If the delay is reproducible, whether the delay is before or after the shell will help us isolate the cause.

Here is what I get: https://asciinema.org/a/632558

By the way, how much RAM does your computer have?

SmylerMC commented 8 months ago

Thank you for your swift response.

Custom Kernel issue

I had missed the change. I added virtio_console as you instructed, and I now get a different behavior, where docker returns immediately, with a slow start on computer 1.

Computer 1 recording: https://asciinema.org/a/NzdZdtgL4N93oENyN2DkO15yG Computer 2 recording: https://asciinema.org/a/NH2PK6gYIPzigmVyUsBsA4hxS

New Dockerfile:

FROM debian:bullseye

ARG KERNEL=linux-image-5.10.0-27-amd64

RUN apt update && \
    apt install -y "$KERNEL" initramfs-tools && \
    echo "virtiofs" >> /etc/initramfs-tools/modules && \
    echo "virtio_console" >> /etc/initramfs-tools/modules && \
    update-initramfs -u

CONSOLE_MONITOR=1 works fine as a workaround.

Computer 1 has 64GB of RAM. Computer 2 has 16GB.

Slow start issue

It is indeed Qemu being very slow to start: https://asciinema.org/a/PSslboorUjZlNgS8NKeOxDmyq .

struanb commented 8 months ago

I notice you've got 20 cores on this computer and are using default memory allocation of 512M.

I wonder if this isn't a happy combination. Let's try --cpus 1 and -m 2g. If that works better we can iterate on these.

struanb commented 8 months ago

Oh I believe there may be an issue whereby debian specifically doesn't like using virtio_console with RUNCVM_KERNEL_DEBUG=1. The aforementioned workaround to use serial instead is needed if you use RUNCVM_KERNEL_DEBUG=1 with debian.

(Bizarrely ubuntu doesn't exhibit this issue, only Debian).

SmylerMC commented 8 months ago

Oh I believe there may be an issue whereby debian specifically doesn't like using virtio_console with RUNCVM_KERNEL_DEBUG=1.

Good catch, removing the option works. Any idea what's causing this?

Let's try --cpus 1 and -m 2g.

No luck, doesn't change a thing. The behavior was also the same when running in my Fedora VM, with 8 cores and 8GB. What's weird is that I use Qemu on a daily basis on this computer through libvirt and the cli, and I have never experienced anything like this, except when using RuncVM. One of the options must be causing it. As a last resort, I can try starting the VM manually, removing options until I find the problematic one.

struanb commented 8 months ago

Oh I believe there may be an issue whereby debian specifically doesn't like using virtio_console with RUNCVM_KERNEL_DEBUG=1.

Good catch, removing the option works. Any idea what's causing this?

No idea about the Debian/virtio_console issue, though logically I feel it has to be either a kernel build config or initramfs start-up script, as Ubuntu doesn't exhibit the issue. There's an argument to reverting to use serial by default, but I'm reluctant as virtio_console seems the more modern and appropriate interface...

Let's try --cpus 1 and -m 2g.

No luck, doesn't change a thing. The behavior was also the same when running in my Fedora VM, with 8 cores and 8GB. What's weird is that I use Qemu on a daily basis on this computer through libvirt and the cli, and I have never experienced anything like this, except when using RuncVM. One of the options must be causing it. As a last resort, I can try starting the VM manually, removing options until I find the problematic one.

To be clear, does this slow start only affect vanilla Ubuntu or does it affect any other images? And if you build a custom Ubuntu image with a different kernel, does it affect that?

What does top show qemu is doing during the slow start?

If you're feeling brave, you could try strace -f on the qemu process to see what system calls it is running.

I agree that it's likely some qemu command line option could be triggering this, if you normally run qemu without problems. Easy way you can test this is hacking the /opt/runcvm/scripts/runcvm-ctr-qemu script. It should be reasonably clear how it composes the final qemu command line, so you can chop it around.

struanb commented 8 months ago

Another idea: with CONSOLE_MONITOR="1" in /opt/runcvm/scripts/runcvm-ctr-qemu, try removing --env=RUNCVM_BIOS_DEBUG=1 and adding --env=RUNCVM_KERNEL_APPEND='earlyprintk=serial', i.e. running:

docker run --rm -it --runtime=runcvm --env=RUNCVM_KERNEL_DEBUG=1 --env=RUNCVM_RUNTIME_DEBUG=1 --env=RUNCVM_BREAK=preqemu --env=RUNCVM_KERNEL_APPEND='earlyprintk=serial' ubuntu:latest

This might print some kernel logs earlier, or it might not.

Also with this mode, please copy and paste the kernel logs directly from the terminal rather than use asciinema, as I'm concerned asciinema may be omitting some output.

For comparison, here's the initial output of the above command, run on a Dell R620 running Debian Bullseye:

# docker run --rm -it --runtime=runcvm --env=RUNCVM_KERNEL_DEBUG=1 --env=RUNCVM_RUNTIME_DEBUG=1 --env=RUNCVM_BREAK=preqemu --env=RUNCVM_KERNEL_APPEND='earlyprintk=serial' ubuntu:latest
Preparing to run: '/.runcvm/guest/usr/bin/qemu-system-x86_64' '-no-user-config' '-nodefaults' '-no-reboot' '-action' 'panic=none' '-action' 'reboot=shutdown' '-enable-kvm' '-cpu' 'host,pmu=off' '-machine' 'q35,accel=kvm,usb=off,sata=off' '-device' 'isa-debug-exit' '-nographic' '-vga' 'none' '-fw_cfg' 'opt/org.seabios/etc/sercon-port,string=0' '-m' '512M' '-smp' '48,cores=1,threads=1,sockets=48,maxcpus=48' '-device' 'virtio-serial-pci,id=serial0' '-object' 'rng-random,id=rng0,filename=/dev/urandom' '-device' 'virtio-rng-pci,rng=rng0' '-numa' 'node,memdev=mem' '-object' 'memory-backend-file,id=mem,size=512M,mem-path=/dev/shm,share=on,prealloc=off' '-chardev' 'socket,id=virtiofs,path=/run/.virtiofs.sock' '-device' 'vhost-user-fs-pci,queue-size=1024,chardev=virtiofs,tag=runcvmfs,ats=off' '-netdev' 'tap,id=qemu0,ifname=tap-eth0,script=/.runcvm/guest/scripts/runcvm-ctr-qemu-ifup,downscript=/.runcvm/guest/scripts/runcvm-ctr-qemu-ifdown' '-device' 'virtio-net-pci,netdev=qemu0,mac=52:54:00:14:00:04,rombar=0' '-chardev' 'stdio,id=char0,mux=on,signal=off' '-serial' 'chardev:char0' '-mon' 'chardev=char0' '-echr' '20' '-chardev' 'socket,id=qemuguest0,path=/run/.qemu-guest-agent,server=on,wait=off' '-device' 'virtserialport,chardev=qemuguest0,name=org.qemu.guest_agent.0' '-monitor' 'unix:/run/.qemu-monitor-socket,server,nowait' '-kernel' '/.runcvm/guest/kernels/ubuntu/5.15.0-91-generic/vmlinuz' '-initrd' '/.runcvm/guest/kernels/ubuntu/5.15.0-91-generic/initrd' '-L' '/.runcvm/guest/usr/share/qemu' '-append' 'rootfstype=virtiofs root=runcvmfs noresume nomodeset net.ifnames=1 init=/.runcvm/guest/scripts/runcvm-vm-init rw ipv6.disable=1 panic=-1 scsi_mod.scan=none tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests pci=lastbus=0 selinux=0 systemd.show_status=1 console=ttyS0 earlyprintk=serial'
root@6ead255967f7:/# 
exit
[    0.000000] Linux version 5.15.0-91-generic (buildd@lcy02-amd64-045) (gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #101-Ubuntu SMP Tue Nov 14 13:30:08 UTC 2023 (Ubuntu 5.15.0-91.101-generic 5.15.131)
[    0.000000] Command line: rootfstype=virtiofs root=runcvmfs noresume nomodeset net.ifnames=1 init=/.runcvm/guest/scripts/runcvm-vm-init rw ipv6.disable=1 panic=-1 scsi_mod.scan=none tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests pci=lastbus=0 selinux=0 systemd.show_status=1 console=ttyS0 earlyprintk=serial
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000]   AMD AuthenticAMD
[    0.000000]   Hygon HygonGenuine
[    0.000000]   Centaur CentaurHauls
[    0.000000]   zhaoxin   Shanghai  
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000001ffdefff] usable
[    0.000000] BIOS-e820: [mem 0x000000001ffdf000-0x000000001fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    0.000000] printk: bootconsole [earlyser0] enabled
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.8 present.
[    0.000000] DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-20240107_171655-buildkitsandbox 04/01/2014
[    0.000000] Hypervisor detected: KVM
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 17601001, primary cpu clock
[    0.000006] kvm-clock: using sched offset of 729021333 cycles
[    0.000653] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.002394] tsc: Detected 2999.996 MHz processor
[    0.003323] last_pfn = 0x1ffdf max_arch_pfn = 0x400000000
[    0.003961] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT  
Memory KASLR using RDRAND RDTSC...
[    0.020016] Using GB pages for direct mapping
[    0.020772] RAMDISK: [mem 0x1c347000-0x1ffcffff]
[    0.021496] ACPI: Early table checksum verification disabled
[    0.022304] ACPI: RSDP 0x00000000000F5C00 000014 (v00 BOCHS )
[    0.023133] ACPI: RSDT 0x000000001FFE2B4E 00003C (v01 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.024230] ACPI: FACP 0x000000001FFE2426 0000F4 (v03 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.025290] ACPI: DSDT 0x000000001FFDF2C0 003166 (v01 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.026451] ACPI: FACS 0x000000001FFDF280 000040
[    0.027183] ACPI: APIC 0x000000001FFE251A 0001F0 (v01 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.028514] ACPI: HPET 0x000000001FFE270A 000038 (v01 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.029829] ACPI: SRAT 0x000000001FFE2742 0003A8 (v01 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.030775] ACPI: MCFG 0x000000001FFE2AEA 00003C (v01 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.031884] ACPI: WAET 0x000000001FFE2B26 000028 (v01 BOCHS  BXPC     00000001 BXPC 00000001)
[    0.033035] ACPI: Reserving FACP table memory at [mem 0x1ffe2426-0x1ffe2519]
[    0.033799] ACPI: Reserving DSDT table memory at [mem 0x1ffdf2c0-0x1ffe2425]
[    0.034613] ACPI: Reserving FACS table memory at [mem 0x1ffdf280-0x1ffdf2bf]
[    0.035609] ACPI: Reserving APIC table memory at [mem 0x1ffe251a-0x1ffe2709]
[    0.036449] ACPI: Reserving HPET table memory at [mem 0x1ffe270a-0x1ffe2741]
[    0.037324] ACPI: Reserving SRAT table memory at [mem 0x1ffe2742-0x1ffe2ae9]
[    0.038196] ACPI: Reserving MCFG table memory at [mem 0x1ffe2aea-0x1ffe2b25]
[    0.039290] ACPI: Reserving WAET table memory at [mem 0x1ffe2b26-0x1ffe2b4d]
[    0.040310] SRAT: PXM 0 -> APIC 0x00 -> Node 0
[    0.040959] SRAT: PXM 0 -> APIC 0x01 -> Node 0
[    0.041489] SRAT: PXM 0 -> APIC 0x02 -> Node 0
[    0.042072] SRAT: PXM 0 -> APIC 0x03 -> Node 0
[    0.042745] SRAT: PXM 0 -> APIC 0x04 -> Node 0
[    0.043452] SRAT: PXM 0 -> APIC 0x05 -> Node 0
[    0.044112] SRAT: PXM 0 -> APIC 0x06 -> Node 0
[    0.044818] SRAT: PXM 0 -> APIC 0x07 -> Node 0
[    0.045441] SRAT: PXM 0 -> APIC 0x08 -> Node 0
[    0.045913] SRAT: PXM 0 -> APIC 0x09 -> Node 0
[    0.046384] SRAT: PXM 0 -> APIC 0x0a -> Node 0
[    0.046901] SRAT: PXM 0 -> APIC 0x0b -> Node 0
[    0.047477] SRAT: PXM 0 -> APIC 0x0c -> Node 0
[    0.048004] SRAT: PXM 0 -> APIC 0x0d -> Node 0
[    0.048573] SRAT: PXM 0 -> APIC 0x0e -> Node 0
[    0.049250] SRAT: PXM 0 -> APIC 0x0f -> Node 0
[    0.049868] SRAT: PXM 0 -> APIC 0x10 -> Node 0
[    0.050469] SRAT: PXM 0 -> APIC 0x11 -> Node 0
[    0.050947] SRAT: PXM 0 -> APIC 0x12 -> Node 0
[    0.051424] SRAT: PXM 0 -> APIC 0x13 -> Node 0
[    0.052006] SRAT: PXM 0 -> APIC 0x14 -> Node 0
[    0.052605] SRAT: PXM 0 -> APIC 0x15 -> Node 0
[    0.053098] SRAT: PXM 0 -> APIC 0x16 -> Node 0
[    0.053707] SRAT: PXM 0 -> APIC 0x17 -> Node 0
[    0.054309] SRAT: PXM 0 -> APIC 0x18 -> Node 0
[    0.054895] SRAT: PXM 0 -> APIC 0x19 -> Node 0
[    0.055560] SRAT: PXM 0 -> APIC 0x1a -> Node 0
[    0.056159] SRAT: PXM 0 -> APIC 0x1b -> Node 0
[    0.056811] SRAT: PXM 0 -> APIC 0x1c -> Node 0
[    0.057411] SRAT: PXM 0 -> APIC 0x1d -> Node 0
[    0.058067] SRAT: PXM 0 -> APIC 0x1e -> Node 0
[    0.058719] SRAT: PXM 0 -> APIC 0x1f -> Node 0
[    0.059217] SRAT: PXM 0 -> APIC 0x20 -> Node 0
[    0.059772] SRAT: PXM 0 -> APIC 0x21 -> Node 0
[    0.060362] SRAT: PXM 0 -> APIC 0x22 -> Node 0
[    0.060993] SRAT: PXM 0 -> APIC 0x23 -> Node 0
[    0.061575] SRAT: PXM 0 -> APIC 0x24 -> Node 0
[    0.062185] SRAT: PXM 0 -> APIC 0x25 -> Node 0
[    0.062808] SRAT: PXM 0 -> APIC 0x26 -> Node 0
[    0.063437] SRAT: PXM 0 -> APIC 0x27 -> Node 0
[    0.064094] SRAT: PXM 0 -> APIC 0x28 -> Node 0
[    0.064707] SRAT: PXM 0 -> APIC 0x29 -> Node 0
[    0.065348] SRAT: PXM 0 -> APIC 0x2a -> Node 0
[    0.065989] SRAT: PXM 0 -> APIC 0x2b -> Node 0
[    0.066617] SRAT: PXM 0 -> APIC 0x2c -> Node 0
[    0.067264] SRAT: PXM 0 -> APIC 0x2d -> Node 0
[    0.067896] SRAT: PXM 0 -> APIC 0x2e -> Node 0
[    0.068582] SRAT: PXM 0 -> APIC 0x2f -> Node 0
[    0.069233] ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0x0009ffff]
[    0.070145] ACPI: SRAT: Node 0 PXM 0 [mem 0x00100000-0x1fffffff]
[    0.071067] NUMA: Node 0 [mem 0x00000000-0x0009ffff] + [mem 0x00100000-0x1ffdefff] -> [mem 0x00000000-0x1ffdefff]
[    0.072529] NODE_DATA(0) allocated [mem 0x1c31d000-0x1c346fff]
[    0.073947] Zone ranges:
[    0.074330]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.075233]   DMA32    [mem 0x0000000001000000-0x000000001ffdefff]
[    0.076120]   Normal   empty
[    0.076472]   Device   empty
[    0.076871] Movable zone start for each node
[    0.077494] Early memory node ranges
[    0.078022]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.078829]   node   0: [mem 0x0000000000100000-0x000000001ffdefff]
[    0.079627] Initmem setup node 0 [mem 0x0000000000001000-0x000000001ffdefff]
[    0.080689] On node 0, zone DMA: 1 pages in unavailable ranges
[    0.080912] On node 0, zone DMA: 97 pages in unavailable ranges
[    0.088638] On node 0, zone DMA32: 33 pages in unavailable ranges
[    0.089825] ACPI: PM-Timer IO Port: 0x608
[    0.091135] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.091967] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.092830] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.093690] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.094617] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.095605] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.096586] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.097548] ACPI: Using ACPI (MADT) for SMP configuration information
[    0.098483] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.099216] TSC deadline timer available
[    0.099691] smpboot: Allowing 48 CPUs, 0 hotplug CPUs
[    0.100532] kvm-guest: KVM setup pv remote TLB flush
[    0.101269] kvm-guest: setup PV sched yield
[    0.101885] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.102907] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.104000] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff]
[    0.105055] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[    0.106125] [mem 0x20000000-0xafffffff] available for PCI devices
[    0.106950] Booting paravirtualized kernel on KVM
[    0.107643] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.109169] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:48 nr_cpu_ids:48 nr_node_ids:1
[    0.122131] percpu: Embedded 61 pages/cpu s212992 r8192 d28672 u262144
[    0.123174] kvm-guest: setup async PF for cpu 0
[    0.123763] kvm-guest: stealtime: cpu 0, msr 1ae33080
[    0.124453] kvm-guest: PV spinlocks enabled
[    0.125067] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear)
[    0.126139] Built 1 zonelists, mobility grouping on.  Total pages: 128735
[    0.127120] Policy zone: DMA32
[    0.127574] Kernel command line: rootfstype=virtiofs root=runcvmfs noresume nomodeset net.ifnames=1 init=/.runcvm/guest/scripts/runcvm-vm-init rw ipv6.disable=1 panic=-1 scsi_mod.scan=none tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests pci=lastbus=0 selinux=0 systemd.show_status=1 console=ttyS0 earlyprintk=serial
[    0.133037] You have booted with nomodeset. This means your GPU drivers are DISABLED
[    0.134152] Any video related functionality will be severely degraded, and you may not even be able to suspend the system properly
[    0.135921] Unless you actually understand what nomodeset does, you should reboot without enabling it
[    0.137405] printk: log_buf_len individual max cpu contribution: 4096 bytes
[    0.138359] printk: log_buf_len total cpu_extra contributions: 192512 bytes
[    0.139356] printk: log_buf_len min size: 262144 bytes
[    0.142180] printk: log_buf_len: 524288 bytes
[    0.142835] printk: early log buf free: 251768(96%)
[    0.143975] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.145324] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.147705] mem auto-init: stack:off, heap alloc:on, heap free:off
[    0.150641] Memory: 379888K/523764K available (16393K kernel code, 4393K rwdata, 10868K rodata, 3356K init, 18716K bss, 143616K reserved, 0K cma-reserved)
[    0.152735] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=48, Nodes=1
[    0.153502] Kernel/User page tables isolation: enabled
Poking KASLR using RDRAND RDTSC...
[    0.154513] ftrace: allocating 50637 entries in 198 pages
[    0.181295] ftrace: allocated 198 pages with 4 groups
[    0.182578] rcu: Hierarchical RCU implementation.
[    0.183082] rcu:     RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=48.
[    0.183803]  All grace periods are expedited (rcu_expedited).
[    0.184450]  Rude variant of Tasks RCU enabled.
[    0.184955]  Tracing variant of Tasks RCU enabled.
[    0.185459] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.186254] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=48
[    0.191724] NR_IRQS: 524544, nr_irqs: 808, preallocated irqs: 16
[    0.192660] random: crng init done
[    0.193180] Console: colour *CGA 80x25
[    0.193617] printk: console [ttyS0] enabled
[    0.193617] printk: console [ttyS0] enabled
[    0.194513] printk: bootconsole [earlyser0] disabled
[    0.194513] printk: bootconsole [earlyser0] disabled
[    0.195655] ACPI: Core revision 20210730
SmylerMC commented 8 months ago

What does top show qemu is doing during the slow start?

It appears to be sitting with a single thread eating 100% of a CPU core's time.

htop screenshot ![Screenshot_20240124_150811](https://github.com/newsnowlabs/runcvm/assets/19222559/0fc7459e-783b-4c15-ab0b-15ef80644ebe)

To be clear, does this slow start only affect vanilla Ubuntu or does it affect any other images? And if you build a custom Ubuntu image with a different kernel, does it affect that?

All images I have tried so far are affected, including ones with custom kernels.

This might print some kernel logs earlier, or it might not.

It does not appear to. Early boot messages still appear after about one to two minutes.

Output ``` docker run --rm -it --runtime=runcvm --env=RUNCVM_KERNEL_DEBUG=1 --env=RUNCVM_RUNTIME_DEBUG=1 --env=RUNCVM_BREAK=preqemu --env=RUNCVM_KERNEL_APPEND='earlyprintk=serial' ubuntu:latest Preparing to run: '/.runcvm/guest/usr/bin/qemu-system-x86_64' '-no-user-config' '-nodefaults' '-no-reboot' '-action' 'panic=none' '-action' 'reboot=shutdown' '-enable-kvm' '-cpu' 'host,pmu=off' '-machine' 'q35,accel=kvm,usb=off,sata=off' '-device' 'isa-debug-exit' '-nographic' '-vga' 'none' '-fw_cfg' 'opt/org.seabios/etc/sercon-port,string=0' '-m' '512M' '-smp' '20,cores=1,threads=1,sockets=20,maxcpus=20' '-device' 'virtio-serial-pci,id=serial0' '-object' 'rng-random,id=rng0,filename=/dev/urandom' '-device' 'virtio-rng-pci,rng=rng0' '-numa' 'node,memdev=mem' '-object' 'memory-backend-file,id=mem,size=512M,mem-path=/dev/shm,share=on,prealloc=off' '-chardev' 'socket,id=virtiofs,path=/run/.virtiofs.sock' '-device' 'vhost-user-fs-pci,queue-size=1024,chardev=virtiofs,tag=runcvmfs,ats=off' '-netdev' 'tap,id=qemu0,ifname=tap-eth0,script=/.runcvm/guest/scripts/runcvm-ctr-qemu-ifup,downscript=/.runcvm/guest/scripts/runcvm-ctr-qemu-ifdown' '-device' 'virtio-net-pci,netdev=qemu0,mac=52:54:00:11:00:04,rombar=0' '-chardev' 'stdio,id=char0,mux=on,signal=off' '-serial' 'chardev:char0' '-mon' 'chardev=char0' '-echr' '20' '-chardev' 'socket,id=qemuguest0,path=/run/.qemu-guest-agent,server=on,wait=off' '-device' 'virtserialport,chardev=qemuguest0,name=org.qemu.guest_agent.0' '-monitor' 'unix:/run/.qemu-monitor-socket,server,nowait' '-kernel' '/.runcvm/guest/kernels/ubuntu/5.15.0-91-generic/vmlinuz' '-initrd' '/.runcvm/guest/kernels/ubuntu/5.15.0-91-generic/initrd' '-L' '/.runcvm/guest/usr/share/qemu' '-append' 'rootfstype=virtiofs root=runcvmfs noresume nomodeset net.ifnames=1 init=/.runcvm/guest/scripts/runcvm-vm-init rw ipv6.disable=1 panic=-1 scsi_mod.scan=none tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests pci=lastbus=0 selinux=0 systemd.show_status=1 console=ttyS0 earlyprintk=serial' root@22ca5175a0de:/# exit [ 0.000000] Linux version 5.15.0-91-generic (buildd@lcy02-amd64-045) (gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #101-Ubuntu SMP Tue Nov 14 13:30:08 UTC 2023 (Ubuntu 5.15.0-91.101-generic 5.15.131) [ 0.000000] Command line: rootfstype=virtiofs root=runcvmfs noresume nomodeset net.ifnames=1 init=/.runcvm/guest/scripts/runcvm-vm-init rw ipv6.disable=1 panic=-1 scsi_mod.scan=none tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests pci=lastbus=0 selinux=0 systemd.show_status=1 console=ttyS0 earlyprintk=serial [ 0.000000] KERNEL supported cpus: [ 0.000000] Intel GenuineIntel [ 0.000000] AMD AuthenticAMD [ 0.000000] Hygon HygonGenuine [ 0.000000] Centaur CentaurHauls [ 0.000000] zhaoxin Shanghai [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000001ffdefff] usable [ 0.000000] BIOS-e820: [mem 0x000000001ffdf000-0x000000001fffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] printk: bootconsole [earlyser0] enabled [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-20240107_171655-buildkitsandbox 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: cpu 0, msr 1a601001, primary cpu clock [ 0.000003] kvm-clock: using sched offset of 133706279894 cycles [ 0.000702] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.002870] tsc: Detected 2688.000 MHz processor [ 0.003729] last_pfn = 0x1ffdf max_arch_pfn = 0x400000000 [ 0.004519] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT Memory KASLR using RDRAND RDTSC... [ 0.025556] Using GB pages for direct mapping [ 0.026392] RAMDISK: [mem 0x1c34b000-0x1ffcffff] [ 0.027115] ACPI: Early table checksum verification disabled [ 0.028000] ACPI: RSDP 0x00000000000F5C00 000014 (v00 BOCHS ) [ 0.028716] ACPI: RSDT 0x000000001FFE259C 00003C (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.029743] ACPI: FACP 0x000000001FFE2114 0000F4 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.030808] ACPI: DSDT 0x000000001FFDF9C0 002754 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.031863] ACPI: FACS 0x000000001FFDF980 000040 [ 0.032452] ACPI: APIC 0x000000001FFE2208 000110 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.033502] ACPI: HPET 0x000000001FFE2318 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.034555] ACPI: SRAT 0x000000001FFE2350 0001E8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.035736] ACPI: MCFG 0x000000001FFE2538 00003C (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.036823] ACPI: WAET 0x000000001FFE2574 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.038064] ACPI: Reserving FACP table memory at [mem 0x1ffe2114-0x1ffe2207] [ 0.038965] ACPI: Reserving DSDT table memory at [mem 0x1ffdf9c0-0x1ffe2113] [ 0.039933] ACPI: Reserving FACS table memory at [mem 0x1ffdf980-0x1ffdf9bf] [ 0.040902] ACPI: Reserving APIC table memory at [mem 0x1ffe2208-0x1ffe2317] [ 0.041866] ACPI: Reserving HPET table memory at [mem 0x1ffe2318-0x1ffe234f] [ 0.042830] ACPI: Reserving SRAT table memory at [mem 0x1ffe2350-0x1ffe2537] [ 0.043787] ACPI: Reserving MCFG table memory at [mem 0x1ffe2538-0x1ffe2573] [ 0.044748] ACPI: Reserving WAET table memory at [mem 0x1ffe2574-0x1ffe259b] [ 0.045780] SRAT: PXM 0 -> APIC 0x00 -> Node 0 [ 0.046392] SRAT: PXM 0 -> APIC 0x01 -> Node 0 [ 0.046992] SRAT: PXM 0 -> APIC 0x02 -> Node 0 [ 0.047598] SRAT: PXM 0 -> APIC 0x03 -> Node 0 [ 0.048241] SRAT: PXM 0 -> APIC 0x04 -> Node 0 [ 0.048882] SRAT: PXM 0 -> APIC 0x05 -> Node 0 [ 0.049498] SRAT: PXM 0 -> APIC 0x06 -> Node 0 [ 0.050084] SRAT: PXM 0 -> APIC 0x07 -> Node 0 [ 0.050640] SRAT: PXM 0 -> APIC 0x08 -> Node 0 [ 0.051263] SRAT: PXM 0 -> APIC 0x09 -> Node 0 [ 0.051913] SRAT: PXM 0 -> APIC 0x0a -> Node 0 [ 0.052559] SRAT: PXM 0 -> APIC 0x0b -> Node 0 [ 0.053212] SRAT: PXM 0 -> APIC 0x0c -> Node 0 [ 0.053869] SRAT: PXM 0 -> APIC 0x0d -> Node 0 [ 0.054545] SRAT: PXM 0 -> APIC 0x0e -> Node 0 [ 0.055113] SRAT: PXM 0 -> APIC 0x0f -> Node 0 [ 0.055666] SRAT: PXM 0 -> APIC 0x10 -> Node 0 [ 0.056218] SRAT: PXM 0 -> APIC 0x11 -> Node 0 [ 0.056767] SRAT: PXM 0 -> APIC 0x12 -> Node 0 [ 0.057324] SRAT: PXM 0 -> APIC 0x13 -> Node 0 [ 0.057894] ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0x0009ffff] [ 0.058642] ACPI: SRAT: Node 0 PXM 0 [mem 0x00100000-0x1fffffff] [ 0.059382] NUMA: Node 0 [mem 0x00000000-0x0009ffff] + [mem 0x00100000-0x1ffdefff] -> [mem 0x00000000-0x1ffdefff] [ 0.060673] NODE_DATA(0) allocated [mem 0x1c321000-0x1c34afff] [ 0.062009] Zone ranges: [ 0.062341] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.063111] DMA32 [mem 0x0000000001000000-0x000000001ffdefff] [ 0.063871] Normal empty [ 0.064236] Device empty [ 0.064588] Movable zone start for each node [ 0.065208] Early memory node ranges [ 0.065756] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.066577] node 0: [mem 0x0000000000100000-0x000000001ffdefff] [ 0.067338] Initmem setup node 0 [mem 0x0000000000001000-0x000000001ffdefff] [ 0.068273] On node 0, zone DMA: 1 pages in unavailable ranges [ 0.068534] On node 0, zone DMA: 97 pages in unavailable ranges [ 0.076571] On node 0, zone DMA32: 33 pages in unavailable ranges [ 0.077785] ACPI: PM-Timer IO Port: 0x608 [ 0.079215] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.080019] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.080956] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.081823] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.082717] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.083502] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.084344] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.085433] ACPI: Using ACPI (MADT) for SMP configuration information [ 0.086241] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.086920] TSC deadline timer available [ 0.087542] smpboot: Allowing 20 CPUs, 0 hotplug CPUs [ 0.088286] kvm-guest: KVM setup pv remote TLB flush [ 0.089060] kvm-guest: setup PV sched yield [ 0.089689] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.090887] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.091955] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.092881] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.093894] [mem 0x20000000-0xafffffff] available for PCI devices [ 0.094775] Booting paravirtualized kernel on KVM [ 0.095530] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns [ 0.097283] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:20 nr_cpu_ids:20 nr_node_ids:1 [ 0.104903] percpu: Embedded 61 pages/cpu s212992 r8192 d28672 u262144 [ 0.106002] kvm-guest: setup async PF for cpu 0 [ 0.106720] kvm-guest: stealtime: cpu 0, msr 1b433080 [ 0.107474] kvm-guest: PV spinlocks enabled [ 0.108019] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.108967] Built 1 zonelists, mobility grouping on. Total pages: 128735 [ 0.109819] Policy zone: DMA32 [ 0.110286] Kernel command line: rootfstype=virtiofs root=runcvmfs noresume nomodeset net.ifnames=1 init=/.runcvm/guest/scripts/runcvm-vm-init rw ipv6.disable=1 panic=-1 scsi_mod.scan=none tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests pci=lastbus=0 selinux=0 systemd.show_status=1 console=ttyS0 earlyprintk=serial [ 0.115573] You have booted with nomodeset. This means your GPU drivers are DISABLED [ 0.116540] Any video related functionality will be severely degraded, and you may not even be able to suspend the system properly [ 0.118003] Unless you actually understand what nomodeset does, you should reboot without enabling it [ 0.120008] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes, linear) [ 0.121198] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes, linear) [ 0.122878] mem auto-init: stack:off, heap alloc:on, heap free:off [ 0.125895] Memory: 389260K/523764K available (16393K kernel code, 4393K rwdata, 10868K rodata, 3356K init, 18716K bss, 134244K reserved, 0K cma-reserved) [ 0.128725] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=20, Nodes=1 Poking KASLR using RDRAND RDTSC... [ 0.130068] ftrace: allocating 50637 entries in 198 pages [ 0.163544] ftrace: allocated 198 pages with 4 groups [ 0.164829] rcu: Hierarchical RCU implementation. [ 0.165520] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=20. [ 0.166576] All grace periods are expedited (rcu_expedited). [ 0.167432] Rude variant of Tasks RCU enabled. [ 0.168031] Tracing variant of Tasks RCU enabled. [ 0.168668] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. [ 0.169755] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=20 [ 0.176009] NR_IRQS: 524544, nr_irqs: 584, preallocated irqs: 16 [ 0.177144] random: crng init done [ 0.177729] Console: colour *CGA 80x25 [ 0.178277] printk: console [ttyS0] enabled [ 0.178277] printk: console [ttyS0] enabled [ 0.179481] printk: bootconsole [earlyser0] disabled [ 0.179481] printk: bootconsole [earlyser0] disabled [ 0.180899] ACPI: Core revision 20210730 [ 0.181616] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.183061] APIC: Switch to symmetric I/O mode setup [ 0.184043] x2apic enabled [ 0.184708] Switched APIC routing to physical x2apic. [ 0.185443] kvm-guest: setup PV IPIs [ 0.186905] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.187843] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x26bef67878b, max_idle_ns: 440795293631 ns [ 0.189611] Calibrating delay loop (skipped) preset value.. 5376.00 BogoMIPS (lpj=10752000) [ 0.191043] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.193708] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.194533] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.195386] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization [ 0.197603] Spectre V2 : Mitigation: Enhanced IBRS [ 0.198244] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch [ 0.199534] Spectre V2 : Spectre v2 / PBRSB-eIBRS: Retire a single CALL on VMEXIT [ 0.200659] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier [ 0.201602] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp [ 0.203014] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.204385] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.205598] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.206508] x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers' [ 0.207746] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.208761] x86/fpu: xstate_offset[9]: 832, xstate_sizes[9]: 8 [ 0.209598] x86/fpu: Enabled xstate features 0x207, context size is 840 bytes, using 'compacted' format. [ 0.236460] Freeing SMP alternatives memory: 44K [ 0.237310] pid_max: default: 32768 minimum: 301 [ 0.237646] LSM: Security Framework initializing [ 0.238393] landlock: Up and running. [ 0.238945] Yama: becoming mindful. [ 0.239619] AppArmor: AppArmor initialized [ 0.240274] Mount-cache hash table entries: 1024 (order: 1, 8192 bytes, linear) [ 0.241609] Mountpoint-cache hash table entries: 1024 (order: 1, 8192 bytes, linear) [ 0.243494] smpboot: CPU0: 12th Gen Intel(R) Core(TM) i7-12700H (family: 0x6, model: 0x9a, stepping: 0x3) [ 0.245302] Performance Events: unsupported p6 CPU model 154 no PMU driver, software events only. [ 0.245594] signal: max sigframe size: 3632 [ 0.245678] rcu: Hierarchical SRCU implementation. [ 0.247099] NMI watchdog: Perf NMI watchdog permanently disabled [ 0.248781] smp: Bringing up secondary CPUs ... [ 0.249827] x86: Booting SMP configuration: [ 0.250516] .... node #0, CPUs: #1 [ 0.012468] kvm-clock: cpu 1, msr 1a601041, secondary cpu clock [ 0.012468] smpboot: CPU 1 Converting physical 0 to logical die 1 [ 0.253809] kvm-guest: setup async PF for cpu 1 [ 0.254409] kvm-guest: stealtime: cpu 1, msr 1b473080 [ 0.255274] #2 [ 0.012468] kvm-clock: cpu 2, msr 1a601081, secondary cpu clock [ 0.012468] smpboot: CPU 2 Converting physical 0 to logical die 2 [ 0.258472] kvm-guest: setup async PF for cpu 2 [ 0.258472] kvm-guest: stealtime: cpu 2, msr 1b4b3080 [ 0.259052] #3 [ 0.012468] kvm-clock: cpu 3, msr 1a6010c1, secondary cpu clock [ 0.012468] smpboot: CPU 3 Converting physical 0 to logical die 3 [ 0.263242] kvm-guest: setup async PF for cpu 3 [ 0.263242] kvm-guest: stealtime: cpu 3, msr 1b4f3080 [ 0.263450] #4 [ 0.012468] kvm-clock: cpu 4, msr 1a601101, secondary cpu clock [ 0.012468] smpboot: CPU 4 Converting physical 0 to logical die 4 [ 0.268909] kvm-guest: setup async PF for cpu 4 [ 0.268909] kvm-guest: stealtime: cpu 4, msr 1b533080 [ 0.270251] #5 [ 0.012468] kvm-clock: cpu 5, msr 1a601141, secondary cpu clock [ 0.012468] smpboot: CPU 5 Converting physical 0 to logical die 5 [ 0.274816] kvm-guest: setup async PF for cpu 5 [ 0.274816] kvm-guest: stealtime: cpu 5, msr 1b573080 [ 0.275190] #6 [ 0.012468] kvm-clock: cpu 6, msr 1a601181, secondary cpu clock [ 0.012468] smpboot: CPU 6 Converting physical 0 to logical die 6 [ 0.280318] kvm-guest: setup async PF for cpu 6 [ 0.280318] kvm-guest: stealtime: cpu 6, msr 1b5b3080 [ 0.281945] #7 [ 0.012468] kvm-clock: cpu 7, msr 1a6011c1, secondary cpu clock [ 0.012468] smpboot: CPU 7 Converting physical 0 to logical die 7 [ 0.286894] kvm-guest: setup async PF for cpu 7 [ 0.286894] kvm-guest: stealtime: cpu 7, msr 1b5f3080 [ 0.290104] #8 [ 0.012468] kvm-clock: cpu 8, msr 1a601201, secondary cpu clock [ 0.012468] smpboot: CPU 8 Converting physical 0 to logical die 8 [ 0.294567] kvm-guest: setup async PF for cpu 8 [ 0.294872] kvm-guest: stealtime: cpu 8, msr 1b633080 [ 0.297844] #9 [ 0.012468] kvm-clock: cpu 9, msr 1a601241, secondary cpu clock [ 0.012468] smpboot: CPU 9 Converting physical 0 to logical die 9 [ 0.300778] kvm-guest: setup async PF for cpu 9 [ 0.300778] kvm-guest: stealtime: cpu 9, msr 1b673080 [ 0.302126] #10 [ 0.012468] kvm-clock: cpu 10, msr 1a601281, secondary cpu clock [ 0.012468] smpboot: CPU 10 Converting physical 0 to logical die 10 [ 0.306662] kvm-guest: setup async PF for cpu 10 [ 0.306662] kvm-guest: stealtime: cpu 10, msr 1b6b3080 [ 0.307271] #11 [ 0.012468] kvm-clock: cpu 11, msr 1a6012c1, secondary cpu clock [ 0.012468] smpboot: CPU 11 Converting physical 0 to logical die 11 [ 0.311806] kvm-guest: setup async PF for cpu 11 [ 0.311806] kvm-guest: stealtime: cpu 11, msr 1b6f3080 [ 0.313793] #12 [ 0.012468] kvm-clock: cpu 12, msr 1a601301, secondary cpu clock [ 0.012468] smpboot: CPU 12 Converting physical 0 to logical die 12 [ 0.318038] kvm-guest: setup async PF for cpu 12 [ 0.318873] kvm-guest: stealtime: cpu 12, msr 1b733080 [ 0.320283] #13 [ 0.012468] kvm-clock: cpu 13, msr 1a601341, secondary cpu clock [ 0.012468] smpboot: CPU 13 Converting physical 0 to logical die 13 [ 0.324482] kvm-guest: setup async PF for cpu 13 [ 0.324482] kvm-guest: stealtime: cpu 13, msr 1b773080 [ 0.326466] #14 [ 0.012468] kvm-clock: cpu 14, msr 1a601381, secondary cpu clock [ 0.012468] smpboot: CPU 14 Converting physical 0 to logical die 14 [ 0.329666] kvm-guest: setup async PF for cpu 14 [ 0.330414] kvm-guest: stealtime: cpu 14, msr 1b7b3080 [ 0.331347] #15 [ 0.012468] kvm-clock: cpu 15, msr 1a6013c1, secondary cpu clock [ 0.012468] smpboot: CPU 15 Converting physical 0 to logical die 15 [ 0.335123] kvm-guest: setup async PF for cpu 15 [ 0.335123] kvm-guest: stealtime: cpu 15, msr 1b7f3080 [ 0.335123] #16 [ 0.012468] kvm-clock: cpu 16, msr 1a601401, secondary cpu clock [ 0.012468] smpboot: CPU 16 Converting physical 0 to logical die 16 [ 0.340034] kvm-guest: setup async PF for cpu 16 [ 0.340034] kvm-guest: stealtime: cpu 16, msr 1b833080 [ 0.341995] #17 [ 0.012468] kvm-clock: cpu 17, msr 1a601441, secondary cpu clock [ 0.012468] smpboot: CPU 17 Converting physical 0 to logical die 17 [ 0.347043] kvm-guest: setup async PF for cpu 17 [ 0.347043] kvm-guest: stealtime: cpu 17, msr 1b873080 [ 0.350040] #18 [ 0.012468] kvm-clock: cpu 18, msr 1a601481, secondary cpu clock [ 0.012468] smpboot: CPU 18 Converting physical 0 to logical die 18 [ 0.353001] kvm-guest: setup async PF for cpu 18 [ 0.353001] kvm-guest: stealtime: cpu 18, msr 1b8b3080 [ 0.354010] #19 [ 0.012468] kvm-clock: cpu 19, msr 1a6014c1, secondary cpu clock [ 0.012468] smpboot: CPU 19 Converting physical 0 to logical die 19 [ 0.358675] kvm-guest: setup async PF for cpu 19 [ 0.358675] kvm-guest: stealtime: cpu 19, msr 1b8f3080 [ 0.359137] smp: Brought up 1 node, 20 CPUs [ 0.359137] smpboot: Max logical packages: 20 [ 0.361601] smpboot: Total of 20 processors activated (107520.00 BogoMIPS) [ 0.366214] devtmpfs: initialized [ 0.366777] x86/mm: Memory block size: 128MB [ 0.370194] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns [ 0.374461] futex hash table entries: 8192 (order: 7, 524288 bytes, linear) [ 0.377139] pinctrl core: initialized pinctrl subsystem [ 0.377998] PM: RTC time: 13:48:03, date: 2024-01-24 [ 0.380270] NET: Registered PF_NETLINK/PF_ROUTE protocol family [ 0.382356] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations [ 0.383574] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.385035] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.385636] audit: initializing netlink subsys (disabled) [ 0.386684] audit: type=2000 audit(1706104084.485:1): state=initialized audit_enabled=0 res=1 [ 0.386684] thermal_sys: Registered thermal governor 'fair_share' [ 0.386995] thermal_sys: Registered thermal governor 'bang_bang' [ 0.388230] thermal_sys: Registered thermal governor 'step_wise' [ 0.389606] thermal_sys: Registered thermal governor 'user_space' [ 0.390824] thermal_sys: Registered thermal governor 'power_allocator' [ 0.392074] EISA bus registered [ 0.394704] cpuidle: using governor ladder [ 0.394704] cpuidle: using governor menu [ 0.395690] ACPI: bus type PCI registered [ 0.397609] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.399189] PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xb0000000-0xbfffffff] (base 0xb0000000) [ 0.401071] PCI: MMCONFIG at [mem 0xb0000000-0xbfffffff] reserved in E820 [ 0.401638] PCI: Using configuration type 1 for base access [ 0.405785] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. [ 0.407523] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.407523] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.413805] ACPI: Added _OSI(Module Device) [ 0.414556] ACPI: Added _OSI(Processor Device) [ 0.415269] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.415988] ACPI: Added _OSI(Processor Aggregator Device) [ 0.416933] ACPI: Added _OSI(Linux-Dell-Video) [ 0.417631] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio) [ 0.418581] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics) [ 0.421142] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.423143] ACPI: Interpreter enabled [ 0.423931] ACPI: PM: (supports S0 S3 S4 S5) [ 0.424667] ACPI: Using IOAPIC for interrupt routing [ 0.425507] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.425602] PCI: Using E820 reservations for host bridge windows [ 0.426771] ACPI: Enabled 2 GPEs in block 00 to 3F [ 0.430864] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.431850] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI EDR HPX-Type3] [ 0.433412] acpi PNP0A08:00: _OSC: platform does not support [PCIeHotplug LTR DPC] [ 0.433675] acpi PNP0A08:00: _OSC: OS now controls [SHPCHotplug PME AER PCIeCapability] [ 0.435062] PCI host bridge to bus 0000:00 [ 0.435732] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.436636] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.437621] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.438762] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.440018] pci_bus 0000:00: root bus resource [mem 0x20000000-0xafffffff window] [ 0.441255] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.441598] pci_bus 0000:00: root bus resource [mem 0x100000000-0x8ffffffff window] [ 0.442971] pci 0000:00:00.0: [8086:29c0] type 00 class 0x060000 [ 0.444934] pci 0000:00:01.0: [1af4:1003] type 00 class 0x078000 [ 0.449081] pci 0000:00:01.0: reg 0x10: [io 0xc000-0xc03f] [ 0.452697] pci 0000:00:01.0: reg 0x14: [mem 0xfebfc000-0xfebfcfff] [ 0.463248] pci 0000:00:01.0: reg 0x20: [mem 0xfebec000-0xfebeffff 64bit pref] [ 0.468142] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 [ 0.472609] pci 0000:00:02.0: reg 0x10: [io 0xc080-0xc09f] [ 0.474811] pci 0000:00:02.0: reg 0x14: [mem 0xfebfd000-0xfebfdfff] [ 0.482906] pci 0000:00:02.0: reg 0x20: [mem 0xfebf0000-0xfebf3fff 64bit pref] [ 0.486726] pci 0000:00:03.0: [1af4:105a] type 00 class 0x018000 [ 0.492010] pci 0000:00:03.0: reg 0x14: [mem 0xfebfe000-0xfebfefff] [ 0.499079] pci 0000:00:03.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.503583] pci 0000:00:04.0: [1af4:1000] type 00 class 0x020000 [ 0.507066] pci 0000:00:04.0: reg 0x10: [io 0xc0a0-0xc0bf] [ 0.509605] pci 0000:00:04.0: reg 0x14: [mem 0xfebff000-0xfebfffff] [ 0.519112] pci 0000:00:04.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.532807] pci 0000:00:1f.0: [8086:2918] type 00 class 0x060100 [ 0.534158] pci 0000:00:1f.0: quirk: [io 0x0600-0x067f] claimed by ICH6 ACPI/GPIO/TCO [ 0.536083] pci 0000:00:1f.3: [8086:2930] type 00 class 0x0c0500 [ 0.543771] pci 0000:00:1f.3: reg 0x20: [io 0x0700-0x073f] [ 0.548579] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.549748] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.550721] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.551680] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.552613] ACPI: PCI: Interrupt link LNKE configured for IRQ 10 [ 0.553617] ACPI: PCI: Interrupt link LNKF configured for IRQ 10 [ 0.554616] ACPI: PCI: Interrupt link LNKG configured for IRQ 11 [ 0.555663] ACPI: PCI: Interrupt link LNKH configured for IRQ 11 [ 0.556690] ACPI: PCI: Interrupt link GSIA configured for IRQ 16 [ 0.557658] ACPI: PCI: Interrupt link GSIB configured for IRQ 17 [ 0.558700] ACPI: PCI: Interrupt link GSIC configured for IRQ 18 [ 0.559940] ACPI: PCI: Interrupt link GSID configured for IRQ 19 [ 0.561363] ACPI: PCI: Interrupt link GSIE configured for IRQ 20 [ 0.561615] ACPI: PCI: Interrupt link GSIF configured for IRQ 21 [ 0.562655] ACPI: PCI: Interrupt link GSIG configured for IRQ 22 [ 0.563679] ACPI: PCI: Interrupt link GSIH configured for IRQ 23 [ 0.566396] iommu: Default domain type: Translated [ 0.566493] iommu: DMA domain TLB invalidation policy: lazy mode [ 0.568477] SCSI subsystem initialized [ 0.569754] vgaarb: loaded [ 0.570202] ACPI: bus type USB registered [ 0.571033] usbcore: registered new interface driver usbfs [ 0.572094] usbcore: registered new interface driver hub [ 0.573026] usbcore: registered new device driver usb [ 0.573634] pps_core: LinuxPPS API ver. 1 registered [ 0.574676] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.576419] PTP clock support registered [ 0.577158] EDAC MC: Ver: 3.0.0 [ 0.577853] NetLabel: Initializing [ 0.578399] NetLabel: domain hash size = 128 [ 0.579501] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.580460] NetLabel: unlabeled traffic allowed by default [ 0.581653] PCI: Using ACPI for IRQ routing [ 0.587727] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.588483] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.596239] clocksource: Switched to clocksource kvm-clock [ 0.621330] VFS: Disk quotas dquot_6.6.0 [ 0.622160] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.623778] AppArmor: AppArmor Filesystem Enabled [ 0.624835] pnp: PnP ACPI init [ 0.625467] system 00:04: [mem 0xb0000000-0xbfffffff window] has been reserved [ 0.626912] pnp: PnP ACPI: found 5 devices [ 0.635560] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.637510] NET: Registered PF_INET protocol family [ 0.638547] IP idents hash table entries: 8192 (order: 4, 65536 bytes, linear) [ 0.640429] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.642264] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) [ 0.645315] TCP established hash table entries: 4096 (order: 3, 32768 bytes, linear) [ 0.646788] TCP bind hash table entries: 4096 (order: 4, 65536 bytes, linear) [ 0.648043] TCP: Hash tables configured (established 4096 bind 4096) [ 0.649421] MPTCP token hash table entries: 512 (order: 1, 12288 bytes, linear) [ 0.650710] UDP hash table entries: 256 (order: 1, 8192 bytes, linear) [ 0.652298] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear) [ 0.653728] NET: Registered PF_UNIX/PF_LOCAL protocol family [ 0.654612] NET: Registered PF_XDP protocol family [ 0.655395] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.656766] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.657968] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.658969] pci_bus 0000:00: resource 7 [mem 0x20000000-0xafffffff window] [ 0.660259] pci_bus 0000:00: resource 8 [mem 0xc0000000-0xfebfffff window] [ 0.661385] pci_bus 0000:00: resource 9 [mem 0x100000000-0x8ffffffff window] [ 0.662508] PCI: CLS 0 bytes, default 64 [ 0.663210] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x26bef67878b, max_idle_ns: 440795293631 ns [ 0.663371] Trying to unpack rootfs image as initramfs... [ 0.668047] Initialise system trusted keyrings [ 0.669338] Key type blacklist registered [ 0.670561] workingset: timestamp_bits=36 max_order=17 bucket_order=0 [ 0.675776] zbud: loaded [ 0.677672] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ 0.680089] fuse: init (API version 7.34) [ 0.682445] integrity: Platform Keyring initialized [ 0.693146] Key type asymmetric registered [ 0.693858] Asymmetric key parser 'x509' registered [ 0.694731] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) [ 0.696163] io scheduler mq-deadline registered [ 0.697881] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 0.699227] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 0.700567] ACPI: button: Power Button [PWRF] [ 0.702924] ACPI: \_SB_.GSIF: Enabled at IRQ 21 [ 0.705469] ACPI: \_SB_.GSIG: Enabled at IRQ 22 [ 0.707760] ACPI: \_SB_.GSIH: Enabled at IRQ 23 [ 0.709881] ACPI: \_SB_.GSIE: Enabled at IRQ 20 [ 0.712032] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled [ 0.736887] 00:02: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 0.756902] Linux agpgart interface v0.103 [ 0.771755] loop: module loaded [ 0.773692] tun: Universal TUN/TAP device driver, 1.6 [ 0.775232] PPP generic driver version 2.4.2 [ 0.776732] VFIO - User Level meta-driver version: 0.3 [ 0.778670] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver [ 0.780436] ehci-pci: EHCI PCI platform driver [ 0.781722] ehci-platform: EHCI generic platform driver [ 0.783128] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver [ 0.784714] ohci-pci: OHCI PCI platform driver [ 0.785925] ohci-platform: OHCI generic platform driver [ 0.787323] uhci_hcd: USB Universal Host Controller Interface driver [ 0.789099] i8042: PNP detection disabled [ 0.790644] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 0.792338] mousedev: PS/2 mouse device common for all mice [ 0.794251] input: AT Raw Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 0.796810] rtc_cmos 00:03: RTC can wake from S4 [ 0.798194] rtc_cmos 00:03: registered as rtc0 [ 0.799348] rtc_cmos 00:03: setting system clock to 2024-01-24T13:48:04 UTC (1706104084) [ 0.800739] rtc_cmos 00:03: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 0.801949] i2c_dev: i2c /dev entries driver [ 0.802756] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. [ 0.804894] device-mapper: uevent: version 1.0.3 [ 0.805854] device-mapper: ioctl: 4.45.0-ioctl (2021-03-22) initialised: dm-devel@redhat.com [ 0.807263] platform eisa.0: Probing EISA bus 0 [ 0.808037] platform eisa.0: EISA: Cannot allocate resource for mainboard [ 0.809300] platform eisa.0: Cannot allocate resource for EISA slot 1 [ 0.810492] platform eisa.0: Cannot allocate resource for EISA slot 2 [ 0.811762] platform eisa.0: Cannot allocate resource for EISA slot 3 [ 0.813023] platform eisa.0: Cannot allocate resource for EISA slot 4 [ 0.814276] platform eisa.0: Cannot allocate resource for EISA slot 5 [ 0.815376] platform eisa.0: Cannot allocate resource for EISA slot 6 [ 0.816439] platform eisa.0: Cannot allocate resource for EISA slot 7 [ 0.817446] platform eisa.0: Cannot allocate resource for EISA slot 8 [ 0.818438] platform eisa.0: EISA: Detected 0 cards [ 0.819224] intel_pstate: CPU model not supported [ 0.821085] ledtrig-cpu: registered to indicate activity on CPUs [ 0.822365] drop_monitor: Initializing network drop monitor service [ 0.823639] IPv6: Loaded, but administratively disabled, reboot required to enable [ 0.825055] NET: Registered PF_PACKET protocol family [ 0.826043] Key type dns_resolver registered [ 0.830963] IPI shorthand broadcast: enabled [ 0.832166] sched_clock: Marking stable (822341520, 8468229)->(875744850, -44935101) [ 0.835391] registered taskstats version 1 [ 0.838272] Loading compiled-in X.509 certificates [ 0.840265] Loaded X.509 cert 'Build time autogenerated kernel key: 5d922c8510ab93d63cb90d7e9088ad693f9da42f' [ 0.842381] Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' [ 0.844502] Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' [ 0.846170] blacklist: Loading compiled-in revocation X.509 certificates [ 0.847153] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' [ 0.848745] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' [ 0.850326] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' [ 0.851859] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' [ 0.853495] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' [ 0.855102] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' [ 0.856885] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' [ 0.858576] Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' [ 0.866152] zswap: loaded using pool lzo/zbud [ 0.873978] Key type .fscrypt registered [ 0.874824] Key type fscrypt-provisioning registered [ 1.307767] Freeing initrd memory: 61972K [ 1.314705] Key type encrypted registered [ 1.315429] AppArmor: AppArmor sha1 policy hashing enabled [ 1.316372] ima: No TPM chip found, activating TPM-bypass! [ 1.317313] Loading compiled-in module X.509 certificates [ 1.318669] Loaded X.509 cert 'Build time autogenerated kernel key: 5d922c8510ab93d63cb90d7e9088ad693f9da42f' [ 1.320132] ima: Allocated hash algorithm: sha1 [ 1.320944] ima: No architecture policies found [ 1.321658] evm: Initialising EVM extended attributes: [ 1.322445] evm: security.selinux [ 1.322955] evm: security.SMACK64 [ 1.323473] evm: security.SMACK64EXEC [ 1.324088] evm: security.SMACK64TRANSMUTE [ 1.324750] evm: security.SMACK64MMAP [ 1.325360] evm: security.apparmor [ 1.325933] evm: security.ima [ 1.326525] evm: security.capability [ 1.327097] evm: HMAC attrs: 0x1 [ 1.328083] PM: Magic number: 8:937:837 [ 1.329587] RAS: Correctable Errors collector initialized. [ 1.337384] Freeing unused decrypted memory: 2036K [ 1.338881] Freeing unused kernel image (initmem) memory: 3356K [ 1.360633] Write protecting the kernel read-only data: 30720k [ 1.362517] Freeing unused kernel image (text/rodata gap) memory: 2036K [ 1.364215] Freeing unused kernel image (rodata/data gap) memory: 1420K [ 1.377135] x86/mm: Checked W+X mappings: passed, no W+X pages found. [ 1.378235] Run /init as init process Loading, please wait... Starting version 249.11-0ubuntu3.11 [ 1.462517] lpc_ich 0000:00:1f.0: I/O space for GPIO uninitialized [ 1.468731] virtiofs virtio2: virtio_fs_setup_dax: No cache capability [ 1.483063] ACPI: \_SB_.GSIA: Enabled at IRQ 16 [ 1.484300] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt [ 1.485536] i2c i2c-0: 1/1 memory slots populated (from DMI) [ 1.486569] i2c i2c-0: Memory type 0x07 not supported yet, not instantiating SPD [ 1.494233] virtio_net virtio3 enp0s4: renamed from eth0 Begin: Loading essential drivers ... done. Begin: Running /scripts/init-premount ... done. Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done. Begin: Running /scripts/local-premount ... done. Warning: fsck not present, so skipping root file system done. Begin: Running /scripts/local-bottom ... done. Begin: Running /scripts/init-bottom ... done. [ 1.699663] virtio_net virtio3 eth0-tmp: renamed from enp0s4 [ 1.707290] virtio_net virtio3 eth0: renamed from eth0-tmp root@22ca5175a0de:/# ```
SmylerMC commented 8 months ago

I have managed to get qemu to start immediately by removing the network interface in the qemu command line (launching it by hand from the preqemu hook). However, I cannot find-out why it causes an issue. Changing options from the network device doesn't cut the delay, only removing the interface has so far.

Complete command line ```bash /.runcvm/guest/usr/bin/qemu-system-x86_64 \ '-no-user-config' '-nodefaults' '-no-reboot' \ '-action' 'panic=none' \ '-action' 'reboot=shutdown' \ '-enable-kvm' \ '-cpu' 'host,pmu=off' \ '-machine' 'q35,accel=kvm,usb=off,sata=off' \ '-device' 'isa-debug-exit' \ '-nographic' '-vga' 'none' \ '-m' '8192M' \ '-smp' '4,cores=1,threads=1,sockets=4,maxcpus=4' \ '-device' 'virtio-serial-pci,id=serial0' \ '-object' 'rng-random,id=rng0,filename=/dev/urandom' \ '-device' 'virtio-rng-pci,rng=rng0' \ '-numa' 'node,memdev=mem' \ '-object' 'memory-backend-file,id=mem,size=8192M,mem-path=/dev/shm,share=on,prealloc=off' \ '-chardev' 'socket,id=virtiofs,path=/run/.virtiofs.sock' \ '-device' 'vhost-user-fs-pci,queue-size=1024,chardev=virtiofs,tag=runcvmfs,ats=off' \ '-chardev' 'stdio,id=char0,mux=on,signal=off' \ '-serial' 'chardev:char0' \ '-mon' 'chardev=char0' \ '-echr' '20' \ '-chardev' 'socket,id=qemuguest0,path=/run/.qemu-guest-agent,server=on,wait=off' \ '-device' 'virtserialport,chardev=qemuguest0,name=org.qemu.guest_agent.0' \ '-monitor' 'unix:/run/.qemu-monitor-socket,server,nowait' \ '-kernel' '/.runcvm/guest/kernels/ubuntu/5.15.0-91-generic/vmlinuz' \ '-initrd' '/.runcvm/guest/kernels/ubuntu/5.15.0-91-generic/initrd' \ '-L' '/.runcvm/guest/usr/share/qemu' \ '-append' 'rootfstype=virtiofs root=runcvmfs noresume nomodeset net.ifnames=1 init=/.runcvm/guest/scripts/runcvm-vm-init rw ipv6.disable=1 panic=-1 scsi_mod.scan=none tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k cryptomgr.notests pci=lastbus=0 selinux=0 systemd.show_status=1 console=ttyS0 ' ```

The options I removed are the following:

    '-netdev' 'tap,id=qemu0,ifname=tap-eth0,script=/.runcvm/guest/scripts/runcvm-ctr-qemu-ifup,downscript=/.runcvm/guest/scripts/runcvm-ctr-qemu-ifdown' \
    '-device' 'virtio-net-pci,netdev=qemu0,mac=52:54:00:11:00:03,rombar=0' \
struanb commented 8 months ago

@SmylerMC Thanks so much for persisting with this. At least it seems we're getting somewhere!

Please would you try removing the script and downscript options from -netdev. That will tell us if it's the tap interface/virtio-net-pci device, or the scripts that set it up, that's causing the delay.

If the latter, we can debug the scripts by adding set -x to the beginning of the script.

If the former, then we could experiment with different -device drivers.

P.S. To make this change, just edit around line 97 of runcvm-scripts/runcvm-ctr-qemu:

   IFACES+=(
        -netdev tap,id=qemu$id,ifname=tap-$DOCKER_IF,script=$QEMU_IFUP,downscript=$QEMU_IFDOWN
        -device virtio-net-pci,netdev=qemu$id,mac=$mac,rombar=$id
    )
SmylerMC commented 8 months ago

I'm away from the keyboard right now, so I will try again later, but I did try removing the script options earlier and I don't think it changed anything.

As for the device type, I did remove the -device line, which should have made it fallback to a E1000 adapter if I'm not mistaken. That did nothing either.

I think I will try reproducing RuncVM's configuration as closely as I can outside of RunC to see if that could have anything to do with the container's configuration.

struanb commented 8 months ago

You could certainly change virtio-net-pci to e1000 in the -device line. I've tested RunCVM/QEMU boots with this change (although as the RunCVM kernel initrds do not contain the e1000 module, guest Linux network is not correctly configured).

struanb commented 8 months ago

Hi @SmylerMC have you had a chance to look at this again? I'm very keen to get to the bottom of it (although at the same time I still haven't been able to reproduce the issue on any test platform).

SmylerMC commented 8 months ago

I'm quite busy at the moment, but I'll probably come back to this in a week or so. I would really like to keep using RuncVM and it is really annoying.

SmylerMC commented 8 months ago

I just realized I did not come back to you about the network scripts and switching the network card to e1000, but neither did anything.