search

projectacrn / acrn-hypervisor

Project ACRN hypervisor
BSD 3-Clause "New" or "Revised" License
1.12k stars 513 forks source link

Cannot launch hard RT user VM with Ubuntu 20.04.3 and preempt-RT kernel 5.10.52-rt47 #6950

Closed christophsusen closed 2 years ago

christophsusen commented 2 years ago

Describe the bug Cannot launch hard RT user VM with Ubuntu 20.04.3 and preempt-RT kernel 5.10.52-rt47. The user VM gets stuck in the starting process when using the launch script for an RT-VM. When a launch script for a non-RT-VM is used with the same image, the VM starts successfully.

Platform Dell OptiPlex 5070 with Intel Core i7-9700, 8 GB RAM and 256 GB NVME SSD. The board configuration file can be found here.

Codebase ACRN kernel v2.6 ACRN hypervisor v2.6 SOS Ubuntu 20.04.3 UOS Ubuntu 20.04.3 with preempt-RT kernel 5.10.52-rt47

Scenario Custom scenario derived from the industry scenario. Scenario contains one non-RT-VM (VM number one) and one RT-VM (VM number two). These VMs are basically identical to VMs three and two from the industry scenario.

To Reproduce Steps to reproduce the behavior:

  1. Start user VM with Ubuntu 20.04.3 and preempt-RT kernel 5.10.52-rt47 using the launch script for the RT-VM in the industry scenario.

Expected Behavior From my point of understanding, my configuration should work and the RT user VM should start. If anything with my configuration is wrong, please let me know.

Additional Context

Thanks in advance for your help!

I changed the file ending to .txt for all uploaded files since GitHub does not accept .xml and .sh files.

fuzhongl commented 2 years ago

@christophsusen Is CONFIG_VIRTIO_PMD enabled in your RT-kernel config? If not, Please refer following patch: https://github.com/projectacrn/acrn-kernel/commit/0e8ea675e40db608646417fe99c0db32c5f6dd28

thanks!

christophsusen commented 2 years ago

Hi @fuzhongl, thanks for your reply!

I applied the patch you mentioned to the preempt-RT kernel running in my user VM and set CONFIG_VIRTIO_PMD=y in the kernel configuration file. Now it seems like the VM does not freeze at the point where it did before. However, as you can see, it is really slow and something seems to go wrong with the file system. Using the same image with the first launch script (non-RT-VM) still works without any problems.

[    0.743369] Run /init as init process
[    1.664655] virtio_blk virtio0: [vda] 104857600 512-byte logical blocks (53.7 GB/50.0 GiB)
[    1.664658] vda: detected capacity change from 0 to 53687091200
[    1.664714] virtio_blk virtio0: start polling timer: 10000000
[    1.894723] virtio_net virtio2: start polling timer: 10000000
[    1.897378] virtio_net virtio2 enp0s7: renamed from eth0
[    3.362435]  vda: vda1 vda2
[    3.506419] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2b3e459bf4c, max_idle_ns: 440795289890 ns
[    3.506464] clocksource: Switched to clocksource tsc
[    4.618746] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts: (null)
[   38.278595] systemd[1]: Inserted module 'autofs4'
[   38.498619] request_module fs-efivarfs succeeded, but still no fs?
[   38.568609] systemd[1]: systemd 245.4-4ubuntu3.13 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
[   38.568624] systemd[1]: Detected virtualization acrn.
[   38.568626] systemd[1]: Detected architecture x86-64.
[   70.661996] systemd[1]: Set hostname to <ssn-optiplex-5070-uos-3>.
[  103.792405] systemd[1]: Created slice system-modprobe.slice.
[  134.146657] systemd[1]: Created slice system-serial\x2dgetty.slice.
[  164.866674] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[  195.586647] systemd[1]: Created slice User and Session Slice.
[  226.306537] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[  257.026599] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[  287.746528] systemd[1]: Reached target User and Group Name Lookups.
[  318.466435] systemd[1]: Reached target Remote File Systems.
[  349.186511] systemd[1]: Reached target Slices.
[  379.906580] systemd[1]: Listening on Syslog Socket.
[  410.626614] systemd[1]: Listening on fsck to fsckd communication Socket.
[  441.346553] systemd[1]: Listening on initctl Compatibility Named Pipe.
[  472.066718] systemd[1]: Listening on Journal Audit Socket.
[  502.786594] systemd[1]: Listening on Journal Socket (/dev/log).
[  533.506599] systemd[1]: Listening on Journal Socket.
[  564.226627] systemd[1]: Listening on udev Control Socket.
[  594.946585] systemd[1]: Listening on udev Kernel Socket.
[  625.667221] systemd[1]: Mounting Huge Pages File System...
[  656.387105] systemd[1]: Mounting POSIX Message Queue File System...
[  687.107229] systemd[1]: Mounting Kernel Debug File System...
[  717.827131] systemd[1]: Mounting Kernel Trace File System...
[  748.547915] systemd[1]: Starting Journal Service...
[  779.267280] systemd[1]: Starting Set the console keyboard layout...
[  809.987270] systemd[1]: Starting Create list of static device nodes for the current kernel...
[  840.707282] systemd[1]: Starting Load Kernel Module drm...
[  871.444460] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[  871.444481] systemd[1]: Condition check resulted in File System Check on Root Device being skipped.
[  871.465218] systemd[1]: Starting Load Kernel Modules...
[  871.604972] lp: driver loaded but no devices found
[  871.626292] ppdev: user-space parallel port driver
[  902.147244] systemd[1]: Starting Remount Root and Kernel File Systems...
[  902.183799] EXT4-fs (vda2): re-mounted. Opts: errors=remount-ro
[  932.867297] systemd[1]: Starting udev Coldplug all Devices...
[  963.587163] systemd[1]: Starting Uncomplicated firewall...

So far I did not wait long enough to check if the VM starts successfully at all.

Do you have further suggestions on how to improve the situation?

Best regards, Christoph

fuzhongl commented 2 years ago

Usually, guest_flag isn't needed for post VM: Could you help to rebuild acrn with following change in scenario.xml? 

  <vm id="2">
    <vm_type>POST_RT_VM</vm_type>
    <guest_flags>
      <guest_flag>GUEST_FLAG_LAPIC_PASSTHROUGH</guest_flag>
      <guest_flag>GUEST_FLAG_RT</guest_flag>
    </guest_flags>

To

  <vm id="2">
    <vm_type>POST_RT_VM</vm_type>
    <guest_flags>
      <guest_flag>0</guest_flag>
    </guest_flags>

BR. Fuzhong

christophsusen commented 2 years ago

I made the changes to the scenario configuration and rebuild the hypervisor. Unfortunately, the start-up process of the VM is still awfully slow.

EDIT: I played around a little bit with the parameters in the launch script for the RTVM. When removing the --lapic_pt option, the problem disappears and the RTVM with preempt-RT Ubuntu starts successfully. Is this behavior as expected?

Thanks for your help!

Best regards, Christoph

christophsusen commented 2 years ago

Since I read at https://projectacrn.github.io/latest/tutorials/rtvm_performance_tips.html?highlight=lapic_pt#mandatory-options-for-an-rtvm that --lapic_pt is mandatory for RTVMs, I would still say that my issue is not resolved. Do you have any further ideas on what the problem could be?

Best regards, Christoph

fuzhongl commented 2 years ago

Could you please disable Hyper-thread in BIOS and re-generate the board.xml? Then rebuild acrn.bin with the updated board.xml.

Thanks!

BR. Fuzhong

christophsusen commented 2 years ago

Hi @fuzhongl, thanks for your answer!

I don't think that my CPU even supports hyper-threading. Here is the output that I get from lscpu:

Architecture:                    x86_64
CPU op-mode(s):                  32-bit, 64-bit
Byte Order:                      Little Endian
Address sizes:                   39 bits physical, 48 bits virtual
CPU(s):                          8
On-line CPU(s) list:             0-7
Thread(s) per core:              1
Core(s) per socket:              8
Socket(s):                       1
Vendor ID:                       GenuineIntel
CPU family:                      6
Model:                           158
Model name:                      Intel(R) Core(TM) i7-9700 CPU @ 3.00GHz
Stepping:                        13
CPU MHz:                         3000.000
CPU max MHz:                     3000.0000
CPU min MHz:                     800.0000
BogoMIPS:                        6000.00
L1d cache:                       256 KiB
L1i cache:                       256 KiB
L2 cache:                        2 MiB
L3 cache:                        12 MiB
Vulnerability Itlb multihit:     Processor vulnerable
Vulnerability L1tf:              Not affected
Vulnerability Mds:               Not affected
Vulnerability Meltdown:          Not affected
Vulnerability Spec store bypass: Mitigation; Speculative Store Bypass disabled via prctl and seccomp
Vulnerability Spectre v1:        Mitigation; usercopy/swapgs barriers and __user pointer sanitization
Vulnerability Spectre v2:        Mitigation; Enhanced IBRS, IBPB conditional, RSB filling
Vulnerability Srbds:             Mitigation; TSX disabled
Vulnerability Tsx async abort:   Mitigation; TSX disabled
Flags:                           fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl xtopolo
                                 gy nonstop_tsc cpuid aperfmperf pni pclmulqdq monitor est tm2 ssse3 fma cx16 xtpr pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor la
                                 hf_lm abm 3dnowprefetch cpuid_fault epb invpcid_single ssbd ibrs ibpb stibp ibrs_enhanced fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid rdseed adx smap clflushopt xsaveopt
                                 xsavec xgetbv1 xsaves dtherm arat pln pts hwp hwp_notify hwp_act_window hwp_epp md_clear flush_l1d arch_capabilities

Best regards, Christoph

fuzhongl commented 2 years ago

Could you please input vcpu_list and vm_console 2 in HV console with --lapic_pt in launch script?

Thanks!

BR. Fuzhong

christophsusen commented 2 years ago

This is the output of vcpu_list:

VM ID    PCPU ID    VCPU ID    VCPU ROLE    VCPU STATE    THREAD STATE
=====    =======    =======    =========    ==========    ==========
  0         0          0       PRIMARY      Running          BLOCKED
  0         1          1       SECONDARY    Running          BLOCKED
  0         2          2       SECONDARY    Running          BLOCKED
  0         3          3       SECONDARY    Running          BLOCKED
  2         4          0       PRIMARY      Running          RUNNING
  2         5          1       SECONDARY    Running          RUNNING
  2         6          2       SECONDARY    Running          RUNNING
  2         7          3       SECONDARY    Running          RUNNING

Please note that I changed the number of CPUs for the RTVM to 4 while experimenting with the problem.

This is the output I get when running vm_console 2:

[    0.000000] Linux version 5.10.52-rt47 (ssn@ssn-optiplex-5070-uos-3) (gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1 SMP PREEMPT_RT Tue Dec 7 16:44:17 CET 2021
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.10.52-rt47 root=UUID=74f2a1a0-ad7e-4bda-a851-f3efe55cb507 ro rootwait nohpet console=hvc0 console=ttyS0 no_timer_check ignore_loglevel log_buf_len=16M consoleblank=0 clocksource=tsc tsc=reliable x2apic_phys processor.max_cstate=0 intel_idle.max_cstate=0 intel_pstate=disable mce=ignore_ce audit=0 isolcpus=nohz,domain,1 nohz_full=1 rcu_nocbs=1 nosoftlockup idle=poll irqaffinity=0
[    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] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'compacted' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007e7d1fff] usable
[    0.000000] BIOS-e820: [mem 0x000000007e7d2000-0x000000007e7d2fff] reserved
[    0.000000] BIOS-e820: [mem 0x000000007e7d3000-0x000000007e7f4fff] usable
[    0.000000] BIOS-e820: [mem 0x000000007e7f5000-0x000000007e91afff] reserved
[    0.000000] BIOS-e820: [mem 0x000000007e91b000-0x000000007f99afff] usable
[    0.000000] BIOS-e820: [mem 0x000000007f99b000-0x000000007f9eefff] reserved
[    0.000000] BIOS-e820: [mem 0x000000007f9ef000-0x000000007f9f3fff] usable
[    0.000000] BIOS-e820: [mem 0x000000007f9f4000-0x000000007f9fafff] ACPI data
[    0.000000] BIOS-e820: [mem 0x000000007f9fb000-0x000000007f9fefff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x000000007f9ff000-0x000000007ffdffff] usable
[    0.000000] BIOS-e820: [mem 0x000000007ffe0000-0x000000007fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000e0000000-0x00000000efffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000ffe00000-0x00000000ffe1ffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000017fffffff] usable
[    0.000000] printk: debug: ignoring loglevel setting.
[    0.000000] process: using polling idle threads
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] efi: EFI v2.70 by ARCN
[    0.000000] efi: ACPI=0x7f9fa000 ACPI 2.0=0x7f9fa014 MEMATTR=0x7f559118 MOKvar=0x7f45f000
[    0.000000] DMI not present or invalid.
[    0.000000] Hypervisor detected: ACRN
[    0.000000] tsc: Detected 3000.000 MHz processor
[    0.000010] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000012] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000017] last_pfn = 0x180000 max_arch_pfn = 0x400000000
[    0.000037] MTRR default type: uncachable
[    0.000038] MTRR fixed ranges enabled:
[    0.000039]   00000-FFFFF write-back
[    0.000040] MTRR variable ranges enabled:
[    0.000169] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT
[    0.000669] CPU MTRRs all blank - virtualized system.
[    0.000674] last_pfn = 0x7ffe0 max_arch_pfn = 0x400000000
[    0.000742] found SMP MP-table at [mem 0x000f0000-0x000f000f]
[    0.000759] check: Scanning 1 areas for low memory corruption
[    0.000819] Using GB pages for direct mapping
[    0.008658] printk: log_buf_len: 16777216 bytes
[    0.008660] printk: early log buf free: 258736(98%)
[    0.008662] Secure boot disabled
[    0.008662] RAMDISK: [mem 0x3a30d000-0x3d060fff]
[    0.008666] ACPI: Early table checksum verification disabled
[    0.008671] ACPI: RSDP 0x000000007F9FA014 000024 (v02 DM    )
[    0.008675] ACPI: XSDT 0x000000007F9F90E8 000044 (v01 DM     DMFACP   00000001      01000013)
[    0.008681] ACPI: FACP 0x000000007F9F7000 00010C (v05 DM     DMFACP   00000001 INTL 20210105)
[    0.008687] ACPI: DSDT 0x000000007F9F4000 0008A2 (v02 DM     DMDSDT   00000001 INTL 20210105)
[    0.008691] ACPI: FACS 0x000000007F9FE000 000040
[    0.008694] ACPI: APIC 0x000000007F9F8000 00005E (v01 DM     DMMADT   00000001 INTL 20210105)
[    0.008697] ACPI: HPET 0x000000007F9F6000 000038 (v01 DM     DMHPET   00000001 INTL 20210105)
[    0.008701] ACPI: MCFG 0x000000007F9F5000 00003C (v01 DM     DMMCFG   00000001 INTL 20210105)
[    0.008703] ACPI: Reserving FACP table memory at [mem 0x7f9f7000-0x7f9f710b]
[    0.008705] ACPI: Reserving DSDT table memory at [mem 0x7f9f4000-0x7f9f48a1]
[    0.008706] ACPI: Reserving FACS table memory at [mem 0x7f9fe000-0x7f9fe03f]
[    0.008707] ACPI: Reserving APIC table memory at [mem 0x7f9f8000-0x7f9f805d]
[    0.008707] ACPI: Reserving HPET table memory at [mem 0x7f9f6000-0x7f9f6037]
[    0.008708] ACPI: Reserving MCFG table memory at [mem 0x7f9f5000-0x7f9f503b]
[    0.008765] ACPI: Local APIC address 0xfee00000
[    0.010080] No NUMA configuration found
[    0.010081] Faking a node at [mem 0x0000000000000000-0x000000017fffffff]
[    0.010090] NODE_DATA(0) allocated [mem 0x17b7d5000-0x17b7fffff]
[    0.010393] Zone ranges:
[    0.010393]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.010395]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
[    0.010397]   Normal   [mem 0x0000000100000000-0x000000017fffffff]
[    0.010398]   Device   empty
[    0.010399] Movable zone start for each node
[    0.010401] Early memory node ranges
[    0.010402]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.010403]   node   0: [mem 0x0000000000100000-0x000000007e7d1fff]
[    0.010404]   node   0: [mem 0x000000007e7d3000-0x000000007e7f4fff]
[    0.010405]   node   0: [mem 0x000000007e91b000-0x000000007f99afff]
[    0.010405]   node   0: [mem 0x000000007f9ef000-0x000000007f9f3fff]
[    0.010406]   node   0: [mem 0x000000007f9ff000-0x000000007ffdffff]
[    0.010407]   node   0: [mem 0x0000000100000000-0x000000017fffffff]
[    0.010408] Initmem setup node 0 [mem 0x0000000000001000-0x000000017fffffff]
[    0.010409] On node 0 totalpages: 1048057
[    0.010411]   DMA zone: 64 pages used for memmap
[    0.010412]   DMA zone: 22 pages reserved
[    0.010412]   DMA zone: 3999 pages, LIFO batch:0
[    0.010715]   DMA zone: 28769 pages in unavailable ranges
[    0.010716]   DMA32 zone: 8122 pages used for memmap
[    0.010717]   DMA32 zone: 519770 pages, LIFO batch:63
[    0.013431]   DMA32 zone: 422 pages in unavailable ranges
[    0.013433]   Normal zone: 8192 pages used for memmap
[    0.013434]   Normal zone: 524288 pages, LIFO batch:63
[    0.017519] ACPI: Local APIC address 0xfee00000
[    0.017529] ACPI: LAPIC_NMI (acpi_id[0xff] high edge lint[0x1])
[    0.017558] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-47
[    0.017563] ACPI: IRQ9 used by override.
[    0.017565] Using ACPI (MADT) for SMP configuration information
[    0.017567] ACPI: HPET id: 0x80860701 base: 0xfed00000
[    0.017570] TSC deadline timer available
[    0.017574] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[    0.017591] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.017593] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000fffff]
[    0.017595] PM: hibernation: Registered nosave memory: [mem 0x7e7d2000-0x7e7d2fff]
[    0.017596] PM: hibernation: Registered nosave memory: [mem 0x7e7f5000-0x7e91afff]
[    0.017597] PM: hibernation: Registered nosave memory: [mem 0x7f99b000-0x7f9eefff]
[    0.017599] PM: hibernation: Registered nosave memory: [mem 0x7f9f4000-0x7f9fafff]
[    0.017599] PM: hibernation: Registered nosave memory: [mem 0x7f9fb000-0x7f9fefff]
[    0.017600] PM: hibernation: Registered nosave memory: [mem 0x7ffe0000-0x7fffffff]
[    0.017601] PM: hibernation: Registered nosave memory: [mem 0x80000000-0xdfffffff]
[    0.017602] PM: hibernation: Registered nosave memory: [mem 0xe0000000-0xefffffff]
[    0.017602] PM: hibernation: Registered nosave memory: [mem 0xf0000000-0xffdfffff]
[    0.017603] PM: hibernation: Registered nosave memory: [mem 0xffe00000-0xffe1ffff]
[    0.017603] PM: hibernation: Registered nosave memory: [mem 0xffe20000-0xffffffff]
[    0.017607] [mem 0x80000000-0xdfffffff] available for PCI devices
[    0.017608] Booting paravirtualized kernel on bare hardware
[    0.017612] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.017621] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1
[    0.017755] percpu: Embedded 53 pages/cpu s180224 r8192 d28672 u524288
[    0.017761] pcpu-alloc: s180224 r8192 d28672 u524288 alloc=1*2097152
[    0.017763] pcpu-alloc: [0] 0 1 2 3
[    0.017786] Built 1 zonelists, mobility grouping on.  Total pages: 1031657
[    0.017787] Policy zone: Normal
[    0.017788] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.10.52-rt47 root=UUID=74f2a1a0-ad7e-4bda-a851-f3efe55cb507 ro rootwait nohpet console=hvc0 console=ttyS0 no_timer_check ignore_loglevel log_buf_len=16M consoleblank=0 clocksource=tsc tsc=reliable x2apic_phys processor.max_cstate=0 intel_idle.max_cstate=0 intel_pstate=disable mce=ignore_ce audit=0 isolcpus=nohz,domain,1 nohz_full=1 rcu_nocbs=1 nosoftlockup idle=poll irqaffinity=0
[    0.017965] audit: disabled (until reboot)
[    0.017979] Housekeeping: nohz unsupported. Build with CONFIG_NO_HZ_FULL
[    0.017999] Housekeeping: nohz unsupported. Build with CONFIG_NO_HZ_FULL
[    0.018266] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[    0.018374] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.018448] mem auto-init: stack:off, heap alloc:on, heap free:off
[    0.029282] Memory: 3896140K/4192228K available (16393K kernel code, 3947K rwdata, 5404K rodata, 2576K init, 5624K bss, 295828K reserved, 0K cma-reserved)
[    0.029290] random: get_random_u64 called from __kmem_cache_create+0x2d/0x3d0 with crng_init=0
[    0.029402] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.029418] ftrace: allocating 47827 entries in 187 pages
[    0.045211] ftrace: allocated 187 pages with 6 groups
[    0.045311] rcu: Preemptible hierarchical RCU implementation.
[    0.045312] rcu:     RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4.
[    0.045313] rcu:     RCU priority boosting: priority 1 delay 500 ms.
[    0.045314] rcu:     RCU_SOFTIRQ processing moved to rcuc kthreads.
[    0.045314]  No expedited grace period (rcu_normal_after_boot).
[    0.045314]  Trampoline variant of Tasks RCU enabled.
[    0.045315]  Rude variant of Tasks RCU enabled.
[    0.045315]  Tracing variant of Tasks RCU enabled.
[    0.045316] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.045317] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.048994] Using NULL legacy PIC
[    0.048994] NR_IRQS: 524544, nr_irqs: 864, preallocated irqs: 0
[    0.049640] random: crng done (trusting CPU's manufacturer)
[    0.049664] Console: colour dummy device 80x25
[    0.049681] printk: console [ttyS0] enabled
[    0.049699] ACPI: Core revision 20200925
[    0.049965] APIC: Switch to symmetric I/O mode setup
[    0.050411] x2apic enabled
[    0.050841] Switched APIC routing to physical x2apic.
[    0.050875] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2b3e459bf4c, max_idle_ns: 440795289890 ns
[    0.050880] Calibrating delay loop (skipped), value calculated using timer frequency.. 6000.00 BogoMIPS (lpj=12000000)
[    0.050882] pid_max: default: 32768 minimum: 301
[    0.050907] LSM: Security Framework initializing
[    0.050913] Yama: becoming mindful.
[    0.050934] AppArmor: AppArmor initialized
[    0.050969] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.050976] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.051324] mce: CPU0: Thermal monitoring enabled (TM1)
[    0.051330] Last level iTLB entries: 4KB 128, 2MB 8, 4MB 8
[    0.051331] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
[    0.051336] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.051338] Spectre V2 : Mitigation: Enhanced IBRS
[    0.051339] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.051340] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
[    0.051342] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.051342] TAA: Mitigation: TSX disabled
[    0.051343] SRBDS: Mitigation: TSX disabled
[    0.051572] Freeing SMP alternatives memory: 36K
[    0.052362] smpboot: CPU0: Intel(R) Core(TM) i7-9700 CPU @ 3.00GHz (family: 0x6, model: 0x9e, stepping: 0xd)
[    0.052524] Performance Events: Skylake events, 32-deep LBR, Intel PMU driver.
[    0.052573] ... version:                4
[    0.052574] ... bit width:              48
[    0.052574] ... generic registers:      8
[    0.052575] ... value mask:             0000ffffffffffff
[    0.052575] ... max period:             000000007fffffff
[    0.052576] ... fixed-purpose events:   3
[    0.052576] ... event mask:             00000007000000ff
[    0.052662] rcu: Hierarchical SRCU implementation.
[    0.053082] NMI watchdog: Enabled. Permanently consumes one hw-PMU counter.
[    0.053132] smp: Bringing up secondary CPUs ...
[    0.053250] x86: Booting SMP configuration:
[    0.053251] .... node  #0, CPUs:      #1 #2 #3
[    0.585153] smp: Brought up 1 node, 4 CPUs
[    0.585153] smpboot: Max logical packages: 1
[    0.585153] smpboot: Total of 4 processors activated (24000.00 BogoMIPS)
[    0.585153] devtmpfs: initialized
[    0.585153] x86/mm: Memory block size: 128MB
[    0.586892] PM: Registering ACPI NVS region [mem 0x7f9fb000-0x7f9fefff] (16384 bytes)
[    0.586932] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.586942] futex hash table entries: 1024 (order: 5, 131072 bytes, linear)
[    0.586994] pinctrl core: initialized pinctrl subsystem
[    0.588870] PM: RTC time: 07:01:26, date: 2021-12-13
[    0.589009] NET: Registered protocol family 16
[    0.589200] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations
[    0.589233] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.589265] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.589380] thermal_sys: Registered thermal governor 'fair_share'
[    0.589381] thermal_sys: Registered thermal governor 'bang_bang'
[    0.589381] thermal_sys: Registered thermal governor 'step_wise'
[    0.589382] thermal_sys: Registered thermal governor 'user_space'
[    0.589382] thermal_sys: Registered thermal governor 'power_allocator'
[    0.589387] EISA bus registered
[    0.589413] cpuidle: using governor ladder
[    0.589416] cpuidle: using governor menu
[    0.589416] ACPI FADT declares the system doesn't support PCIe ASPM, so disable it
[    0.589416] ACPI: bus type PCI registered
[    0.589416] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.589416] PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xe0000000-0xefffffff] (base 0xe0000000)
[    0.589416] PCI: MMCONFIG at [mem 0xe0000000-0xefffffff] reserved in E820
[    0.589416] PCI: Using configuration type 1 for base access
[    0.591353] Kprobes globally optimized
[    0.591353] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.591353] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.591353] ACPI: Added _OSI(Module Device)
[    0.591353] ACPI: Added _OSI(Processor Device)
[    0.591353] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.591353] ACPI: Added _OSI(Processor Aggregator Device)
[    0.591353] ACPI: Added _OSI(Linux-Dell-Video)
[    0.591353] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.591353] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    0.591419] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.591661] ACPI: Interpreter enabled
[    0.591661] ACPI: (supports S0 S3 S5)
[    0.591661] ACPI: Using IOAPIC for interrupt routing
[    0.591661] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.591661] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00])
[    0.591661] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]
[    0.591661] PCI host bridge to bus 0000:00
[    0.591661] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.591661] pci_bus 0000:00: root bus resource [io  0x0d00-0x1fff window]
[    0.591661] pci_bus 0000:00: root bus resource [io  0x2000-0x60ff window]
[    0.591661] pci_bus 0000:00: root bus resource [mem 0x80000000-0xdfffffff window]
[    0.591661] pci_bus 0000:00: root bus resource [mem 0x4000000000-0x7fffffffff window]
[    0.591661] pci_bus 0000:00: root bus resource [bus 00]
[    0.591777] pci 0000:00:00.0: [1275:1275] type 00 class 0x060000
[    0.594869] pci 0000:00:04.0: [10ec:8168] type 00 class 0x020000
[    0.594914] pci 0000:00:04.0: reg 0x10: [io  0x6000-0x60ff]
[    0.594982] pci 0000:00:04.0: reg 0x18: [mem 0x4000000000-0x4000000fff 64bit]
[    0.595026] pci 0000:00:04.0: reg 0x20: [mem 0x4000004000-0x4000007fff 64bit pref]
[    0.595052] pci 0000:00:04.0: [Firmware Bug]: reg 0x30: invalid BAR (can't size)
[    0.595233] pci 0000:00:04.0: supports D1 D2
[    0.595234] pci 0000:00:04.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.596438] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000
[    0.596996] pci 0000:00:06.0: reg 0x10: [io  0x2000-0x207f]
[    0.597299] pci 0000:00:06.0: reg 0x14: [mem 0x80000000-0x80001fff]
[    0.601474] pci 0000:00:08.0: [1af4:1003] type 00 class 0x078000
[    0.602031] pci 0000:00:08.0: reg 0x10: [io  0x3000-0x303f]
[    0.602333] pci 0000:00:08.0: reg 0x14: [mem 0x80002000-0x80003fff]
[    0.606889] pci 0000:00:09.0: [1af4:1000] type 00 class 0x020000
[    0.606889] pci 0000:00:09.0: reg 0x10: [io  0x4000-0x401f]
[    0.607008] pci 0000:00:09.0: reg 0x14: [mem 0x80004000-0x80005fff]
[    0.618889] iommu: Default domain type: Translated
[    0.618896] vgaarb: loaded
[    0.619034] SCSI subsystem initialized
[    0.619039] libata version 3.00 loaded.
[    0.619039] ACPI: bus type USB registered
[    0.619039] usbcore: registered new interface driver usbfs
[    0.619039] usbcore: registered new interface driver hub
[    0.619039] usbcore: registered new device driver usb
[    0.619039] pps_core: LinuxPPS API ver. 1 registered
[    0.619039] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.619039] PTP clock support registered
[    0.619039] EDAC MC: Ver: 3.0.0
[    0.619260] NetLabel: Initializing
[    0.619260] NetLabel:  domain hash size = 128
[    0.619260] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.619260] NetLabel:  unlabeled traffic allowed by default
[    0.619260] PCI: Using ACPI for IRQ routing
[    1.034790] PCI: pci_cache_line_size set to 64 bytes
[    1.035133] e820: reserve RAM buffer [mem 0x7e7d2000-0x7fffffff]
[    1.035135] e820: reserve RAM buffer [mem 0x7e7f5000-0x7fffffff]
[    1.035136] e820: reserve RAM buffer [mem 0x7f99b000-0x7fffffff]
[    1.035137] e820: reserve RAM buffer [mem 0x7f9f4000-0x7fffffff]
[    1.035138] e820: reserve RAM buffer [mem 0x7ffe0000-0x7fffffff]
[    1.035142] clocksource: Switched to clocksource tsc-early
[    1.050814] VFS: Disk quotas dquot_6.6.0
[    1.050826] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    1.050953] AppArmor: AppArmor Filesystem Enabled
[    1.050978] pnp: PnP ACPI init
[    1.051003] pnp: PnP ACPI: found 0 devices
[    1.052191] NET: Registered protocol family 2
[    1.052246] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    1.052769] tcp_listen_portaddr_hash hash table entries: 2048 (order: 5, 131072 bytes, linear)
[    1.052800] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    1.052953] TCP bind hash table entries: 32768 (order: 8, 1835008 bytes, linear)
[    1.053119] TCP: Hash tables configured (established 32768 bind 32768)
[    1.053195] MPTCP token hash table entries: 4096 (order: 6, 294912 bytes, linear)
[    1.053241] UDP hash table entries: 2048 (order: 6, 262144 bytes, linear)
[    1.053281] UDP-Lite hash table entries: 2048 (order: 6, 262144 bytes, linear)
[    1.053467] NET: Registered protocol family 1
[    1.053472] NET: Registered protocol family 44
[    1.053478] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    1.053481] pci_bus 0000:00: resource 5 [io  0x0d00-0x1fff window]
[    1.053482] pci_bus 0000:00: resource 6 [io  0x2000-0x60ff window]
[    1.053483] pci_bus 0000:00: resource 7 [mem 0x80000000-0xdfffffff window]
[    1.053485] pci_bus 0000:00: resource 8 [mem 0x4000000000-0x7fffffffff window]
[    1.053687] PCI: CLS 64 bytes, default 64
[    1.053723] Trying to unpack rootfs image as initramfs...
[    1.182108] Freeing initrd memory: 46416K
[    1.182129] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    1.182130] software IO TLB: mapped [mem 0x000000007a2a1000-0x000000007e2a1000] (64MB)
[    1.182281] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    1.182401] check: Scanning for low memory corruption every 60 seconds
[    1.182746] Initialise system trusted keyrings
[    1.182764] Key type blacklist registered
[    1.182791] workingset: timestamp_bits=36 max_order=20 bucket_order=0
[    1.184073] zbud: loaded
[    1.184381] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    1.184498] fuse: init (API version 7.32)
[    1.184647] integrity: Platform Keyring initialized
[    1.191919] Key type asymmetric registered
[    1.191920] Asymmetric key parser 'x509' registered
[    1.191927] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243)
[    1.191952] io scheduler mq-deadline registered
[    1.192075] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    1.192164] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    1.194924] ACPI: Power Button [PWRF]
[    1.195324] virtio-pci 0000:00:06.0: can't derive routing for PCI INT A
[    1.195327] virtio-pci 0000:00:06.0: PCI INT A: not connected
[    1.195592] virtio-pci 0000:00:06.0: virtio_pci: leaving for legacy driver
[    1.195907] virtio-pci 0000:00:08.0: can't derive routing for PCI INT A
[    1.195907] virtio-pci 0000:00:08.0: PCI INT A: not connected
[    1.196173] virtio-pci 0000:00:08.0: virtio_pci: leaving for legacy driver
[    1.196476] virtio-pci 0000:00:09.0: can't derive routing for PCI INT A
[    1.196477] virtio-pci 0000:00:09.0: PCI INT A: not connected
[    1.196740] virtio-pci 0000:00:09.0: virtio_pci: leaving for legacy driver
[    1.197046] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[    1.198439] serial8250: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    1.199852] serial8250: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[    1.221563] virtio_console virtio1: start polling timer: 10000000
[    1.221742] hpet_acpi_add: no address or irqs in _CRS
[    1.221765] Linux agpgart interface v0.103
[    1.231817] printk: console [hvc0] enabled
[    1.370904] loop: module loaded
[    1.371142] libphy: Fixed MDIO Bus: probed
[    1.371143] tun: Universal TUN/TAP device driver, 1.6
[    1.371163] PPP generic driver version 2.4.2
[    1.371200] VFIO - User Level meta-driver version: 0.3
[    1.371239] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.371242] ehci-pci: EHCI PCI platform driver
[    1.371249] ehci-platform: EHCI generic platform driver
[    1.371253] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.371255] ohci-pci: OHCI PCI platform driver
[    1.371260] ohci-platform: OHCI generic platform driver
[    1.371265] uhci_hcd: USB Universal Host Controller Interface driver
[    1.371289] i8042: PNP: No PS/2 controller found.
[    1.371326] mousedev: PS/2 mouse device common for all mice
[    1.373495] rtc_cmos rtc_cmos: registered as rtc0
[    1.373972] rtc_cmos rtc_cmos: setting system clock to 2021-12-13T07:01:26 UTC (1639378886)
[    1.373988] rtc_cmos rtc_cmos: alarms up to one day, y3k, 114 bytes nvram
[    1.373993] i2c /dev entries driver
[    1.374030] device-mapper: uevent: version 1.0.3
[    1.374071] device-mapper: ioctl: 4.43.0-ioctl (2020-10-01) initialised: dm-devel@redhat.com
[    1.374087] platform eisa.0: Probing EISA bus 0
[    1.374089] platform eisa.0: EISA: Cannot allocate resource for mainboard
[    1.374091] platform eisa.0: Cannot allocate resource for EISA slot 1
[    1.374092] platform eisa.0: Cannot allocate resource for EISA slot 2
[    1.374093] platform eisa.0: Cannot allocate resource for EISA slot 3
[    1.374094] platform eisa.0: Cannot allocate resource for EISA slot 4
[    1.374095] platform eisa.0: Cannot allocate resource for EISA slot 5
[    1.374096] platform eisa.0: Cannot allocate resource for EISA slot 6
[    1.374213] platform eisa.0: EISA: Detected 0 cards
[    1.374364] intel_pmc_core intel_pmc_core.0:  initialized
[    1.374394] drop_monitor: Initializing network drop monitor service
[    1.374523] NET: Registered protocol family 10
[    1.379641] Segment Routing with IPv6
[    1.379661] NET: Registered protocol family 17
[    1.379695] Key type dns_resolver registered
[    1.379920] IPI shorthand broadcast: enabled
[    1.379926] sched_clock: Marking stable (1378439663, 1381825)->(1401392005, -21570517)
[    1.379996] printk: console [ttyS0]: printing thread started
[    1.380010] printk: console [hvc0]: printing thread started
[    1.380028] registered taskstats version 1
[    1.380038] Loading compiled-in X.509 certificates
[    1.380588] Loaded X.509 cert 'Build time autogenerated kernel key: 4f9dcdb23e9a96c61e60b71c903bb572c33524ee'
[    1.380612] zswap: loaded using pool lzo/zbud
[    1.380728] Key type ._fscrypt registered
[    1.380729] Key type .fscrypt registered
[    1.380730] Key type fscrypt-provisioning registered
[    1.383176] Key type encrypted registered
[    1.383179] AppArmor: AppArmor sha1 policy hashing enabled
[    1.383187] ima: No TPM chip found, activating TPM-bypass!
[    1.383193] ima: Allocated hash algorithm: sha1
[    1.383199] ima: No architecture policies found
[    1.383211] evm: Initialising EVM extended attributes:
[    1.383211] evm: security.selinux
[    1.383212] evm: security.SMACK64
[    1.383213] evm: security.SMACK64EXEC
[    1.383213] evm: security.SMACK64TRANSMUTE
[    1.383213] evm: security.SMACK64MMAP
[    1.383214] evm: security.apparmor
[    1.383214] evm: security.ima
[    1.383214] evm: security.capability
[    1.383215] evm: HMAC attrs: 0x1
[    1.383422] PM:   Magic number: 1:715:15
[    1.443353] RAS: Correctable Errors collector initialized.
[    1.444641] Freeing unused decrypted memory: 2036K
[    1.444943] Freeing unused kernel image (initmem) memory: 2576K
[    1.462888] Write protecting the kernel read-only data: 24576k
[    1.745734] Freeing unused kernel image (text/rodata gap) memory: 2036K
[    1.745870] Freeing unused kernel image (rodata/data gap) memory: 740K
[    1.757801] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    1.757809] Run /init as init process
[    1.757810]   with arguments:
[    1.757811]     /init
[    1.757812]   with environment:
[    1.757812]     HOME=/
[    1.757813]     TERM=linux
[    1.757813]     BOOT_IMAGE=/boot/vmlinuz-5.10.52-rt47
[    1.757814]     isolcpus=nohz,domain,1
[    1.757815]     nohz_full=1
[    1.757815]     rcu_nocbs=1
[    2.370892] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2b3e459bf4c, max_idle_ns: 440795289890 ns
[    2.370915] clocksource: Switched to clocksource tsc
[    2.603835] virtio_blk virtio0: [vda] 104857600 512-byte logical blocks (53.7 GB/50.0 GiB)
[    2.603839] vda: detected capacity change from 0 to 53687091200
[    2.603907] virtio_blk virtio0: start polling timer: 10000000
[    3.292834] virtio_net virtio2: start polling timer: 10000000
[    3.293146] libphy: r8169: probed
[    3.305549] r8169 0000:00:04.0 eth1: RTL8168e/8111e, 3c:49:37:07:07:11, XID 2c2, IRQ 84
[    3.305553] r8169 0000:00:04.0 eth1: jumbo features [frames: 9194 bytes, tx checksumming: ko]
[    3.436116] virtio_net virtio2 enp0s9: renamed from eth0
[    3.454996] r8169 0000:00:04.0 enp0s4: renamed from eth1
[    4.284802]  vda: vda1 vda2
[    5.565435] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts: (null)
[   38.293042] systemd[1]: Inserted module 'autofs4'
[   38.512101] request_module fs-efivarfs succeeded, but still no fs?
[   38.582060] systemd[1]: systemd 245.4-4ubuntu3.13 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
[   38.582082] systemd[1]: Detected virtualization acrn.
[   38.582085] systemd[1]: Detected architecture x86-64.
[   68.627883] systemd[1]: Set hostname to <ssn-optiplex-5070-uos-3>.
[  101.756394] systemd[1]: Created slice system-modprobe.slice.
[  132.111189] systemd[1]: Created slice system-serial\x2dgetty.slice.

The VM is not completely stuck at that point. There are new messages being printed really slowly. However, I never had the VM start completely even when I waited very long.

Best regards, Christoph

fuzhongl commented 2 years ago

@mcao6 Could you please help to check the boot issue for RTVM? Thanks!

BR. Fuzhong

mgcao commented 2 years ago

@christophsusen just checked the history of this issue. it is a strange issue, please help to check following:

  1. add no_ipi_broadcast=1 to your RTVM bootargs, and boot to check.
  2. if still slow, just as your test, remove --lapic_pt, and boot to put the "dmesg" of VM2 info here, let me compare.

from the log: [ 5.565435] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts: (null) [ 38.293042] systemd[1]: Inserted module 'autofs4'

the time seems spending on FS module. but not sure why.

christophsusen commented 2 years ago

Hi @mgcao, thanks for your quick answer!

I added no_ipi_broadcast=1 to the kernel command line of the RTVM. Unfortunately, that did not change the situation.

Afterwards, I removed --lapic_pt from the launch script and added --rtvm to obtain the following dmesg output:

[    0.000000] Linux version 5.10.52-rt47 (ssn@ssn-optiplex-5070-uos-3) (gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1 SMP PREEMPT_RT Tue Dec 7 16:44:17 CET 2021
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.10.52-rt47 root=UUID=74f2a1a0-ad7e-4bda-a851-f3efe55cb507 ro rootwait nohpet console=hvc0 console=ttyS0 no_timer_check ignore_loglevel log_buf_len=16M consoleblank=0 clocksource=tsc tsc=reliable x2apic_phys processor.max_cstate=0 intel_idle.max_cstate=0 intel_pstate=disable mce=ignore_ce audit=0 isolcpus=nohz,domain,1 nohz_full=1 rcu_nocbs=1 nosoftlockup idle=poll irqaffinity=0 no_ipi_broadcast=1
[    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] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'compacted' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007e7d1fff] usable
[    0.000000] BIOS-e820: [mem 0x000000007e7d2000-0x000000007e7d2fff] reserved
[    0.000000] BIOS-e820: [mem 0x000000007e7d3000-0x000000007e7f4fff] usable
[    0.000000] BIOS-e820: [mem 0x000000007e7f5000-0x000000007e91afff] reserved
[    0.000000] BIOS-e820: [mem 0x000000007e91b000-0x000000007f99afff] usable
[    0.000000] BIOS-e820: [mem 0x000000007f99b000-0x000000007f9eefff] reserved
[    0.000000] BIOS-e820: [mem 0x000000007f9ef000-0x000000007f9f3fff] usable
[    0.000000] BIOS-e820: [mem 0x000000007f9f4000-0x000000007f9fafff] ACPI data
[    0.000000] BIOS-e820: [mem 0x000000007f9fb000-0x000000007f9fefff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x000000007f9ff000-0x000000007ffdffff] usable
[    0.000000] BIOS-e820: [mem 0x000000007ffe0000-0x000000007fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000e0000000-0x00000000efffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000ffe00000-0x00000000ffe1ffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000017fffffff] usable
[    0.000000] printk: debug: ignoring loglevel setting.
[    0.000000] process: using polling idle threads
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] efi: EFI v2.70 by ARCN
[    0.000000] efi: ACPI=0x7f9fa000 ACPI 2.0=0x7f9fa014 MEMATTR=0x7f559118 MOKvar=0x7f45f000 
[    0.000000] DMI not present or invalid.
[    0.000000] Hypervisor detected: ACRN
[    0.000000] tsc: Detected 3000.000 MHz processor
[    0.000010] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000012] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000017] last_pfn = 0x180000 max_arch_pfn = 0x400000000
[    0.000037] MTRR default type: uncachable
[    0.000038] MTRR fixed ranges enabled:
[    0.000039]   00000-FFFFF write-back
[    0.000040] MTRR variable ranges enabled:
[    0.000168] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT  
[    0.000665] CPU MTRRs all blank - virtualized system.
[    0.000670] last_pfn = 0x7ffe0 max_arch_pfn = 0x400000000
[    0.000738] found SMP MP-table at [mem 0x000f0000-0x000f000f]
[    0.000755] check: Scanning 1 areas for low memory corruption
[    0.000812] Using GB pages for direct mapping
[    0.008893] printk: log_buf_len: 16777216 bytes
[    0.008895] printk: early log buf free: 258720(98%)
[    0.008896] Secure boot disabled
[    0.008897] RAMDISK: [mem 0x3a30d000-0x3d060fff]
[    0.008901] ACPI: Early table checksum verification disabled
[    0.008906] ACPI: RSDP 0x000000007F9FA014 000024 (v02 DM    )
[    0.008910] ACPI: XSDT 0x000000007F9F90E8 000044 (v01 DM     DMFACP   00000001      01000013)
[    0.008916] ACPI: FACP 0x000000007F9F7000 00010C (v05 DM     DMFACP   00000001 INTL 20210105)
[    0.008923] ACPI: DSDT 0x000000007F9F4000 0008A2 (v02 DM     DMDSDT   00000001 INTL 20210105)
[    0.008929] ACPI: FACS 0x000000007F9FE000 000040
[    0.008932] ACPI: APIC 0x000000007F9F8000 00005E (v01 DM     DMMADT   00000001 INTL 20210105)
[    0.008935] ACPI: HPET 0x000000007F9F6000 000038 (v01 DM     DMHPET   00000001 INTL 20210105)
[    0.008939] ACPI: MCFG 0x000000007F9F5000 00003C (v01 DM     DMMCFG   00000001 INTL 20210105)
[    0.008941] ACPI: Reserving FACP table memory at [mem 0x7f9f7000-0x7f9f710b]
[    0.008943] ACPI: Reserving DSDT table memory at [mem 0x7f9f4000-0x7f9f48a1]
[    0.008944] ACPI: Reserving FACS table memory at [mem 0x7f9fe000-0x7f9fe03f]
[    0.008945] ACPI: Reserving APIC table memory at [mem 0x7f9f8000-0x7f9f805d]
[    0.008945] ACPI: Reserving HPET table memory at [mem 0x7f9f6000-0x7f9f6037]
[    0.008946] ACPI: Reserving MCFG table memory at [mem 0x7f9f5000-0x7f9f503b]
[    0.009005] ACPI: Local APIC address 0xfee00000
[    0.010382] No NUMA configuration found
[    0.010383] Faking a node at [mem 0x0000000000000000-0x000000017fffffff]
[    0.010392] NODE_DATA(0) allocated [mem 0x17b7d5000-0x17b7fffff]
[    0.010694] Zone ranges:
[    0.010695]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.010696]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
[    0.010698]   Normal   [mem 0x0000000100000000-0x000000017fffffff]
[    0.010699]   Device   empty
[    0.010700] Movable zone start for each node
[    0.010703] Early memory node ranges
[    0.010703]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.010704]   node   0: [mem 0x0000000000100000-0x000000007e7d1fff]
[    0.010705]   node   0: [mem 0x000000007e7d3000-0x000000007e7f4fff]
[    0.010706]   node   0: [mem 0x000000007e91b000-0x000000007f99afff]
[    0.010707]   node   0: [mem 0x000000007f9ef000-0x000000007f9f3fff]
[    0.010707]   node   0: [mem 0x000000007f9ff000-0x000000007ffdffff]
[    0.010708]   node   0: [mem 0x0000000100000000-0x000000017fffffff]
[    0.010709] Initmem setup node 0 [mem 0x0000000000001000-0x000000017fffffff]
[    0.010711] On node 0 totalpages: 1048057
[    0.010712]   DMA zone: 64 pages used for memmap
[    0.010713]   DMA zone: 22 pages reserved
[    0.010713]   DMA zone: 3999 pages, LIFO batch:0
[    0.011015]   DMA zone: 28769 pages in unavailable ranges
[    0.011016]   DMA32 zone: 8122 pages used for memmap
[    0.011017]   DMA32 zone: 519770 pages, LIFO batch:63
[    0.013714]   DMA32 zone: 422 pages in unavailable ranges
[    0.013716]   Normal zone: 8192 pages used for memmap
[    0.013717]   Normal zone: 524288 pages, LIFO batch:63
[    0.017919] ACPI: Local APIC address 0xfee00000
[    0.017931] ACPI: LAPIC_NMI (acpi_id[0xff] high edge lint[0x1])
[    0.017960] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-47
[    0.017965] ACPI: IRQ9 used by override.
[    0.017967] Using ACPI (MADT) for SMP configuration information
[    0.017968] ACPI: HPET id: 0x80860701 base: 0xfed00000
[    0.017972] TSC deadline timer available
[    0.017975] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[    0.017992] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.017994] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000fffff]
[    0.017996] PM: hibernation: Registered nosave memory: [mem 0x7e7d2000-0x7e7d2fff]
[    0.017997] PM: hibernation: Registered nosave memory: [mem 0x7e7f5000-0x7e91afff]
[    0.017999] PM: hibernation: Registered nosave memory: [mem 0x7f99b000-0x7f9eefff]
[    0.018000] PM: hibernation: Registered nosave memory: [mem 0x7f9f4000-0x7f9fafff]
[    0.018000] PM: hibernation: Registered nosave memory: [mem 0x7f9fb000-0x7f9fefff]
[    0.018002] PM: hibernation: Registered nosave memory: [mem 0x7ffe0000-0x7fffffff]
[    0.018002] PM: hibernation: Registered nosave memory: [mem 0x80000000-0xdfffffff]
[    0.018003] PM: hibernation: Registered nosave memory: [mem 0xe0000000-0xefffffff]
[    0.018004] PM: hibernation: Registered nosave memory: [mem 0xf0000000-0xffdfffff]
[    0.018004] PM: hibernation: Registered nosave memory: [mem 0xffe00000-0xffe1ffff]
[    0.018005] PM: hibernation: Registered nosave memory: [mem 0xffe20000-0xffffffff]
[    0.018008] [mem 0x80000000-0xdfffffff] available for PCI devices
[    0.018009] Booting paravirtualized kernel on bare hardware
[    0.018014] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.018022] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1
[    0.018157] percpu: Embedded 53 pages/cpu s180224 r8192 d28672 u524288
[    0.018163] pcpu-alloc: s180224 r8192 d28672 u524288 alloc=1*2097152
[    0.018165] pcpu-alloc: [0] 0 1 2 3 
[    0.018188] Built 1 zonelists, mobility grouping on.  Total pages: 1031657
[    0.018189] Policy zone: Normal
[    0.018190] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.10.52-rt47 root=UUID=74f2a1a0-ad7e-4bda-a851-f3efe55cb507 ro rootwait nohpet console=hvc0 console=ttyS0 no_timer_check ignore_loglevel log_buf_len=16M consoleblank=0 clocksource=tsc tsc=reliable x2apic_phys processor.max_cstate=0 intel_idle.max_cstate=0 intel_pstate=disable mce=ignore_ce audit=0 isolcpus=nohz,domain,1 nohz_full=1 rcu_nocbs=1 nosoftlockup idle=poll irqaffinity=0 no_ipi_broadcast=1
[    0.018368] audit: disabled (until reboot)
[    0.018382] Housekeeping: nohz unsupported. Build with CONFIG_NO_HZ_FULL
[    0.018402] Housekeeping: nohz unsupported. Build with CONFIG_NO_HZ_FULL
[    0.018681] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[    0.018790] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.018864] mem auto-init: stack:off, heap alloc:on, heap free:off
[    0.029675] Memory: 3896140K/4192228K available (16393K kernel code, 3947K rwdata, 5404K rodata, 2576K init, 5624K bss, 295828K reserved, 0K cma-reserved)
[    0.029681] random: get_random_u64 called from __kmem_cache_create+0x2d/0x3d0 with crng_init=0
[    0.029792] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.029808] ftrace: allocating 47827 entries in 187 pages
[    0.045594] ftrace: allocated 187 pages with 6 groups
[    0.045689] rcu: Preemptible hierarchical RCU implementation.
[    0.045690] rcu:     RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4.
[    0.045691] rcu:     RCU priority boosting: priority 1 delay 500 ms.
[    0.045692] rcu:     RCU_SOFTIRQ processing moved to rcuc kthreads.
[    0.045692]  No expedited grace period (rcu_normal_after_boot).
[    0.045693]  Trampoline variant of Tasks RCU enabled.
[    0.045693]  Rude variant of Tasks RCU enabled.
[    0.045694]  Tracing variant of Tasks RCU enabled.
[    0.045694] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.045695] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.049300] NR_IRQS: 524544, nr_irqs: 864, preallocated irqs: 16
[    0.050087] random: crng done (trusting CPU's manufacturer)
[    0.050109] Console: colour dummy device 80x25
[    0.050128] printk: console [ttyS0] enabled
[    0.050144] ACPI: Core revision 20200925
[    0.050409] APIC: Switch to symmetric I/O mode setup
[    0.050855] x2apic enabled
[    0.051290] Switched APIC routing to physical x2apic.
[    0.053099] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2b3e459bf4c, max_idle_ns: 440795289890 ns
[    0.053104] Calibrating delay loop (skipped), value calculated using timer frequency.. 6000.00 BogoMIPS (lpj=12000000)
[    0.053107] pid_max: default: 32768 minimum: 301
[    0.053132] LSM: Security Framework initializing
[    0.053137] Yama: becoming mindful.
[    0.053158] AppArmor: AppArmor initialized
[    0.053193] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.053201] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.053553] mce: CPU0: Thermal monitoring enabled (TM1)
[    0.053559] Last level iTLB entries: 4KB 128, 2MB 8, 4MB 8
[    0.053560] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
[    0.053565] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.053567] Spectre V2 : Mitigation: Enhanced IBRS
[    0.053568] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.053569] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
[    0.053571] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.053572] TAA: Mitigation: TSX disabled
[    0.053572] SRBDS: Mitigation: TSX disabled
[    0.053798] Freeing SMP alternatives memory: 36K
[    0.054605] smpboot: CPU0: Intel(R) Core(TM) i7-9700 CPU @ 3.00GHz (family: 0x6, model: 0x9e, stepping: 0xd)
[    0.054766] Performance Events: unsupported p6 CPU model 158 no PMU driver, software events only.
[    0.054807] rcu: Hierarchical SRCU implementation.
[    0.055211] NMI watchdog: Perf NMI watchdog permanently disabled
[    0.055254] smp: Bringing up secondary CPUs ...
[    0.055371] x86: Booting SMP configuration:
[    0.055371] .... node  #0, CPUs:      #1 #2 #3
[    0.587357] smp: Brought up 1 node, 4 CPUs
[    0.587357] smpboot: Max logical packages: 1
[    0.587357] smpboot: Total of 4 processors activated (24000.00 BogoMIPS)
[    0.587357] devtmpfs: initialized
[    0.587357] x86/mm: Memory block size: 128MB
[    0.587357] PM: Registering ACPI NVS region [mem 0x7f9fb000-0x7f9fefff] (16384 bytes)
[    0.589130] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.589141] futex hash table entries: 1024 (order: 5, 131072 bytes, linear)
[    0.589194] pinctrl core: initialized pinctrl subsystem
[    0.589728] PM: RTC time: 09:44:06, date: 2021-12-13
[    0.589880] NET: Registered protocol family 16
[    0.590071] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations
[    0.590104] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.590136] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.590250] thermal_sys: Registered thermal governor 'fair_share'
[    0.590251] thermal_sys: Registered thermal governor 'bang_bang'
[    0.590251] thermal_sys: Registered thermal governor 'step_wise'
[    0.590252] thermal_sys: Registered thermal governor 'user_space'
[    0.590252] thermal_sys: Registered thermal governor 'power_allocator'
[    0.590258] EISA bus registered
[    0.590276] cpuidle: using governor ladder
[    0.590287] cpuidle: using governor menu
[    0.590287] ACPI FADT declares the system doesn't support PCIe ASPM, so disable it
[    0.590287] ACPI: bus type PCI registered
[    0.590287] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.590287] PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xe0000000-0xefffffff] (base 0xe0000000)
[    0.590287] PCI: MMCONFIG at [mem 0xe0000000-0xefffffff] reserved in E820
[    0.590287] PCI: Using configuration type 1 for base access
[    0.590301] Kprobes globally optimized
[    0.590301] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.590301] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.593177] ACPI: Added _OSI(Module Device)
[    0.593178] ACPI: Added _OSI(Processor Device)
[    0.593179] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.593179] ACPI: Added _OSI(Processor Aggregator Device)
[    0.593180] ACPI: Added _OSI(Linux-Dell-Video)
[    0.593181] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.593182] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    0.593647] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.593889] ACPI: Interpreter enabled
[    0.593889] ACPI: (supports S0 S3 S5)
[    0.593889] ACPI: Using IOAPIC for interrupt routing
[    0.593889] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.593889] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00])
[    0.593889] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]
[    0.593889] PCI host bridge to bus 0000:00
[    0.593889] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.593889] pci_bus 0000:00: root bus resource [io  0x0d00-0x1fff window]
[    0.593889] pci_bus 0000:00: root bus resource [io  0x2000-0x60ff window]
[    0.593889] pci_bus 0000:00: root bus resource [mem 0x80000000-0xdfffffff window]
[    0.593889] pci_bus 0000:00: root bus resource [mem 0x4000000000-0x7fffffffff window]
[    0.593889] pci_bus 0000:00: root bus resource [bus 00]
[    0.594244] pci 0000:00:00.0: [1275:1275] type 00 class 0x060000
[    0.596303] pci 0000:00:04.0: [10ec:8168] type 00 class 0x020000
[    0.596346] pci 0000:00:04.0: reg 0x10: [io  0x6000-0x60ff]
[    0.596414] pci 0000:00:04.0: reg 0x18: [mem 0x4000000000-0x4000000fff 64bit]
[    0.596459] pci 0000:00:04.0: reg 0x20: [mem 0x4000004000-0x4000007fff 64bit pref]
[    0.596485] pci 0000:00:04.0: [Firmware Bug]: reg 0x30: invalid BAR (can't size)
[    0.596667] pci 0000:00:04.0: supports D1 D2
[    0.596668] pci 0000:00:04.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.597876] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000
[    0.598383] pci 0000:00:06.0: reg 0x10: [io  0x2000-0x207f]
[    0.598653] pci 0000:00:06.0: reg 0x14: [mem 0x80000000-0x80001fff]
[    0.602504] pci 0000:00:08.0: [1af4:1003] type 00 class 0x078000
[    0.603054] pci 0000:00:08.0: reg 0x10: [io  0x3000-0x303f]
[    0.603344] pci 0000:00:08.0: reg 0x14: [mem 0x80002000-0x80003fff]
[    0.606933] pci 0000:00:09.0: [1af4:1000] type 00 class 0x020000
[    0.607446] pci 0000:00:09.0: reg 0x10: [io  0x4000-0x401f]
[    0.607737] pci 0000:00:09.0: reg 0x14: [mem 0x80004000-0x80005fff]
[    0.621116] iommu: Default domain type: Translated 
[    0.621120] vgaarb: loaded
[    0.621256] SCSI subsystem initialized
[    0.621262] libata version 3.00 loaded.
[    0.621262] ACPI: bus type USB registered
[    0.621262] usbcore: registered new interface driver usbfs
[    0.621262] usbcore: registered new interface driver hub
[    0.621262] usbcore: registered new device driver usb
[    0.621262] pps_core: LinuxPPS API ver. 1 registered
[    0.621262] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.621262] PTP clock support registered
[    0.621262] EDAC MC: Ver: 3.0.0
[    0.621487] NetLabel: Initializing
[    0.621487] NetLabel:  domain hash size = 128
[    0.621487] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.621487] NetLabel:  unlabeled traffic allowed by default
[    0.621487] PCI: Using ACPI for IRQ routing
[    1.023589] PCI: pci_cache_line_size set to 64 bytes
[    1.023935] e820: reserve RAM buffer [mem 0x7e7d2000-0x7fffffff]
[    1.023937] e820: reserve RAM buffer [mem 0x7e7f5000-0x7fffffff]
[    1.023938] e820: reserve RAM buffer [mem 0x7f99b000-0x7fffffff]
[    1.023940] e820: reserve RAM buffer [mem 0x7f9f4000-0x7fffffff]
[    1.023941] e820: reserve RAM buffer [mem 0x7ffe0000-0x7fffffff]
[    1.025241] clocksource: Switched to clocksource tsc-early
[    1.041254] VFS: Disk quotas dquot_6.6.0
[    1.041267] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    1.041393] AppArmor: AppArmor Filesystem Enabled
[    1.041417] pnp: PnP ACPI init
[    1.041445] pnp: PnP ACPI: found 0 devices
[    1.042690] NET: Registered protocol family 2
[    1.042741] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    1.043291] tcp_listen_portaddr_hash hash table entries: 2048 (order: 5, 131072 bytes, linear)
[    1.043322] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    1.043480] TCP bind hash table entries: 32768 (order: 8, 1835008 bytes, linear)
[    1.043647] TCP: Hash tables configured (established 32768 bind 32768)
[    1.043725] MPTCP token hash table entries: 4096 (order: 6, 294912 bytes, linear)
[    1.043771] UDP hash table entries: 2048 (order: 6, 262144 bytes, linear)
[    1.043811] UDP-Lite hash table entries: 2048 (order: 6, 262144 bytes, linear)
[    1.044008] NET: Registered protocol family 1
[    1.044014] NET: Registered protocol family 44
[    1.044021] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    1.044023] pci_bus 0000:00: resource 5 [io  0x0d00-0x1fff window]
[    1.044025] pci_bus 0000:00: resource 6 [io  0x2000-0x60ff window]
[    1.044026] pci_bus 0000:00: resource 7 [mem 0x80000000-0xdfffffff window]
[    1.044027] pci_bus 0000:00: resource 8 [mem 0x4000000000-0x7fffffffff window]
[    1.044191] PCI: CLS 64 bytes, default 64
[    1.044230] Trying to unpack rootfs image as initramfs...
[    1.173245] Freeing initrd memory: 46416K
[    1.173252] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    1.173253] software IO TLB: mapped [mem 0x000000007a2a1000-0x000000007e2a1000] (64MB)
[    1.173413] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    2.005111] sched: RT throttling activated
[    2.005207] check: Scanning for low memory corruption every 60 seconds
[    2.005536] Initialise system trusted keyrings
[    2.005546] Key type blacklist registered
[    2.005580] workingset: timestamp_bits=36 max_order=20 bucket_order=0
[    2.006824] zbud: loaded
[    2.007143] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    2.007266] fuse: init (API version 7.32)
[    2.007430] integrity: Platform Keyring initialized
[    2.014850] Key type asymmetric registered
[    2.014851] Asymmetric key parser 'x509' registered
[    2.014858] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243)
[    2.014884] io scheduler mq-deadline registered
[    2.015016] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    2.015103] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    2.017134] ACPI: Power Button [PWRF]
[    2.017542] virtio-pci 0000:00:06.0: can't derive routing for PCI INT A
[    2.017544] virtio-pci 0000:00:06.0: PCI INT A: not connected
[    2.017802] virtio-pci 0000:00:06.0: virtio_pci: leaving for legacy driver
[    2.018107] virtio-pci 0000:00:08.0: can't derive routing for PCI INT A
[    2.018108] virtio-pci 0000:00:08.0: PCI INT A: not connected
[    2.018365] virtio-pci 0000:00:08.0: virtio_pci: leaving for legacy driver
[    2.018662] virtio-pci 0000:00:09.0: can't derive routing for PCI INT A
[    2.018663] virtio-pci 0000:00:09.0: PCI INT A: not connected
[    2.018921] virtio-pci 0000:00:09.0: virtio_pci: leaving for legacy driver
[    2.019210] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[    2.020543] serial8250: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    2.021906] serial8250: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[    2.043264] virtio_console virtio1: start polling timer: 10000000
[    2.043439] hpet_acpi_add: no address or irqs in _CRS
[    2.043465] Linux agpgart interface v0.103
[    2.193118] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2b3e459bf4c, max_idle_ns: 440795289890 ns
[    2.193134] clocksource: Switched to clocksource tsc
[    3.005419] printk: console [hvc0] enabled
[    7.745522] irq 9: nobody cared (try booting with the "irqpoll" option)
[    7.745525] CPU: 0 PID: 97 Comm: irq/9-acpi Not tainted 5.10.52-rt47 #1
[    7.745528] Call Trace:
[    7.745529]  <IRQ>
[    7.745532]  dump_stack+0x76/0x94
[    7.745537]  __report_bad_irq+0x3a/0xaf
[    7.745540]  ? _raw_spin_unlock_irq+0x17/0x60
[    7.745543]  note_interrupt.cold+0xb/0x60
[    7.745544]  ? _raw_spin_unlock_irq+0x17/0x60
[    7.745546]  ? handle_untracked_irq+0x160/0x160
[    7.745550]  handle_irq_event_percpu+0x8b/0xa0
[    7.745553]  handle_irq_event+0x57/0xa0
[    7.745555]  handle_fasteoi_irq+0xb4/0x1a0
[    7.745557]  asm_call_irq_on_stack+0xf/0x20
[    7.745560]  </IRQ>
[    7.745561]  common_interrupt+0x14a/0x1f0
[    7.745563]  asm_common_interrupt+0x1e/0x40
[    7.745566] RIP: 0010:_raw_spin_unlock_irq+0x17/0x60
[    7.745569] Code: bf e8 34 af 3f ff 31 c0 eb b6 66 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 48 89 e5 c6 07 00 0f 1f 40 00 fb 66 0f 1f 44 00 00 <bf> 01 00 00 00 e8 6f ee 4c ff 65 8b 05 a8 e4 60 71 85 c0 74 23 a9
[    7.745571] RSP: 0000:ffffb3ff4033be40 EFLAGS: 00000206
[    7.745573] RAX: ffff9903c01c8c00 RBX: ffff9903c01c8c00 RCX: 0000000000000000
[    7.745574] RDX: 0000000000000002 RSI: 0000000000000082 RDI: ffff9903c01c8cb0
[    7.745575] RBP: ffffb3ff4033be40 R08: 0000000000000000 R09: 000000000000000f
[    7.745576] R10: ffffb3ff40077e28 R11: ffff9903c0b0a558 R12: ffff9903c03bb480
[    7.745577] R13: ffff9903c01c8cb0 R14: ffff9903c01c8c28 R15: ffffffff8df228c0
[    7.745578]  ? irq_finalize_oneshot.part.0+0xe0/0xe0
[    7.745580]  irq_finalize_oneshot.part.0+0x64/0xe0
[    7.745582]  irq_forced_thread_fn+0x66/0x90
[    7.745583]  irq_thread+0xdd/0x190
[    7.745584]  ? preempt_count_add+0x74/0xc0
[    7.745587]  ? wake_threads_waitq+0x30/0x30
[    7.745589]  ? irq_thread_check_affinity+0xe0/0xe0
[    7.745590]  kthread+0x176/0x1b0
[    7.745592]  ? kthread_park+0x90/0x90
[    7.745594]  ret_from_fork+0x1f/0x30
[    7.745598] handlers:
[    7.745598] [<00000000477b2c00>] irq_default_primary_handler threaded [<000000008de8a727>] acpi_irq
[    7.745604] Disabling IRQ #9
[    7.889126] loop: module loaded
[    7.889385] libphy: Fixed MDIO Bus: probed
[    7.889386] tun: Universal TUN/TAP device driver, 1.6
[    7.889408] PPP generic driver version 2.4.2
[    7.889451] VFIO - User Level meta-driver version: 0.3
[    7.889492] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    7.889495] ehci-pci: EHCI PCI platform driver
[    7.889503] ehci-platform: EHCI generic platform driver
[    7.889509] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    7.889511] ohci-pci: OHCI PCI platform driver
[    7.889516] ohci-platform: OHCI generic platform driver
[    7.889521] uhci_hcd: USB Universal Host Controller Interface driver
[    7.889545] i8042: PNP: No PS/2 controller found.
[    7.889585] mousedev: PS/2 mouse device common for all mice
[    7.891751] rtc_cmos rtc_cmos: registered as rtc0
[    7.892233] rtc_cmos rtc_cmos: setting system clock to 2021-12-13T09:44:14 UTC (1639388654)
[    7.892247] rtc_cmos rtc_cmos: alarms up to one day, y3k, 114 bytes nvram
[    7.892253] i2c /dev entries driver
[    7.892290] device-mapper: uevent: version 1.0.3
[    7.892336] device-mapper: ioctl: 4.43.0-ioctl (2020-10-01) initialised: dm-devel@redhat.com
[    7.892354] platform eisa.0: Probing EISA bus 0
[    7.892356] platform eisa.0: EISA: Cannot allocate resource for mainboard
[    7.892357] platform eisa.0: Cannot allocate resource for EISA slot 1
[    7.892359] platform eisa.0: Cannot allocate resource for EISA slot 2
[    7.892360] platform eisa.0: Cannot allocate resource for EISA slot 3
[    7.892360] platform eisa.0: Cannot allocate resource for EISA slot 4
[    7.892361] platform eisa.0: Cannot allocate resource for EISA slot 5
[    7.892362] platform eisa.0: Cannot allocate resource for EISA slot 6
[    7.892474] platform eisa.0: EISA: Detected 0 cards
[    7.892609] intel_pmc_core intel_pmc_core.0:  initialized
[    7.892641] drop_monitor: Initializing network drop monitor service
[    7.892770] NET: Registered protocol family 10
[    7.898006] Segment Routing with IPv6
[    7.898023] NET: Registered protocol family 17
[    7.898048] Key type dns_resolver registered
[    7.898275] IPI shorthand broadcast: disabled
[    7.898281] sched_clock: Marking stable (7895011985, 3159257)->(7922821306, -24650064)
[    7.898363] printk: console [ttyS0]: printing thread started
[    7.898384] printk: console [hvc0]: printing thread started
[    7.898406] registered taskstats version 1
[    7.898416] Loading compiled-in X.509 certificates
[    7.898977] Loaded X.509 cert 'Build time autogenerated kernel key: 4f9dcdb23e9a96c61e60b71c903bb572c33524ee'
[    7.898999] zswap: loaded using pool lzo/zbud
[    7.899118] Key type ._fscrypt registered
[    7.899119] Key type .fscrypt registered
[    7.899120] Key type fscrypt-provisioning registered
[    7.901630] Key type encrypted registered
[    7.901633] AppArmor: AppArmor sha1 policy hashing enabled
[    7.901638] ima: No TPM chip found, activating TPM-bypass!
[    7.901648] ima: Allocated hash algorithm: sha1
[    7.901652] ima: No architecture policies found
[    7.901665] evm: Initialising EVM extended attributes:
[    7.901665] evm: security.selinux
[    7.901666] evm: security.SMACK64
[    7.901666] evm: security.SMACK64EXEC
[    7.901667] evm: security.SMACK64TRANSMUTE
[    7.901667] evm: security.SMACK64MMAP
[    7.901667] evm: security.apparmor
[    7.901668] evm: security.ima
[    7.901668] evm: security.capability
[    7.901669] evm: HMAC attrs: 0x1
[    7.901880] PM:   Magic number: 1:651:727
[    7.901884] block loop7: hash matches
[    7.902733] RAS: Correctable Errors collector initialized.
[    7.915256] Freeing unused decrypted memory: 2036K
[    7.915570] Freeing unused kernel image (initmem) memory: 2576K
[    7.937113] Write protecting the kernel read-only data: 24576k
[    7.937631] Freeing unused kernel image (text/rodata gap) memory: 2036K
[    7.937772] Freeing unused kernel image (rodata/data gap) memory: 740K
[    7.949748] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    7.949754] Run /init as init process
[    7.949755]   with arguments:
[    7.949755]     /init
[    7.949756]   with environment:
[    7.949757]     HOME=/
[    7.949757]     TERM=linux
[    7.949758]     BOOT_IMAGE=/boot/vmlinuz-5.10.52-rt47
[    7.949759]     isolcpus=nohz,domain,1
[    7.949759]     nohz_full=1
[    7.949760]     rcu_nocbs=1
[   10.266152] virtio_blk virtio0: [vda] 104857600 512-byte logical blocks (53.7 GB/50.0 GiB)
[   10.266157] vda: detected capacity change from 0 to 53687091200
[   10.266230] virtio_blk virtio0: start polling timer: 10000000
[   10.266444] libphy: r8169: probed
[   10.266819] r8169 0000:00:04.0 eth0: RTL8168e/8111e, 3c:49:37:07:07:11, XID 2c2, IRQ 82
[   10.266822] r8169 0000:00:04.0 eth0: jumbo features [frames: 9194 bytes, tx checksumming: ko]
[   10.267905] r8169 0000:00:04.0 enp0s4: renamed from eth0
[   10.289950] virtio_net virtio2: start polling timer: 10000000
[   10.291643] virtio_net virtio2 enp0s9: renamed from eth0
[   10.437393]  vda: vda1 vda2
[   11.678648] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts: (null)
[   13.861211] systemd[1]: Inserted module 'autofs4'
[   14.080297] request_module fs-efivarfs succeeded, but still no fs?
[   14.150279] systemd[1]: systemd 245.4-4ubuntu3.13 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
[   14.150300] systemd[1]: Detected virtualization acrn.
[   14.150303] systemd[1]: Detected architecture x86-64.
[   14.190195] systemd[1]: Set hostname to <ssn-optiplex-5070-uos-3>.
[   17.252854] systemd[1]: Created slice system-modprobe.slice.
[   17.253303] systemd[1]: Created slice system-serial\x2dgetty.slice.
[   17.253684] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[   17.254094] systemd[1]: Created slice User and Session Slice.
[   17.254325] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[   17.254690] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[   17.254942] systemd[1]: Reached target User and Group Name Lookups.
[   17.255133] systemd[1]: Reached target Remote File Systems.
[   17.255310] systemd[1]: Reached target Slices.
[   17.255556] systemd[1]: Listening on Syslog Socket.
[   17.255784] systemd[1]: Listening on fsck to fsckd communication Socket.
[   17.256020] systemd[1]: Listening on initctl Compatibility Named Pipe.
[   17.271314] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[   17.271409] systemd[1]: Listening on Journal Socket (/dev/log).
[   17.271677] systemd[1]: Listening on Journal Socket.
[   17.271918] systemd[1]: Listening on udev Control Socket.
[   17.272149] systemd[1]: Listening on udev Kernel Socket.
[   17.273188] systemd[1]: Mounting Huge Pages File System...
[   17.279366] systemd[1]: Mounting POSIX Message Queue File System...
[   17.284415] systemd[1]: Mounting Kernel Debug File System...
[   17.289430] systemd[1]: Mounting Kernel Trace File System...
[   17.295027] systemd[1]: Starting Journal Service...
[   17.300993] systemd[1]: Starting Set the console keyboard layout...
[   17.307822] systemd[1]: Starting Create list of static device nodes for the current kernel...
[   17.312892] systemd[1]: Starting Load Kernel Module drm...
[   17.331217] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[   17.331245] systemd[1]: Condition check resulted in File System Check on Root Device being skipped.
[   17.352103] systemd[1]: Starting Load Kernel Modules...
[   17.634747] systemd[1]: Starting Remount Root and Kernel File Systems...
[   17.635971] systemd[1]: Starting udev Coldplug all Devices...
[   17.637019] systemd[1]: Starting Uncomplicated firewall...
[   17.638949] systemd[1]: Mounted Huge Pages File System.
[   17.642838] systemd[1]: Mounted POSIX Message Queue File System.
[   17.679215] systemd[1]: Mounted Kernel Debug File System.
[   17.683377] systemd[1]: Mounted Kernel Trace File System.
[   17.687776] systemd[1]: Finished Set the console keyboard layout.
[   17.691538] EXT4-fs (vda2): re-mounted. Opts: errors=remount-ro
[   17.694900] systemd[1]: Finished Create list of static device nodes for the current kernel.
[   17.696762] systemd[1]: modprobe@drm.service: Succeeded.
[   17.697050] systemd[1]: Finished Load Kernel Module drm.
[   17.701013] systemd[1]: Finished Remount Root and Kernel File Systems.
[   17.706237] systemd[1]: Finished Uncomplicated firewall.
[   17.711795] systemd[1]: Activating swap /swapfile...
[   17.731794] lp: driver loaded but no devices found
[   17.868605] systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
[   17.868651] systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.
[   17.869535] systemd[1]: Starting Load/Save Random Seed...
[   17.873738] ppdev: user-space parallel port driver
[   17.877883] systemd[1]: Starting Create System Users...
[   17.920297] systemd[1]: Started Journal Service.
[   17.945072] systemd-journald[294]: Received client request to flush runtime journal.
[   17.953313] Adding 1190388k swap on /swapfile.  Priority:-2 extents:5 across:1223156k FS
[   20.883419] RAPL PMU: API unit is 2^-32 Joules, 4 fixed counters, 655360 ms ovfl timer
[   20.883423] RAPL PMU: hw unit of domain pp0-core 2^-14 Joules
[   20.883424] RAPL PMU: hw unit of domain package 2^-14 Joules
[   20.883424] RAPL PMU: hw unit of domain dram 2^-14 Joules
[   20.883425] RAPL PMU: hw unit of domain pp1-gpu 2^-14 Joules
[   20.960317] cryptd: max_cpu_qlen set to 1000
[   21.015372] AVX2 version of gcm_enc/dec engaged.
[   21.015375] AES CTR mode by8 optimization enabled
[   21.226291] intel_rapl_common: Found RAPL domain package
[   21.226294] intel_rapl_common: Found RAPL domain core
[   21.226295] intel_rapl_common: Found RAPL domain uncore
[   21.226296] intel_rapl_common: Found RAPL domain dram
[   27.594006] RTL8211DN Gigabit Ethernet r8169-20:00: attached PHY driver [RTL8211DN Gigabit Ethernet] (mii_bus:phy_addr=r8169-20:00, irq=IGNORE)
[   27.894186] r8169 0000:00:04.0 enp0s4: Link is Down
[   30.154205] r8169 0000:00:04.0 enp0s4: Link is Up - 1Gbps/Full - flow control rx/tx
[   30.154219] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s4: link becomes ready
mgcao commented 2 years ago

from the comparison, I doubt two points:

  1. filesystem, it seems it is very slow for root fs mount, not sure why.
  2. network, you pass through a network? r8169 0000:00:04.0

please attach your launch RTVM script here; and lspci in SOS

mgcao commented 2 years ago

also you can： ps -aux | grep dm in SOS, send the info

christophsusen commented 2 years ago

Hi @mgcao, I'm sorry, yes, I added a passthrough NIC while experimenting and also tried using a passthrough SATA disk for the RTVM instead of virtio-blk. However, that did not change anything. The non-RTVM boots fine with passthrough NIC and SATA but the RTVM still has the same problems.

Here is the launch script used for the RTVM to generate the dmesg output in my last comment (just with --lapic_pt added again):

#!/bin/bash
# board: DELL_OPTIPLEX_5070, scenario: INDUSTRY, uos: PREEMPT-RT LINUX
# pci devices for passthru
declare -A passthru_vpid
declare -A passthru_bdf

passthru_vpid=(
["sata"]="8086 a352"
["ethernet"]="10ec 8168"
)
passthru_bdf=(
["sata"]="0000:00:17.0"
["ethernet"]="0000:01:00.0"
)

function tap_net() {
# create a unique tap device for each VM
tap=$1
tap_exist=$(ip a | grep "$tap" | awk '{print $1}')
if [ "$tap_exist"x != "x" ]; then
  echo "tap device existed, reuse $tap"
else
  ip tuntap add dev $tap mode tap
fi

# if acrn-br0 exists, add VM's unique tap device under it
br_exist=$(ip a | grep acrn-br0 | awk '{print $1}')
if [ "$br_exist"x != "x" -a "$tap_exist"x = "x" ]; then
  echo "acrn-br0 bridge aleady exists, adding new tap device to it..."
  ip link set "$tap" master acrn-br0
  ip link set dev "$tap" down
  ip link set dev "$tap" up
fi
}

function launch_preempt_rt_linux()
{
#vm-name used to generate uos-mac address
mac=$(cat /sys/class/net/e*/address)
vm_name=post_vm_id$1
mac_seed=${mac:0:17}-${vm_name}

tap_net tap_tap_uos2
#check if the vm is running or not
vm_ps=$(pgrep -a -f acrn-dm)
result=$(echo $vm_ps | grep -w "${vm_name}")
if [[ "$result" != "" ]]; then
  echo "$vm_name is running, can't create twice!"
  exit
fi

modprobe pci_stub
# Passthrough SATA
#echo ${passthru_vpid["sata"]} > /sys/bus/pci/drivers/pci-stub/new_id
#echo ${passthru_bdf["sata"]} > /sys/bus/pci/devices/${passthru_bdf["sata"]}/driver/unbind
#echo ${passthru_bdf["sata"]} > /sys/bus/pci/drivers/pci-stub/bind

# Passthrough ETHERNET
echo ${passthru_vpid["ethernet"]} > /sys/bus/pci/drivers/pci-stub/new_id
echo ${passthru_bdf["ethernet"]} > /sys/bus/pci/devices/${passthru_bdf["ethernet"]}/driver/unbind
echo ${passthru_bdf["ethernet"]} > /sys/bus/pci/drivers/pci-stub/bind

mem_size=4096M
#interrupt storm monitor for pass-through devices, params order:
#threshold/s,probe-period(s),intr-inject-delay-time(ms),delay-duration(ms)
intr_storm_monitor="--intr_monitor 10000,10,1,100"

#logger_setting, format: logger_name,level; like following
logger_setting="--logger_setting console,level=4;kmsg,level=3;disk,level=5"

acrn-dm -A -m $mem_size -s 0:0,hostbridge -U 495ae2e5-2603-4d64-af76-d4bc5a8ec0e5 \
   --mac_seed $mac_seed \
   --lapic_pt \
   --virtio_poll 1000000 \
   $logger_setting \
   -s 6,virtio-blk,/home/acrn/acrn-target/acrn-work/images/ubuntu/uos-3-50g.img \
   -s 9,virtio-net,tap_tap_uos2 \
   -s 8,virtio-console,@stdio:stdio_port \
   --ovmf /usr/share/acrn/bios/OVMF.fd \
   $intr_storm_monitor \
   -s 4,passthru,01/00/0 \
   $vm_name
}

#   --rtvm \
#   -s 5,passthru,00/17/0 \

# offline pinned vCPUs from SOS before launch UOS
cpu_path="/sys/devices/system/cpu"
for i in `ls ${cpu_path}`; do
    for j in 4 5 6 7; do
        if [ "cpu"$j = $i ]; then
            online=`cat ${cpu_path}/$i/online`
            idx=`echo $i | tr -cd "[0-9]"`
            echo $i online=$online
            if [ "$online" = "1" ]; then
                echo 0 > ${cpu_path}/$i/online
                online=`cat ${cpu_path}/$i/online`
                # during boot time, cpu hotplug may be disabled by pci_device_probe during a pci module insmod
                while [ "$online" = "1" ]; do
                    sleep 1
                    echo 0 > ${cpu_path}/$i/online
                    online=`cat ${cpu_path}/$i/online`
                done
                echo $idx > /sys/devices/virtual/misc/acrn_hsm/remove_cpu
            fi
        fi
    done
done

launch_preempt_rt_linux 2

Here is the output of lspci in the service VM:

00:00.0 Host bridge: Intel Corporation 8th Gen Core 8-core Desktop Processor Host Bridge/DRAM Registers [Coffee Lake S] (rev 0d)
00:01.0 PCI bridge: Intel Corporation Xeon E3-1200 v5/E3-1500 v5/6th Gen Core Processor PCIe Controller (x16) (rev 0d)
00:02.0 VGA compatible controller: Intel Corporation UHD Graphics 630 (Desktop 9 Series) (rev 02)
00:08.0 System peripheral: Intel Corporation Xeon E3-1200 v5/v6 / E3-1500 v5 / 6th/7th/8th Gen Core Processor Gaussian Mixture Model
00:12.0 Signal processing controller: Intel Corporation Cannon Lake PCH Thermal Controller (rev 10)
00:14.0 USB controller: Intel Corporation Cannon Lake PCH USB 3.1 xHCI Host Controller (rev 10)
00:14.2 RAM memory: Intel Corporation Cannon Lake PCH Shared SRAM (rev 10)
00:15.0 Serial bus controller [0c80]: Intel Corporation Cannon Lake PCH Serial IO I2C Controller #0 (rev 10)
00:16.0 Communication controller: Intel Corporation Cannon Lake PCH HECI Controller (rev 10)
00:16.3 Serial controller: Intel Corporation Cannon Lake PCH Active Management Technology - SOL (rev 10)
00:17.0 SATA controller: Intel Corporation Cannon Lake PCH SATA AHCI Controller (rev 10)
00:1b.0 PCI bridge: Intel Corporation Cannon Lake PCH PCI Express Root Port #17 (rev f0)
00:1c.0 PCI bridge: Intel Corporation Cannon Lake PCH PCI Express Root Port #4 (rev f0)
00:1c.6 PCI bridge: Intel Corporation Cannon Lake PCH PCI Express Root Port #7 (rev f0)
00:1d.0 PCI bridge: Intel Corporation Cannon Lake PCH PCI Express Root Port #9 (rev f0)
00:1f.0 ISA bridge: Intel Corporation Q370 Chipset LPC/eSPI Controller (rev 10)
00:1f.3 Audio device: Intel Corporation Cannon Lake PCH cAVS (rev 10)
00:1f.4 SMBus: Intel Corporation Cannon Lake PCH SMBus Controller (rev 10)
00:1f.5 Serial bus controller [0c80]: Intel Corporation Cannon Lake PCH SPI Controller (rev 10)
00:1f.6 Ethernet controller: Intel Corporation Ethernet Connection (7) I219-V (rev 10)
01:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (rev 06)
02:00.0 Non-Volatile memory controller: SK hynix Device 1627
03:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (rev 06)
04:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (rev 06)
05:00.0 Serial controller: MosChip Semiconductor Technology Ltd. PCIe 9912 Multi-I/O Controller

And, finally, the output of ps -aux | grep acrn-dm from within the service VM after starting the RTVM (please let me know if that is not what you wanted): root 4072 3.5 0.0 7586664 6268 pts/0 Sl+ 08:08 0:01 acrn-dm -A -m 4096M -s 0:0,hostbridge -U 495ae2e5-2603-4d64-af76-d4bc5a8ec0e5 --mac_seed e4:54:e8:a3:33:30-post_vm_id2 --lapic_pt --virtio_poll 1000000 --logger_setting console,level=4;kmsg,level=3;disk,level=5 -s 6,virtio-blk,/home/acrn/acrn-target/acrn-work/images/ubuntu/uos-3-50g.img -s 9,virtio-net,tap_tap_uos2 -s 8,virtio-console,@stdio:stdio_port --ovmf /usr/share/acrn/bios/OVMF.fd --intr_monitor 10000,10,1,100 -s 4,passthru,01/00/0 post_vm_id2

Thanks a lot for helping me!

mgcao commented 2 years ago

to be honest, this is very wired issue, we need more try and log info:

  1. just remove : $intr_storm_monitor
  2. remove: -s 4,passthru,01/00/0 \

More log info:

  1. offer the dm log in SOS: /var/log/acrn-dm/

  2. is there some exception info in ACRN hypervisor console? (the console you input vcpu_list)

  3. maybe we need vmexit: https://github.com/projectacrn/acrn-hypervisor/commit/8ae4c90747edad7828e8b24328616b65b3265cba the patch is in release_2.5, you can port to your build, not too much work.

in ACRN console before you launch: vmexit clear after launch (or in the stuck): vmexit offer the vmexit info.

christophsusen commented 2 years ago

I removed the lines you mentioned from the launch script. The new launch script looks like this:

#!/bin/bash
# board: DELL_OPTIPLEX_5070, scenario: INDUSTRY, uos: PREEMPT-RT LINUX
# pci devices for passthru
declare -A passthru_vpid
declare -A passthru_bdf

passthru_vpid=(
["sata"]="8086 a352"
["ethernet"]="10ec 8168"
)
passthru_bdf=(
["sata"]="0000:00:17.0"
["ethernet"]="0000:01:00.0"
)

function tap_net() {
# create a unique tap device for each VM
tap=$1
tap_exist=$(ip a | grep "$tap" | awk '{print $1}')
if [ "$tap_exist"x != "x" ]; then
  echo "tap device existed, reuse $tap"
else
  ip tuntap add dev $tap mode tap
fi

# if acrn-br0 exists, add VM's unique tap device under it
br_exist=$(ip a | grep acrn-br0 | awk '{print $1}')
if [ "$br_exist"x != "x" -a "$tap_exist"x = "x" ]; then
  echo "acrn-br0 bridge aleady exists, adding new tap device to it..."
  ip link set "$tap" master acrn-br0
  ip link set dev "$tap" down
  ip link set dev "$tap" up
fi
}

function launch_preempt_rt_linux()
{
#vm-name used to generate uos-mac address
mac=$(cat /sys/class/net/e*/address)
vm_name=post_vm_id$1
mac_seed=${mac:0:17}-${vm_name}

tap_net tap_tap_uos2
#check if the vm is running or not
vm_ps=$(pgrep -a -f acrn-dm)
result=$(echo $vm_ps | grep -w "${vm_name}")
if [[ "$result" != "" ]]; then
  echo "$vm_name is running, can't create twice!"
  exit
fi

modprobe pci_stub
# Passthrough SATA
#echo ${passthru_vpid["sata"]} > /sys/bus/pci/drivers/pci-stub/new_id
#echo ${passthru_bdf["sata"]} > /sys/bus/pci/devices/${passthru_bdf["sata"]}/driver/unbind
#echo ${passthru_bdf["sata"]} > /sys/bus/pci/drivers/pci-stub/bind

# Passthrough ETHERNET
#echo ${passthru_vpid["ethernet"]} > /sys/bus/pci/drivers/pci-stub/new_id
#echo ${passthru_bdf["ethernet"]} > /sys/bus/pci/devices/${passthru_bdf["ethernet"]}/driver/unbind
#echo ${passthru_bdf["ethernet"]} > /sys/bus/pci/drivers/pci-stub/bind

mem_size=4096M
#interrupt storm monitor for pass-through devices, params order:
#threshold/s,probe-period(s),intr-inject-delay-time(ms),delay-duration(ms)
intr_storm_monitor="--intr_monitor 10000,10,1,100"

#logger_setting, format: logger_name,level; like following
logger_setting="--logger_setting console,level=4;kmsg,level=3;disk,level=5"

acrn-dm -A -m $mem_size -s 0:0,hostbridge -U 495ae2e5-2603-4d64-af76-d4bc5a8ec0e5 \
   --mac_seed $mac_seed \
   --lapic_pt \
   --virtio_poll 1000000 \
   $logger_setting \
   -s 6,virtio-blk,/home/acrn/acrn-target/acrn-work/images/ubuntu/uos-3-50g.img \
   -s 9,virtio-net,tap_tap_uos2 \
   -s 8,virtio-console,@stdio:stdio_port \
   --ovmf /usr/share/acrn/bios/OVMF.fd \
   $vm_name
}

#   --rtvm \
#   $intr_storm_monitor \
#   -s 4,passthru,01/00/0 \
#   -s 5,passthru,00/17/0 \

# offline pinned vCPUs from SOS before launch UOS
cpu_path="/sys/devices/system/cpu"
for i in `ls ${cpu_path}`; do
    for j in 4 5 6 7; do
        if [ "cpu"$j = $i ]; then
            online=`cat ${cpu_path}/$i/online`
            idx=`echo $i | tr -cd "[0-9]"`
            echo $i online=$online
            if [ "$online" = "1" ]; then
                echo 0 > ${cpu_path}/$i/online
                online=`cat ${cpu_path}/$i/online`
                # during boot time, cpu hotplug may be disabled by pci_device_probe during a pci module insmod
                while [ "$online" = "1" ]; do
                    sleep 1
                    echo 0 > ${cpu_path}/$i/online
                    online=`cat ${cpu_path}/$i/online`
                done
                echo $idx > /sys/devices/virtual/misc/acrn_hsm/remove_cpu
            fi
        fi
    done
done

launch_preempt_rt_linux 2

Here is everything that is printed on the ACRN console until the point where the starting process becomes really slow:

[2735477077us][cpu=4][vm2:vcpu0][sev=3][seq=108]:VMX ctrl 0x482 not fully enabled: request 0x92220088 but get 0x9621e1fa

[2735488740us][cpu=4][vm2:vcpu0][sev=3][seq=109]:VMX ctrl 0x48b not fully enabled: request 0x41004ab but get 0x1004ab

[2757905887us][cpu=4][vm2:vcpu0][sev=3][seq=113]:vlapic: Start Secondary VCPU1 for VM[2]...
[2757914624us][cpu=5][vm2:vcpu1][sev=3][seq=114]:VMX ctrl 0x482 not fully enabled: request 0x92220088 but get 0x9621e1fa

[2757926360us][cpu=5][vm2:vcpu1][sev=3][seq=115]:VMX ctrl 0x48b not fully enabled: request 0x41004ab but get 0x1004ab

[2758087466us][cpu=4][vm2:vcpu0][sev=3][seq=119]:vlapic: Start Secondary VCPU2 for VM[2]...
[2758096205us][cpu=6][vm2:vcpu2][sev=3][seq=120]:VMX ctrl 0x482 not fully enabled: request 0x92220088 but get 0x9621e1fa

[2758107936us][cpu=6][vm2:vcpu2][sev=3][seq=121]:VMX ctrl 0x48b not fully enabled: request 0x41004ab but get 0x1004ab

[2758272280us][cpu=4][vm2:vcpu0][sev=3][seq=125]:vlapic: Start Secondary VCPU3 for VM[2]...
[2758281036us][cpu=7][vm2:vcpu3][sev=3][seq=126]:VMX ctrl 0x482 not fully enabled: request 0x92220088 but get 0x9621e1fa

[2758292756us][cpu=7][vm2:vcpu3][sev=3][seq=127]:VMX ctrl 0x48b not fully enabled: request 0x41004ab but get 0x1004ab

Here is the log info from /var/log/acrn-dm/ after launching the RTVM:

----------------new vm instance------------------

[2021-12-14 08:57:51][ 2704.672829] SW_LOAD: get ovmf path /usr/share/acrn/bios/OVMF.fd, size 0x200000
[2021-12-14 08:57:51][ 2704.673065] vm_create: post_vm_id2
[2021-12-14 08:57:51][ 2704.677089] vm_setup_memory: size=0x100000000
[2021-12-14 08:57:51][ 2704.677184] level 0 free/need pages:0/1 page size:0x200000
[2021-12-14 08:57:51][ 2704.677211] level 1 free/need pages:4/4 page size:0x40000000
[2021-12-14 08:57:51][ 2704.677221] to reserve more free pages:
[2021-12-14 08:57:51][ 2704.677887] now enough free pages are reserved!
[2021-12-14 08:57:51][ 2704.677897]
try to setup hugepage with:
[2021-12-14 08:57:51][ 2704.677906]     level 0 - lowmem 0x0, biosmem 0x200000, highmem 0x0

[2021-12-14 08:57:51][ 2704.677937] mmap ptr 0x0x7fb52366a000 -> baseaddr 0x0x7fb540000000
[2021-12-14 08:57:51][ 2704.677953] mmap 0x80000000@0x7fb540000000
[2021-12-14 08:57:51][ 2704.913991] touch 1 pages with pagesz 0x200000
[2021-12-14 08:57:52][ 2705.336095] init passthru first to reserve PIO BAR
[2021-12-14 08:57:52][ 2705.336573] pci init virtio-net^M
[2021-12-14 08:57:52][ 2705.347460] basl_fwrite_madt, dm_cpu_bitmask:0x0, hv_cpu_bitmask:0xf0, guest_cpu_bitmask: 0xf0
[2021-12-14 08:57:52][ 2705.347473] basl_fwrite_madt, vcpu_id=0x0, pcpu_id=0x4, lapic_id=0x8
[2021-12-14 08:57:52][ 2705.347483] basl_fwrite_madt, vcpu_id=0x1, pcpu_id=0x5, lapic_id=0xa
[2021-12-14 08:57:52][ 2705.347493] basl_fwrite_madt, vcpu_id=0x2, pcpu_id=0x6, lapic_id=0xc
[2021-12-14 08:57:52][ 2705.347502] basl_fwrite_madt, vcpu_id=0x3, pcpu_id=0x7, lapic_id=0xe
[2021-12-14 08:57:52][ 2705.365683] acrn_sw_load
[2021-12-14 08:57:52][ 2705.368444] SW_LOAD: partition blob /usr/share/acrn/bios/OVMF.fd size 0x200000 copied to addr 0x7fb63fe00000
[2021-12-14 08:57:52][ 2705.368461] SW_LOAD: build e820 4 entries to addr: 0x7fb5400ef008^M
[2021-12-14 08:57:52][ 2705.368472] SW_LOAD: entry[0]: addr 0x0000000000000000, size 0x00000000000a0000,  type 0x1^M
[2021-12-14 08:57:52][ 2705.368482] SW_LOAD: entry[1]: addr 0x0000000000100000, size 0x000000007ff00000,  type 0x1^M
[2021-12-14 08:57:52][ 2705.368492] SW_LOAD: entry[2]: addr 0x00000000e0000000, size 0x0000000020000000,  type 0x2^M
[2021-12-14 08:57:52][ 2705.368502] SW_LOAD: entry[3]: addr 0x0000000100000000, size 0x0000000080000000,  type 0x1^M
[2021-12-14 08:57:52][ 2705.368511] SW_LOAD: ovmf_entry 0xfffffff0
[2021-12-14 08:57:52][ 2705.368520] add_cpu
[2021-12-14 08:57:52][ 2705.554636] out instr on NMI port (0x61) not supported
[2021-12-14 08:57:52][ 2705.554784] out instr on NMI port (0x61) not supported
[2021-12-14 08:57:52][ 2705.609733] out instr on NMI port (0x61) not supported
[2021-12-14 08:58:15][ 2729.133465] Unhandled memory access to 0xfe001818
[2021-12-14 08:58:15][ 2729.133491] Failed to emulate instruction [[2021-12-14 08:58:15][ 2729.133499] mmio address 0xfe001818, size 4

I will immediately try to apply the patch to my build. Hopefully, I have enough knowledge to do that. Should I execute vmexit clear on the ACRN shell? Currently, I get Error: Invalid command. when I do that. Does this command come with the patch you mentioned.

mgcao commented 2 years ago

yes, in ACRN shell.

christophsusen commented 2 years ago

I applied the patch. I ran vmexit clear on the ACRN shell before launching the RTVM and I ran vmexit after launching the RTVM at the point where the start-up process becomes so slow. Here is the output:

Now(us) =        188168873

REASON        CPU0          US        CPU1          US        CPU2          US        CPU3          US        CPU4          US        CPU5          US        CPU6          US        CPU7          US
0x00             0           0           0           0           0           0           0           0          37          23          37          22          37          23          37          22
0x01          1949        1919        2138        2234        1460        2771        1060        1071       12270        9688          20          39          28          52          36          61
0x07         54786       24890       55191       24367       18554        8034       40021       18079          67          30          78          34         122          53         185          81
0x0a           349         193         687         369         604         320         702         374     9433886     3967772         473         249       74483       32322         370         194
0x0c         52641    75961664       54016    75033750       18358    74763178       39611    75002619          64     4284179          74     5058475         117     4392271         177     5069573
0x12            16       42108           0           0           7      224768           1           2           0           0           0           0           0           0           1          39
0x1c             0           0           0           0           0           0           0           0          92          64           8           6           8           5           8           5
0x1e             0           0           8         220         146        1526          92        2119     4768927     2810027       25024       32015       32825      404205        8758       26375
0x1f            74          38          75          39          75          37          73          37         713         302          49          23          52          24          55          28
0x20        156714       98555      185496      101262       75158       42928      193897      109207         856       27313         727        1470         504         718        1046        1849
0x28           146          87          88          51         127          70          99          56      681303      305027           3           1           3           2           0           0
0x2c             0           0           0           0           0           0           0           0         249         468           0           0           0           0           0           0
0x30            11         143           5         301           3          64           1          57        1407       27331          38         467          74        1194          59         743
0x36             0           0           0           0           0           0           0           0           1         301           2      149623           2      152767           2      155550
0x37             0           0           0           0           0           0           0           0           2           1           1           0           1           0           1           0

Now=188448312us, for detailed latency of each vmexit on each cpu:

   VMEXIT/0x00        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us           0           0           0           0          37          37          36          37
   2us -   4us           0           0           0           0           0           0           1           0
  Max Lat(us):           0           0           0           0           0           1           2           1

   VMEXIT/0x01        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us        1897        2138         922        1050       12261          18          24          32
   2us -   4us          23           7         517           9           7           0           2           2
   4us -   8us          23           0          22           1           0           0           0           0
   8us -  16us           5           0           0           0           1           1           1           1
  16us -  32us           1           0           0           0           0           0           0           0
  Max Lat(us):          16           2           5           4          14          14          14          14

   VMEXIT/0x07        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us       54784       55497       18560       40021          67          78         122         185
   2us -   4us           0           1           0           0           0           0           0           0
   4us -   8us           1           0           0           0           0           0           0           0
   8us -  16us           1           0           0           0           0           0           0           0
  Max Lat(us):           8           2           1           1           0           1           0           0

   VMEXIT/0x0a        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us         349         687         604         702     9433885         473       74483         370
   2us -   4us           0           0           0           0           1           0           0           0
  Max Lat(us):           1           1           1           1           2           1           1           1

   VMEXIT/0x0c        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us         431         152          23          32           0           0           0           0
   2us -   4us         145         127          66          95           0           0           0           2
   4us -   8us         511         414         234        9050           0           0           0           1
   8us -  16us       10020        2511        1049       11762           3           3           2           6
  16us -  32us       12318        2654        1084        1181           3           1           5           4
  32us -  64us         468        9498         770         572           5           0           2           5
  64us - 128us         613        2036         677         418           0           1           3           4
 128us - 256us        6615       13446         958         345           0           5           0          10
 256us - 512us        1354        1472        1223         630           2           5           6          10
 512us -1024us       16796       19353       10285       13940          35          52          79         117
1024us -2048us         322         367         269         461           2           1           0           3
2048us -4096us         389         512         161         503           0           1           2           0
4096us -8192us         430         171         186          35           2           0           1           1
8192us -  more        2229        1609        1378         587          13           6          18          15
  Max Lat(us):     1395884     1130649      767964     1504125      815090     1643080      908630     1004048

   VMEXIT/0x12        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us           9           0           1           0           0           0           0           0
   2us -   4us           2           0           0           1           0           0           0           0
  32us -  64us           1           0           2           0           0           0           0           1
  64us - 128us           0           0           1           0           0           0           0           0
 256us - 512us           0           0           1           0           0           0           0           0
8192us -  more           4           0           2           0           0           0           0           0
  Max Lat(us):       10544           0      112116           2           0           0           0          39

   VMEXIT/0x1c        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us           0           0           0           0          92           8           8           8
  Max Lat(us):           0           0           0           0           1           1           0           0

   VMEXIT/0x1e        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us           0           6         109          66     4765088       24413       15079        8140
   2us -   4us           0           0           1           0           2           0           0           1
   4us -   8us           0           1          25           9           1           0           0           0
   8us -  16us           0           0           5           6          61           8         466          12
  16us -  32us           0           0           0           2        3360         351       16943         223
  32us -  64us           0           0           0           0         392         247         335         371
  64us - 128us           0           0           0           0          23           5           2          11
 128us - 256us           0           1           6           9           0           0           0           0
  Max Lat(us):           0         211         217         224          95          78          67          85

   VMEXIT/0x1f        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us          74          76          76          73         712          48          51          54
   2us -   4us           0           0           0           0           0           1           1           1
   4us -   8us           0           0           0           0           1           0           0           0
  Max Lat(us):           0           1           0           0           5           2           2           2

   VMEXIT/0x20        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us      156659      186586       75126      193867         558         284         387         494
   2us -   4us          51          81          48          29         288         436         105         545
   4us -   8us           1           0           2           1           3           5          10           4
   8us -  16us           3           0           0           0           0           0           0           1
  16us -  32us           0           0           0           0           3           1           0           0
  32us -  64us           0           0           0           0           1           1           2           2
8192us -  more           0           0           0           0           3           0           0           0
  Max Lat(us):           8           3           4           5        8659          35          37          38

   VMEXIT/0x28        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us         146          88         127          99      681303           3           3           0
  Max Lat(us):           1           1           1           1           1           0           0           0

   VMEXIT/0x2c        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us           0           0           0           0         217           0           0           0
   2us -   4us           0           0           0           0          27           0           0           0
   4us -   8us           0           0           0           0           5           0           0           0
  Max Lat(us):           0           0           0           0           5           0           0           0

   VMEXIT/0x30        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us           3           0           1           0         401          10          22          20
   2us -   4us           4           0           0           0          11          10          15          10
   4us -   8us           2           0           1           0           3           1           2           2
   8us -  16us           0           0           0           0           0           0           1           0
  16us -  32us           0           0           0           0         979          16          31          26
  32us -  64us           2           5           1           1          13           1           2           0
  64us - 128us           0           0           0           0           0           0           0           1
 128us - 256us           0           0           0           0           0           0           1           0
  Max Lat(us):          60          60          58          57          52          60         199         112

   VMEXIT/0x36        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
 256us - 512us           0           0           0           0           1           1           1           1
8192us -  more           0           0           0           0           0           1           1           1
  Max Lat(us):           0           0           0           0         301      149249      152455      155225

   VMEXIT/0x37        CPU0        CPU1        CPU2        CPU3        CPU4        CPU5        CPU6        CPU7
   0us -   2us           0           0           0           0           2           1           1           1
  Max Lat(us):           0           0           0           0           0           0           0           0

Now(us) =        189491928; total vmexit per vm/vCPU (count & time):

REASON   VM0/vCPU0          US   VM0/vCPU1          US   VM0/vCPU2          US   VM0/vCPU3          US   VM2/vCPU0          US   VM2/vCPU1          US   VM2/vCPU2          US   VM2/vCPU3          US
0x00             0           0           0           0           0           0           0           0          37          23          37          22          37          23          37          22
0x01          1949        1919        2168        2261        1461        2772        1060        1071       12255        9669           1          14           1          14           1          14
0x07         54786       24890       56647       24989       18566        8039       40023       18080           0           0           0           0           0           0           0           0
0x0a           349         193         687         369         604         320         702         374     9433885     3967771         441         231       74451       32305         307         159
0x0c         52641    75961664       55467    76334499       18369    76095496       39613    76427636           0           0           0           0           0           0           0           0
0x12            16       42108           0           0           7      224768           1           2           0           0           0           0           0           0           0           0
0x1c             0           0           0           0           0           0           0           0          92          64           8           6           8           5           8           5
0x1e             0           0           8         220         146        1526          92        2119     4768927     2810027       25024       32015       32825      404205        8758       26375
0x1f            74          38          77          40          77          38          74          37         692         292          29          14          30          14          32          16
0x20        156714       98555      191036      104128       75200       42950      193905      109211         651       27187         519        1339         176         516         591        1554
0x28           146          87          88          51         127          70          99          56      681219      304988           0           0           0           0           0           0
0x2c             0           0           0           0           0           0           0           0         249         468           0           0           0           0           0           0
0x30            11         143           5         301           3          64           1          57        1384       27192          15         324          53        1078          36         579
0x36             0           0           0           0           0           0           0           0           0           0           1      149249           1      152455           1      155225
0x37             0           0           0           0           0           0           0           0           2           1           1           0           1           0           1           0

Now=189775353us, for detailed latency of each vmexit on each VM/vCPU:

   VMEXIT/0x00   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us           0           0           0           0          37          37          36          37
   2us -   4us           0           0           0           0           0           0           1           0
  Max Lat(us):           0           0           0           0           0           1           2           1

   VMEXIT/0x01   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us        1897        2163         928        1050       12247           0           0           0
   2us -   4us          23           7         517           9           7           0           0           0
   4us -   8us          23           0          22           1           0           0           0           0
   8us -  16us           5           0           0           0           1           1           1           1
  16us -  32us           1           0           0           0           0           0           0           0
  Max Lat(us):          16           2           5           4          14          14          14          14

   VMEXIT/0x07   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us       54784       56681       18853       40023           0           0           0           0
   2us -   4us           0           1           0           0           0           0           0           0
   4us -   8us           1           0           0           0           0           0           0           0
   8us -  16us           1           0           0           0           0           0           0           0
  Max Lat(us):           8           2           1           1           0           0           0           0

   VMEXIT/0x0a   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us         349         687         604         702     9433884         441       74451         307
   2us -   4us           0           0           0           0           1           0           0           0
  Max Lat(us):           1           1           1           1           2           1           1           1

   VMEXIT/0x0c   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us         431         152          24          32           0           0           0           0
   2us -   4us         145         127          66          95           0           0           0           0
   4us -   8us         511         414         234        9050           0           0           0           0
   8us -  16us       10020        2512        1049       11762           0           0           0           0
  16us -  32us       12318        2656        1085        1181           0           0           0           0
  32us -  64us         468        9508         770         572           0           0           0           0
  64us - 128us         613        2056         679         418           0           0           0           0
 128us - 256us        6615       13474         959         345           0           0           0           0
 256us - 512us        1354        1529        1226         630           0           0           0           0
 512us -1024us       16796       20383       10562       13940           0           0           0           0
1024us -2048us         322         369         269         461           0           0           0           0
2048us -4096us         389         515         161         504           0           0           0           0
4096us -8192us         430         174         186          35           0           0           0           0
8192us -  more        2229        1633        1383         588           0           0           0           0
  Max Lat(us):     1395884     1130649      767964     1504125           0           0           0           0

   VMEXIT/0x12   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us           9           0           1           0           0           0           0           0
   2us -   4us           2           0           0           1           0           0           0           0
  32us -  64us           1           0           2           0           0           0           0           0
  64us - 128us           0           0           1           0           0           0           0           0
 256us - 512us           0           0           1           0           0           0           0           0
8192us -  more           4           0           2           0           0           0           0           0
  Max Lat(us):       10544           0      112116           2           0           0           0           0

   VMEXIT/0x1c   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us           0           0           0           0          92           8           8           8
  Max Lat(us):           0           0           0           0           1           1           0           0

   VMEXIT/0x1e   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us           0           6         109          66     4765088       24413       15079        8140
   2us -   4us           0           0           1           0           2           0           0           1
   4us -   8us           0           1          25           9           1           0           0           0
   8us -  16us           0           0           5           6          61           8         466          12
  16us -  32us           0           0           0           2        3360         351       16943         223
  32us -  64us           0           0           0           0         392         247         335         371
  64us - 128us           0           0           0           0          23           5           2          11
 128us - 256us           0           1           6           9           0           0           0           0
  Max Lat(us):           0         211         217         224          95          78          67          85

   VMEXIT/0x1f   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us          74          77          77          74         691          28          29          31
   2us -   4us           0           0           0           0           0           1           1           1
   4us -   8us           0           0           0           0           1           0           0           0
  Max Lat(us):           0           1           0           0           5           2           2           2

   VMEXIT/0x20   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us      156659      191119       76565      193875         353          76          59          43
   2us -   4us          51          81          48          29         288         436         105         542
   4us -   8us           1           0           2           1           3           5          10           4
   8us -  16us           3           0           0           0           0           0           0           0
  16us -  32us           0           0           0           0           3           1           0           0
  32us -  64us           0           0           0           0           1           1           2           2
8192us -  more           0           0           0           0           3           0           0           0
  Max Lat(us):           8           3           4           5        8659          35          37          38

   VMEXIT/0x28   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us         146          88         127          99      681219           0           0           0
  Max Lat(us):           1           1           1           1           1           0           0           0

   VMEXIT/0x2c   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us           0           0           0           0         217           0           0           0
   2us -   4us           0           0           0           0          27           0           0           0
   4us -   8us           0           0           0           0           5           0           0           0
  Max Lat(us):           0           0           0           0           5           0           0           0

   VMEXIT/0x30   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us           3           0           1           0         391           0          16           9
   2us -   4us           4           0           0           0           3           0           4           1
   4us -   8us           2           0           1           0           0           0           0           0
  16us -  32us           0           0           0           0         978          15          31          26
  32us -  64us           2           5           1           1          12           0           1           0
 128us - 256us           0           0           0           0           0           0           1           0
  Max Lat(us):          60          60          58          57          50          25         199          26

   VMEXIT/0x36   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
8192us -  more           0           0           0           0           0           1           1           1
  Max Lat(us):           0           0           0           0           0      149249      152455      155225

   VMEXIT/0x37   VM0/vCPU0   VM0/vCPU1   VM0/vCPU2   VM0/vCPU3   VM2/vCPU0   VM2/vCPU1   VM2/vCPU2   VM2/vCPU3
   0us -   2us           0           0           0           0           2           1           1           1
  Max Lat(us):           0           0           0           0           0           0           0           0
mgcao commented 2 years ago

VMEXIT/0x28 VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 146 88 127 99 681219 0 0 0 Max Lat(us): 1 1 1 1 1 0 0 0

This one shall not happens VM2/vCPU0, and so many times, let me check it.

christophsusen commented 2 years ago

Happy to hear that you found something! Thanks again for helping me out!

mgcao commented 2 years ago

@christophsusen help to confirm:

the rtvm kernel log: a. [ 5.565435] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts: (null) b. [ 38.293042] systemd[1]: Inserted module 'autofs4'

after the RTVM bootup, when it is stuck (go to a) in ACRN SHELL: vmexit clear when it goes to b. vmexit

send out the info. I'd like to confirm the data.

christophsusen commented 2 years ago

@mgcao here you find the info that you asked for:

  1. Output after executing vmexit clear just after the line [ 2.837401] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts: (null): 
    
Now(us) =      57029516632

REASON CPU0 US CPU1 US CPU2 US CPU3 US CPU4 US CPU5 US CPU6 US CPU7 US

Now=57029537354us, for detailed latency of each vmexit on each cpu:

VMEXIT/0x07 CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 0 0 0 2 0 0 0 0 Max Lat(us): 0 0 0 0 0 0 0 0

VMEXIT/0x0c CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 8192us - more 0 0 0 2 0 0 0 0 Max Lat(us): 0 0 0 10048 0 0 0 0

VMEXIT/0x1e CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 Max Lat(us): 0 0 0 0 0 0 0 0

VMEXIT/0x20 CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 0 0 0 10 0 0 0 0 Max Lat(us): 0 0 0 0 0 0 0 0

Now(us) = 57029662564; total vmexit per vm/vCPU (count & time):

REASON VM0/vCPU0 US VM0/vCPU1 US VM0/vCPU2 US VM0/vCPU3 US VM2/vCPU0 US VM2/vCPU1 US VM2/vCPU2 US VM2/vCPU3 US 0x07 0 0 2 0 3 1 15 7 0 0 0 0 0 0 0 0 0x0c 0 0 2 208961 3 149047 15 150724 0 0 0 0 0 0 0 0 0x1e 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0x20 0 0 5 3 13 7 75 38 0 0 0 0 0 0 0 0

Now=57029756226us, for detailed latency of each vmexit on each VM/vCPU:

VMEXIT/0x07 VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 0 2 3 24 0 0 0 0 Max Lat(us): 0 0 0 1 0 0 0 0

VMEXIT/0x0c VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 8192us - more 0 2 3 24 0 0 0 0 Max Lat(us): 0 127871 67993 10048 0 0 0 0

VMEXIT/0x1e VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 Max Lat(us): 0 0 0 0 0 0 0 0

VMEXIT/0x20 VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 0 5 13 120 0 0 0 0 Max Lat(us): 0 1 1 0 0 0 0 0


2. Output after executing `vmexit` just after the line `[   36.244839] systemd[1]: Inserted module 'autofs4'` appeared (maybe a little later since a few log lines appear faster again at that point):

Now(us) = 57064956624

REASON CPU0 US CPU1 US CPU2 US CPU3 US CPU4 US CPU5 US CPU6 US CPU7 US 0x01 125 152 895 854 119 114 65 56 0 0 0 0 0 0 0 0 0x07 1144 515 34030 14474 5128 2168 3996 1698 0 0 0 0 0 0 0 0 0x0a 1 1 1 0 1 1 1 0 35 18 5 3 21 11 35 19 0x0c 1066 35198160 33776 34904475 5084 35191024 3978 35391482 0 0 0 0 0 0 0 0 0x1e 0 0 0 0 0 0 0 0 0 0 1527 988 80 365524 0 0 0x1f 37 18 37 18 36 17 37 18 0 0 0 0 0 0 0 0 0x20 4461 2510 144622 75299 17356 9264 16556 8550 1 3 122 261 6 19 1 3 0x28 1 1 0 0 1 0 1 0 0 0 0 0 0 0 0 0

Now=57065115308us, for detailed latency of each vmexit on each cpu:

VMEXIT/0x01 CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 116 900 119 65 0 0 0 0 2us - 4us 6 0 0 0 0 0 0 0 4us - 8us 3 0 0 0 0 0 0 0 Max Lat(us): 4 1 1 1 0 0 0 0

VMEXIT/0x07 CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 1144 34353 5128 4013 0 0 0 0 Max Lat(us): 1 1 1 1 0 0 0 0

VMEXIT/0x0a CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 1 1 1 1 35 5 21 35 Max Lat(us): 1 0 1 0 1 0 1 1

VMEXIT/0x0c CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 4 37 9 5 0 0 0 0 2us - 4us 2 9 15 0 0 0 0 0 4us - 8us 11 20 24 0 0 0 0 0 8us - 16us 8 27 27 2 0 0 0 0 16us - 32us 23 83 142 6 0 0 0 0 32us - 64us 17 191 318 14 0 0 0 0 64us - 128us 67 573 470 53 0 0 0 0 128us - 256us 50 2699 584 58 0 0 0 0 256us - 512us 32 765 327 39 0 0 0 0 512us -1024us 531 29591 2941 129 0 0 0 0 1024us -2048us 4 1 3 39 0 0 0 0 2048us -4096us 4 0 1 84 0 0 0 0 4096us -8192us 15 10 8 168 0 0 0 0 8192us - more 298 91 215 3398 0 0 0 0 Max Lat(us): 522629 257436 751964 10048 0 0 0 0

VMEXIT/0x1e CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 0 0 0 0 0 1520 0 0 2us - 4us 0 0 0 0 0 1 0 0 16us - 32us 0 0 0 0 0 4 61 0 32us - 64us 0 0 0 0 0 2 18 0 8192us - more 0 0 0 0 0 0 1 0 Max Lat(us): 0 0 0 0 0 33 363129 0

VMEXIT/0x1f CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 37 37 36 38 0 0 0 0 Max Lat(us): 0 0 0 1 0 0 0 0

VMEXIT/0x20 CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 4459 145573 17355 16624 0 85 0 0 2us - 4us 2 0 1 0 1 36 6 1 4us - 8us 0 0 0 0 0 1 0 0 Max Lat(us): 2 1 2 1 3 4 3 3

VMEXIT/0x28 CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7 0us - 2us 1 0 1 1 0 0 0 0 Max Lat(us): 1 0 0 0 0 0 0 0

Now(us) = 57065603800; total vmexit per vm/vCPU (count & time):

REASON VM0/vCPU0 US VM0/vCPU1 US VM0/vCPU2 US VM0/vCPU3 US VM2/vCPU0 US VM2/vCPU1 US VM2/vCPU2 US VM2/vCPU3 US 0x01 125 152 914 872 119 114 67 58 0 0 0 0 0 0 0 0 0x07 1144 515 35334 15025 5133 2170 4069 1729 0 0 0 0 0 0 0 0 0x0a 1 1 1 0 1 1 1 0 35 18 5 3 21 11 35 19 0x0c 1066 35198160 35072 35535232 5089 36010702 4050 36034497 0 0 0 0 0 0 0 0 0x1e 0 0 0 0 0 0 0 0 0 0 1527 988 80 365524 0 0 0x1f 37 18 38 18 37 18 38 18 0 0 0 0 0 0 0 0 0x20 4461 2510 148487 77363 17375 9274 16854 8704 1 3 122 261 6 19 1 3 0x28 1 1 0 0 1 0 1 0 0 0 0 0 0 0 0 0

Now=57065766468us, for detailed latency of each vmexit on each VM/vCPU:

VMEXIT/0x01 VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 116 919 119 67 0 0 0 0 2us - 4us 6 0 0 0 0 0 0 0 4us - 8us 3 0 0 0 0 0 0 0 Max Lat(us): 4 1 1 1 0 0 0 0

VMEXIT/0x07 VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 1144 35660 5134 4086 0 0 0 0 Max Lat(us): 1 1 1 1 0 0 0 0

VMEXIT/0x0a VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 1 1 1 1 35 5 21 35 Max Lat(us): 1 0 1 0 1 0 1 1

VMEXIT/0x0c VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 4 40 9 5 0 0 0 0 2us - 4us 2 9 15 0 0 0 0 0 4us - 8us 11 21 24 0 0 0 0 0 8us - 16us 8 28 27 2 0 0 0 0 16us - 32us 23 83 142 6 0 0 0 0 32us - 64us 17 192 318 14 0 0 0 0 64us - 128us 67 574 470 53 0 0 0 0 128us - 256us 50 3344 584 60 0 0 0 0 256us - 512us 32 772 327 39 0 0 0 0 512us -1024us 531 30231 2941 134 0 0 0 0 1024us -2048us 4 1 3 40 0 0 0 0 2048us -4096us 4 0 1 84 0 0 0 0 4096us -8192us 15 10 8 169 0 0 0 0 8192us - more 298 91 221 3461 0 0 0 0 Max Lat(us): 522629 257436 751964 10048 0 0 0 0

VMEXIT/0x1e VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 0 0 0 0 0 1520 0 0 2us - 4us 0 0 0 0 0 1 0 0 16us - 32us 0 0 0 0 0 4 61 0 32us - 64us 0 0 0 0 0 2 18 0 8192us - more 0 0 0 0 0 0 1 0 Max Lat(us): 0 0 0 0 0 33 363129 0

VMEXIT/0x1f VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 37 38 37 38 0 0 0 0 Max Lat(us): 0 0 0 1 0 0 0 0

VMEXIT/0x20 VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 4459 149455 17375 16937 0 85 0 0 2us - 4us 2 0 1 0 1 36 6 1 4us - 8us 0 0 0 0 0 1 0 0 Max Lat(us): 2 1 2 1 3 4 3 3

VMEXIT/0x28 VM0/vCPU0 VM0/vCPU1 VM0/vCPU2 VM0/vCPU3 VM2/vCPU0 VM2/vCPU1 VM2/vCPU2 VM2/vCPU3 0us - 2us 1 0 1 1 0 0 0 0 Max Lat(us): 1 0 0 0 0 0 0 0

mgcao commented 2 years ago

just check the latest data about VMEXIT/028, there is no data on VMEXIT/0x28 VM2 CPUs, it is fine. the former data is from the initial time. So my doubt is wrong. No obvious issue in ACRN hypervisor now. Maybe we need check where the kernel goes and what task caused the long time stuck.

mgcao commented 2 years ago

it could be a complex debugging work. I'm not sure if you're familiar with the linux kernel. [ 5.565435] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts: (null) [ 38.293042] systemd[1]: Inserted module 'autofs4'

between them, could be something wrong caused the cpu stuck.

christophsusen commented 2 years ago

Okay, thanks for your help! I don't think that I know enough about the Linux kernel to do that kind of debugging.

Do you have a suggestion on which guest OS to use to get an ACRN VM with RT capabilities up and running easily? I would rather change to a different guest OS or kernel than doing the kernel debugging.

mgcao commented 2 years ago

maybe this data: VMEXIT/0x1e --> it cause 363129 us, but less than 1 second, however it is not normal

mgcao commented 2 years ago

I'm not sure if you can use ACRNTrace to catch the data, parser it, it is a port IO access; or you can do more test, to check if each time it case long time, usually it shall be <1 ms.

mgcao commented 2 years ago

@christophsusen you can ask @fuzhongl if could offer a virtio-img for RTVM to test again.

christophsusen commented 2 years ago

@mgcao, @fuzhongl, that would be really helpful! If I have a virtio-img for RTVM that works for one of you, it would be much easier to know if my guest OS or the hypervisor causes the problem.

Unfortunately, I don't have the knowledge yet to do further debugging by myself.

Thanks for your help!

fuzhongl commented 2 years ago

@christophsusen We can't provide any image for policy concern. But, we can try to re-produce this issue on our side if you share the image of rtvm rootfs to us. Thanks!

BR. Fuzhong

gvancuts commented 2 years ago

How did you build your RT kernel by the way (what config are you using)? I see you also use an initrd with it, have you tried to have all drivers compiled in instead and get rid of that initrd?

christophsusen commented 2 years ago

@fuzhongl, thanks for the offer! I will try to make a clean user VM image later today or tomorrow and send you a link to download it afterwards.

christophsusen commented 2 years ago

Hi @gvancuts, as I started to experiment with ACRN, I first tried to configure a non-RTVM with Ubuntu 20.04. After I got this to work, I tried to use this VM image as a starting point for the RTVM and compiled the preempt RT kernel inside the Ubuntu VM. Here are all the commands that I executed to do this:

wget https://mirrors.edge.kernel.org/pub/linux/kernel/projects/rt/5.10/older/patch-5.10.52-rt47.patch.gz
wget https://mirrors.edge.kernel.org/pub/linux/kernel/v5.x/linux-5.10.52.tar.gz

tar xzvf linux-5.10.52.tar.gz
gunzip patch-5.10.52-rt47.patch.gz
cd linux-5.10.52
patch -p1 < ../patch-5.10.52-rt47.patch

# Use kernel config that comes with Ubuntu as basis.
cp /boot/config-$(uname -r) .config
make olddefconfig

# Select fully preemtible kernel from the menu, leave everything else as is.
make menuconfig

scripts/config --disable SYSTEM_TRUSTED_KEYS
scripts/config --disable SYSTEM_REVOCATION_KEYS

make -j $(nproc) deb-pkg

for pkg in ./*.deb; do sudo dpkg -i $pkg; done
sudo reboot

The only thing I changed in the user VM from that point are the kernel command line parameters. I think, the last set I used is the following: ro rootwait nohpet console=hvc0 console=ttyS0 no_timer_check ignore_loglevel log_buf_len=16M consoleblank=0 clocksource=tsc tsc=reliable x2apic_phys processor.max_cstate=0 intel_idle.max_cstate=0 intel_pstate=disable mce=ignore_ce audit=0 isolcpus=nohz,domain,1 nohz_full=1 rcu_nocbs=1 nosoftlockup idle=poll irqaffinity=0

Regarding your second question: I have not tried to get rid of initrd. If that could potentially solve the issue, I have to figure out how to do this first. I actually never compiled a linux kernel except for this RT kernel for the VM. :sweat_smile:

gvancuts commented 2 years ago

Thanks @christophsusen ! @mgcao , do we have a kernel config we could recommend? Should we have @christophsusen to compile and try use https://github.com/projectacrn/acrn-kernel/tree/5.10/preempt-rt isntead (not sure whether we may have other ACRN patches in there)?

You do not need an initrd if all the essential drivers are built into the kernel, so if your kernel config is right, you can avoid it.

mgcao commented 2 years ago

@gvancuts yes there is a config file for RT kernel, but I have not built the RT kernel. could @fuzhongl check that?

christophsusen commented 2 years ago

@gvancuts, @mgcao, I can't find a config file in https://github.com/projectacrn/acrn-kernel/tree/5.10/preempt-rt. Do I have to generate such a config file by myself from scratch or can you recommend something to get started with?

Thanks a lot for taking so much time to help me out, much appreciated!

gvancuts commented 2 years ago

@gvancuts, @mgcao, I can't find a config file in https://github.com/projectacrn/acrn-kernel/tree/5.10/preempt-rt. Do I have to generate such a config file by myself from scratch or can you recommend something to get started with?

We have one for the 4.19 kernel here. But I have not played with this in some time and so I do not know if you can use it with the 5.10 kernel. @fuzhongl , can you share the kernel config file we use to test realtime performace?

fuzhongl commented 2 years ago

Please try it: rtvm_config.gz

christophsusen commented 2 years ago

Thanks, @fuzhongl, @gvancuts and @mgcao!

I compiled the kernel with the config file you provided and tried to use it with the non-RTVM and with the RTVM launch script. The former one works fine, as before. Unfortunately, when using the launch script for the RTVM, the starting process gets stuck again.

Here is the output that I get on the ACRN console after executing vm_console 2:

Loading Linux 5.10.78-acrn-kernel-sos+ ...
6az at.1Orottlose o=po:AVE f1: 'x
0-0[f f0affefBIOS-e820: [mem 0x00000000e0000000-0x00000000efffffff] reserved
BIOS-e820: [mem 0x00000000ffe00000-0x00000000ffe1ffff] reserved
BIOS-e820: [mem 0x0000000100000000-0x000000017fffffff] usable
printk: debug: ignoring loglevel setting.
process: using polling idle threads
NX (Execute Disable) protection: active
efi: EFI v2.70 by ARCN
efi: ACPI=0x7f9fa000 ACPI 2.0=0x7f9fa014 MEMATTR=0x7f55a218
DMI not present or invalid.
Hypervisor detected: ACRN
tsc: Detected 3000.000 MHz processor
e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
e820: remove [mem 0x000a0000-0x000fffff] usable
last_pfn = 0x180000 max_arch_pfn = 0x400000000
MTRR default type: uncachable
MTRR fixed ranges enabled:
  00000-FFFFF write-back
MTRR variable ranges enabled:
x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT
CPU MTRRs all blank - virtualized system.
last_pfn = 0x7ffe0 max_arch_pfn = 0x400000000
found SMP MP-table at [mem 0x000f0000-0x000f000f]
check: Scanning 1 areas for low memory corruption
Using GB pages for direct mapping
printk: log_buf_len: 16777216 bytes
printk: early log buf free: 127840(97%)
Secure boot disabled
ACPI: Early table checksum verification disabled
ACPI: RSDP 0x000000007F9FA014 000024 (v02 DM    )
ACPI: XSDT 0x000000007F9F90E8 000044 (v01 DM     DMFACP   00000001      01000013)
ACPI: FACP 0x000000007F9F7000 00010C (v05 DM     DMFACP   00000001 INTL 20210105)
ACPI: DSDT 0x000000007F9F4000 000336 (v02 DM     DMDSDT   00000001 INTL 20210105)
ACPI: FACS 0x000000007F9FE000 000040
ACPI: APIC 0x000000007F9F8000 00005E (v01 DM     DMMADT   00000001 INTL 20210105)
ACPI: HPET 0x000000007F9F6000 000038 (v01 DM     DMHPET   00000001 INTL 20210105)
ACPI: MCFG 0x000000007F9F5000 00003C (v01 DM     DMMCFG   00000001 INTL 20210105)
ACPI: Reserving FACP table memory at [mem 0x7f9f7000-0x7f9f710b]
ACPI: Reserving DSDT table memory at [mem 0x7f9f4000-0x7f9f4335]
ACPI: Reserving FACS table memory at [mem 0x7f9fe000-0x7f9fe03f]
ACPI: Reserving APIC table memory at [mem 0x7f9f8000-0x7f9f805d]
ACPI: Reserving HPET table memory at [mem 0x7f9f6000-0x7f9f6037]
ACPI: Reserving MCFG table memory at [mem 0x7f9f5000-0x7f9f503b]
ACPI: Local APIC address 0xfee00000
Zone ranges:
  DMA      [mem 0x0000000000001000-0x0000000000ffffff]
  DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
  Normal   [mem 0x0000000100000000-0x000000017fffffff]
Movable zone start for each node
Early memory node ranges
  node   0: [mem 0x0000000000001000-0x000000000009ffff]
  node   0: [mem 0x0000000000100000-0x000000007e7d1fff]
  node   0: [mem 0x000000007e7d3000-0x000000007e7f4fff]
  node   0: [mem 0x000000007e91b000-0x000000007f99afff]
  node   0: [mem 0x000000007f9ef000-0x000000007f9f3fff]
  node   0: [mem 0x000000007f9ff000-0x000000007ffdffff]
  node   0: [mem 0x0000000100000000-0x000000017fffffff]
Initmem setup node 0 [mem 0x0000000000001000-0x000000017fffffff]
On node 0 totalpages: 1048057
  DMA zone: 64 pages used for memmap
  DMA zone: 2039 pages reserved
  DMA zone: 3999 pages, LIFO batch:0
  DMA32 zone: 8122 pages used for memmap
  DMA32 zone: 519770 pages, LIFO batch:63
  Normal zone: 8192 pages used for memmap
  Normal zone: 524288 pages, LIFO batch:63
On node 0, zone DMA: 1 pages in unavailable ranges
On node 0, zone DMA: 96 pages in unavailable ranges
On node 0, zone DMA32: 1 pages in unavailable ranges
On node 0, zone DMA32: 294 pages in unavailable ranges
On node 0, zone DMA32: 84 pages in unavailable ranges
On node 0, zone DMA32: 11 pages in unavailable ranges
On node 0, zone Normal: 32 pages in unavailable ranges
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC_NMI (acpi_id[0xff] high edge lint[0x1])
IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-47
ACPI: IRQ9 used by override.
Using ACPI (MADT) for SMP configuration information
ACPI: HPET id: 0x80860701 base: 0xfed00000
TSC deadline timer available
smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[mem 0x80000000-0xdfffffff] available for PCI devices
Booting paravirtualized kernel on bare hardware
clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:4 nr_node_ids:1
percpu: Embedded 53 pages/cpu s177496 r8192 d31400 u524288
pcpu-alloc: s177496 r8192 d31400 u524288 alloc=1*2097152
pcpu-alloc: [0] 0 1 2 3
Built 1 zonelists, mobility grouping on.  Total pages: 1029640
Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.10.78-acrn-kernel-sos+ root=/dev/vda2 ro root=/dev/vda2 rootfstype=ext4 ro rootwait nohpet console=hvc0 console=ttyS0 no_timer_check ignore_loglevel log_buf_len=16M consoleblank=0 clocksource=tsc tsc=reliable x2apic_phys processor.max_cstate=0 intel_idle.max_cstate=0 intel_pstate=disable mce=ignore_ce audit=0 isolcpus=nohz,domain,1 nohz_full=1 rcu_nocbs=1 nosoftlockup idle=poll irqaffinity=0
Housekeeping: nohz unsupported. Build with CONFIG_NO_HZ_FULL
Housekeeping: nohz unsupported. Build with CONFIG_NO_HZ_FULL
Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
mem auto-init: stack:off, heap alloc:off, heap free:off
Memory: 3921828K/4192228K available (18448K kernel code, 2352K rwdata, 4660K rodata, 1668K init, 1940K bss, 270140K reserved, 0K cma-reserved)
random: get_random_u64 called from __kmem_cache_create+0x2f/0x410 with crng_init=0
SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
ftrace: allocating 57183 entries in 224 pages
ftrace: allocated 224 pages with 3 groups

**********************************************************
**   NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE   **
**                                                      **
** trace_printk() being used. Allocating extra memory.  **
**                                                      **
** This means that this is a DEBUG kernel and it is     **
** unsafe for production use.                           **
**                                                      **
** If you see this message and you are not debugging    **
** the kernel, report this immediately to your vendor!  **
**                                                      **
**   NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE   **
**********************************************************
rcu: Preemptible hierarchical RCU implementation.
rcu:    RCU event tracing is enabled.
rcu:    RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=4.
    Trampoline variant of Tasks RCU enabled.
    Rude variant of Tasks RCU enabled.
    Tracing variant of Tasks RCU enabled.
rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
Using NULL legacy PIC
NR_IRQS: 4352, nr_irqs: 864, preallocated irqs: 0
random: crng done (trusting CPU's manufacturer)
Console: colour dummy device 80x25
printk: console [ttyS0] enabled
ACPI: Core revision 20200925
APIC: Switch to symmetric I/O mode setup
x2apic enabled
Switched APIC routing to physical x2apic.
clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2b3e459bf4c, max_idle_ns: 440795289890 ns
Calibrating delay loop (skipped), value calculated using timer frequency.. 6000.00 BogoMIPS (lpj=3000000)
pid_max: default: 32768 minimum: 301
LSM: Security Framework initializing
Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
CPU0: Thermal monitoring enabled (TM1)
Last level iTLB entries: 4KB 128, 2MB 8, 4MB 8
Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
Spectre V2 : Mitigation: Enhanced IBRS
Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
TAA: Mitigation: TSX disabled
SRBDS: Mitigation: TSX disabled
Freeing SMP alternatives memory: 56K
[119351564us][cpu=4][vm2:vcpu0][sev=3][seq=117]:vlapic: Start Secondary VCPU1 for VM[2]...s
m[119360321us][cpu=5][vm2:vcpu1][sev=3][seq=118]:VMX ctrl 0x482 not fully enabled: request 0x92220088 but get 0x9621e1fa
p
b[119372162us][cpu=5][vm2:vcpu1][sev=3][seq=119]:VMX ctrl 0x48b not fully enabled: request 0x41004ab but get 0x1004ab
o
ot: CPU0: Intel(R) Core(TM) i7-9700 CPU @ 3.00GHz (family: 0x6, model: 0x9e, stepping: 0xd)
Performance Events: Skylake events, 32-deep LBR, Intel PMU driver.
... version:                4
... bit width:              48
... generic registers:      8
... value mask:             0000ffffffffffff
... max period:             000000007fffffff
... fixed-purpose events:   3
... event mask:             00000007000000ff
rcu: Hierarchical SRCU implementation.
smp: Bringing up secondary CPUs ...
x86: Booting SMP configuration:
[119533339us][cpu=4][vm2:vcpu0][sev=3][seq=122]:vlapic: Start Secondary VCPU2 for VM[2]...
[119541990us][cpu=6][vm2:vcpu2][sev=3][seq=123]:VMX ctrl 0x482 not fully enabled: request 0x92220088 but get 0x9621e1fa

[119553645us][cpu=6][vm2:vcpu2][sev=3][seq=124]:VMX ctrl 0x48b not fully enabled: request 0x41004ab but get 0x1004ab

[119717828us][cpu=4][vm2:vcpu0][sev=3][seq=127]:vlapic: Start Secondary VCPU3 for VM[2]...
[119726482us][cpu=7][vm2:vcpu3][sev=3][seq=128]:VMX ctrl 0x482 not fully enabled: request 0x92220088 but get 0x9621e1fa

[119738129us][cpu=7][vm2:vcpu3][sev=3][seq=129]:VMX ctrl 0x48b not fully enabled: request 0x41004ab but get 0x1004ab

.... node  #0, CPUs:      #1 #2 #3
smp: Brought up 1 node, 4 CPUs
smpboot: Max logical packages: 1
smpboot: Total of 4 processors activated (24000.00 BogoMIPS)
devtmpfs: initialized
PM: Registering ACPI NVS region [mem 0x7f9fb000-0x7f9fefff] (16384 bytes)
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
pinctrl core: initialized pinctrl subsystem
NET: Registered protocol family 16
thermal_sys: Registered thermal governor 'step_wise'
thermal_sys: Registered thermal governor 'user_space'
cpuidle: using governor menu
ACPI FADT declares the system doesn't support PCIe ASPM, so disable it
ACPI: bus type PCI registered
dca service started, version 1.12.1
PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xe0000000-0xefffffff] (base 0xe0000000)
PCI: MMCONFIG at [mem 0xe0000000-0xefffffff] reserved in E820
PCI: Using configuration type 1 for base access
Kprobes globally optimized
HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
cryptd: max_cpu_qlen set to 1000
raid6: avx2x4   gen() 32737 MB/s
raid6: avx2x4   xor() 15385 MB/s
raid6: avx2x2   gen() 32915 MB/s
raid6: avx2x2   xor() 18982 MB/s
raid6: avx2x1   gen() 27745 MB/s
raid6: avx2x1   xor() 15020 MB/s
raid6: sse2x4   gen() 13669 MB/s
raid6: sse2x4   xor()  7965 MB/s
raid6: sse2x2   gen() 13920 MB/s
raid6: sse2x2   xor()  8381 MB/s
raid6: sse2x1   gen() 11721 MB/s
raid6: sse2x1   xor()  5929 MB/s
raid6: using algorithm avx2x2 gen() 32915 MB/s
raid6: .... xor() 18982 MB/s, rmw enabled
raid6: using avx2x2 recovery algorithm
ACPI: Added _OSI(Module Device)
ACPI: Added _OSI(Processor Device)
ACPI: Added _OSI(3.0 _SCP Extensions)
ACPI: Added _OSI(Processor Aggregator Device)
ACPI: Added _OSI(Linux-Dell-Video)
ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
ACPI: 1 ACPI AML tables successfully acquired and loaded
ACPI: Interpreter enabled
ACPI: (supports S0 S3 S5)
ACPI: Using IOAPIC for interrupt routing
PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00])
acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]
PCI host bridge to bus 0000:00
pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
pci_bus 0000:00: root bus resource [io  0x0d00-0x1fff window]
pci_bus 0000:00: root bus resource [io  0x2000-0x501f window]
pci_bus 0000:00: root bus resource [mem 0x80000000-0xdfffffff window]
pci_bus 0000:00: root bus resource [mem 0x4000000000-0x7fffffffff window]
pci_bus 0000:00: root bus resource [bus 00]
pci 0000:00:00.0: [1275:1275] type 00 class 0x060000
pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000
pci 0000:00:06.0: reg 0x10: [io  0x2000-0x207f]
pci 0000:00:06.0: reg 0x14: [mem 0x80000000-0x80001fff]
pci 0000:00:08.0: [1af4:1003] type 00 class 0x078000
pci 0000:00:08.0: reg 0x10: [io  0x3000-0x303f]
pci 0000:00:08.0: reg 0x14: [mem 0x80002000-0x80003fff]
pci 0000:00:09.0: [1af4:1000] type 00 class 0x020000
pci 0000:00:09.0: reg 0x10: [io  0x4000-0x401f]
pci 0000:00:09.0: reg 0x14: [mem 0x80004000-0x80005fff]
pci_bus 0000:00: on NUMA node 0
vgaarb: loaded
SCSI subsystem initialized
libata version 3.00 loaded.
ACPI: bus type USB registered
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
PTP clock support registered
Registered efivars operations
Advanced Linux Sound Architecture Driver Initialized.
Bluetooth: Core ver 2.22
NET: Registered protocol family 31
Bluetooth: HCI device and connection manager initialized
Bluetooth: HCI socket layer initialized
Bluetooth: L2CAP socket layer initialized
Bluetooth: SCO socket layer initialized
PCI: Using ACPI for IRQ routing
PCI: pci_cache_line_size set to 64 bytes
e820: reserve RAM buffer [mem 0x7e7d2000-0x7fffffff]
e820: reserve RAM buffer [mem 0x7e7f5000-0x7fffffff]
e820: reserve RAM buffer [mem 0x7f99b000-0x7fffffff]
e820: reserve RAM buffer [mem 0x7f9f4000-0x7fffffff]
e820: reserve RAM buffer [mem 0x7ffe0000-0x7fffffff]
clocksource: Switched to clocksource tsc-early
pnp: PnP ACPI init
pnp: PnP ACPI: found 0 devices
NET: Registered protocol family 2
IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)
TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)
TCP: Hash tables configured (established 32768 bind 32768)
UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)
UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
pci_bus 0000:00: resource 5 [io  0x0d00-0x1fff window]
pci_bus 0000:00: resource 6 [io  0x2000-0x501f window]
pci_bus 0000:00: resource 7 [mem 0x80000000-0xdfffffff window]
pci_bus 0000:00: resource 8 [mem 0x4000000000-0x7fffffffff window]
PCI: CLS 0 bytes, default 64
PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
software IO TLB: mapped [mem 0x0000000077dfe000-0x000000007bdfe000] (64MB)
RAPL PMU: API unit is 2^-32 Joules, 4 fixed counters, 655360 ms ovfl timer
RAPL PMU: hw unit of domain pp0-core 2^-14 Joules
RAPL PMU: hw unit of domain package 2^-14 Joules
RAPL PMU: hw unit of domain dram 2^-14 Joules
RAPL PMU: hw unit of domain pp1-gpu 2^-14 Joules
kvm: no hardware support
platform rtc_cmos: registered platform RTC device (no PNP device found)
check: Scanning for low memory corruption every 60 seconds
Initialise system trusted keyrings
workingset: timestamp_bits=46 max_order=20 bucket_order=0
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
Key type cifs.idmap registered
xor: automatically using best checksumming function   avx
async_tx: api initialized (async)
Key type asymmetric registered
Asymmetric key parser 'x509' registered
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
io scheduler mq-deadline registered
io scheduler kyber registered
input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
ACPI: Power Button [PWRF]
ioatdma: Intel(R) QuickData Technology Driver 5.00
virtio-pci 0000:00:06.0: can't derive routing for PCI INT A
virtio-pci 0000:00:06.0: PCI INT A: not connected
[121053468us][cpu=6][vm2:vcpu2][sev=3][seq=331]:vioapic: WARNING: invalid vpic wire mode change
[121062600us][cpu=6][vm2:vcpu2][sev=3][seq=332]:vioapic: WARNING: invalid vpic wire mode change
[121071788us][cpu=6][vm2:vcpu2][sev=3][seq=333]:vioapic: WARNING: invalid vpic wire mode changev
irtio-pci 0000:00:06.0: virtio_pci: leaving for legacy driver
virtio-pci 0000:00:08.0: can't derive routing for PCI INT A
virtio-pci 0000:00:08.0: PCI INT A: not connected
virtio-pci 0000:00:08.0: virtio_pci: leaving for legacy driver
virtio-pci 0000:00:09.0: can't derive routing for PCI INT A
virtio-pci 0000:00:09.0: PCI INT A: not connected
virtio-pci 0000:00:09.0: virtio_pci: leaving for legacy driver
Serial: 8250/16550 driver, 16 ports, IRQ sharing disabled
[121209210us][cpu=6][vm2:vcpu2][sev=3][seq=334]:vioapic: WARNING: invalid vpic wire mode change
[121345502us][cpu=6][vm2:vcpu2][sev=3][seq=335]:vioapic: WARNING: invalid vpic wire mode change
serial8250: ttyS0 at I/O 0x3f8 (irq = 0, base_baud = 115200) is a 16550A
[121480207us][cpu=6][vm2:vcpu2][sev=3][seq=336]:vioapic: WARNING: invalid vpic wire mode change
serial8250: ttyS1 at I/O 0x2f8 (irq = 0, base_baud = 115200) is a 16550A
[121643910us][cpu=3][vm0:vcpu3][sev=3][seq=337]:ret=-1 hypercall=0x80000023 failed in vmcall_vmexit_handler

[121654365us][cpu=3][vm0:vcpu3][sev=3][seq=338]:ret=-1 hypercall=0x80000023 failed in vmcall_vmexit_handler

[121664877us][cpu=3][vm0:vcpu3][sev=3][seq=339]:ret=-1 hypercall=0x80000023 failed in vmcall_vmexit_handler

[121681385us][cpu=1][vm0:vcpu1][sev=3][seq=340]:ret=-1 hypercall=0x80000023 failed in vmcall_vmexit_handler

hpet_acpi_add: no address or irqs in _CRS
Linux agpgart interface v0.103
brd: module loaded
loop: module loaded
virtio_blk virtio0: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB)
vda: detected capacity change from 0 to 107374182400
clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2b3e459bf4c, max_idle_ns: 440795289890 ns
clocksource: Switched to clocksource tsc
christophsusen commented 2 years ago

Just in case this might help to narrow down the issue: I tried to launch the Ubuntu user VM with Xenomai kernel 4.19.59 as described on this page in the ACRN documentation. Using this kernel, the RTVM boots without any problems. So it seems like the problem is somewhere in my kernel configuration.

Do you have advice for me on how to configure a preempt-RT kernel maybe based on the working configuration for the Xenomai kernel?

christophsusen commented 2 years ago

After a long time, I was able to work on this issue again and finally got everything to work. I pursued the following steps. Just in case, this might help someone else.

Thanks a lot for your help, @fuzhongl, @gvancuts and @mgcao!