AMDESE / AMDSEV

AMD Secure Encrypted Virtualization
294 stars 85 forks source link

VM slowdown/hang with `soft lockup` stuck CPUs after boot #221

Open Garandor opened 2 months ago

Garandor commented 2 months ago

I am sometimes/rarely (about 1-in-20) observing severe VM slowdowns when booting up VMs using snp-latest (as of friday 07/12, i had the most recent repo state: ovmf 4b6ee06a09, kernel-guest a38297e3fb01, kernel-host 05b10142ac6a, qemu fb924a5139 using the AmdSevX64 VM BIOS)

I have not yet been able to reproducibly trigger this error, have not seen any other reports on cpu softlocks occurring and would be thankful for any advice on how to further debug this situation.

During boot or soon after the VM comes up it prints watchdog timeouts for stuck CPUs

[   24.713693] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[   24.715447] rcu:     9-...0: (1 ticks this GP) idle=9d74/1/0x4000000000000000 softirq=30/30 fqs=2062
[   24.718017] rcu:     (detected by 20, t=5252 jiffies, g=-831, q=85 ncpus=24)
[   24.719390] Sending NMI from CPU 20 to CPUs 9:

Message from syslogd@ns31614456 at Jul 11 03:12:58 ...
 kernel:[ 4796.249920] watchdog: BUG: soft lockup - CPU#24 stuck for 26s! [qemu-system-x86:263413]

The VM remains responsive but slows to a crawl, VM and Host power operations such as sudo reboot fail and the only way to recover the box is to physically power cycle it, after which both host and VM boot back up and work normally.

If a VM does not run into this issue during/early-after start up, it seems to run stably and not randomly trigger this issue later on.

Here's a trace recorded in host's dmesg in one such situation in case it's helpful.

[148976.223967] watchdog: BUG: soft lockup - CPU#1 stuck for 135570s! [qemu-system-x86:130654]
[148976.224214] Modules linked in: tls dm_crypt xt_multiport tun cpuid nbd overlay binfmt_misc bridge stp llc nft_chain_nat amd_atl intel_rapl_msr intel_rapl_common amd64_edac edac_mce_amd kvm_amd xt_MASQUERADE nf_nat xt_addrtype ipt_REJECT nf_reject_ipv4 xt_tcpudp xt_comment xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nft_compat nf_tables libcrc32c nfnetlink nls_ascii nls_cp437 vfat fat ipmi_ssif snd_pcm dell_smbios kvm rfkill snd_timer video snd mgag200 dcdbas soundcore drm_shmem_helper rapl dell_wmi_descriptor wmi_bmof evdev acpi_cpufreq pcspkr drm_kms_helper i2c_algo_bit ccp sp5100_tco k10temp watchdog acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter button loop fuse drm efi_pstore dm_mod configfs efivarfs ip_tables x_tables autofs4 ext4 crc32c_generic crc16 mbcache jbd2 crc32_pclmul crc32c_intel nvme ghash_clmulni_intel nvme_core ahci t10_pi sha512_ssse3 xhci_pci libahci mpt3sas sha512_generic crc64_rocksoft_generic xhci_hcd sha256_ssse3 raid_class crc64_rocksoft libata sha1_ssse3
[148976.224291]  scsi_transport_sas crc_t10dif tg3 crct10dif_generic usbcore crct10dif_pclmul bnxt_en scsi_mod crc64 crct10dif_common i2c_piix4 usb_common scsi_common wmi aesni_intel crypto_simd cryptd
[148976.227171] CPU: 1 PID: 130654 Comm: qemu-system-x86 Tainted: G      D      L     6.9.0-rc7-snp-host-05b10142ac6a #2
[148976.227472] Hardware name: Dell Inc. PowerEdge R6515/035YY8, BIOS 2.14.1 12/17/2023
[148976.227775] RIP: 0010:native_queued_spin_lock_slowpath+0x21b/0x260
[148976.228079] Code: 83 e0 03 83 ea 01 48 c1 e0 05 48 63 d2 48 05 40 64 03 00 48 03 04 d5 00 1d 16 9b 48 89 28 8b 45 08 85 c0 75 09 f3 90 8b 45 08 <85> c0 74 f7 48 8b 55 00 48 85 d2 74 8f 0f 0d 0a eb 90 8b 03 85 c0
[148976.228711] RSP: 0018:ffffa7a26a473a00 EFLAGS: 00000246
[148976.229035] RAX: 0000000000000000 RBX: ffffa7a26c5d5004 RCX: 0000000000080000
[148976.229362] RDX: 0000000000000002 RSI: 00000000000c0101 RDI: ffffa7a26c5d5004
[148976.229691] RBP: ffff9891bf2b6440 R08: 0000000000000000 R09: 0000000000000000
[148976.230022] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[148976.230352] R13: 0000000000000001 R14: 0000000000000001 R15: 0000000000000000
[148976.230682] FS:  00007f8c15e006c0(0000) GS:ffff9891bf280000(0000) knlGS:0000000000000000
[148976.231014] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[148976.231347] CR2: 0000000000000000 CR3: 00000004dc70a004 CR4: 0000000000770ef0
[148976.231684] PKRU: 55555554
[148976.232018] Call Trace:
[148976.232349]  <IRQ>
[148976.232680]  ? watchdog_timer_fn+0x1d9/0x260
[148976.233013]  ? __pfx_watchdog_timer_fn+0x10/0x10
[148976.233346]  ? __hrtimer_run_queues+0x112/0x250
[148976.233680]  ? hrtimer_interrupt+0xf6/0x230
[148976.234014]  ? __sysvec_apic_timer_interrupt+0x51/0x120
[148976.234350]  ? sysvec_apic_timer_interrupt+0x68/0x90
[148976.234685]  </IRQ>
[148976.235020]  <TASK>
[148976.235353]  ? asm_sysvec_apic_timer_interrupt+0x16/0x20
[148976.235691]  ? native_queued_spin_lock_slowpath+0x21b/0x260
[148976.236020]  queued_read_lock_slowpath+0xda/0xe0
[148976.236339]  kvm_tdp_page_fault+0x10c/0x150 [kvm]
[148976.236700]  kvm_mmu_do_page_fault+0x1c8/0x270 [kvm]
[148976.237057]  kvm_mmu_page_fault+0x8e/0x680 [kvm]
[148976.237409]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.237720]  ? start_sw_timer+0x65/0x1a0 [kvm]
[148976.238079]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.238392]  ? kvm_lapic_reg_write+0x73/0x720 [kvm]
[148976.238745]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.239052]  ? kvm_release_page_clean+0x83/0xb0 [kvm]
[148976.239395]  npf_interception+0x8b/0x120 [kvm_amd]
[148976.239697]  kvm_arch_vcpu_ioctl_run+0x692/0x1590 [kvm]
[148976.240035]  kvm_vcpu_ioctl+0x285/0x6d0 [kvm]
[148976.240362]  __x64_sys_ioctl+0x93/0xd0
[148976.240640]  do_syscall_64+0x80/0x190
[148976.240915]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.241181]  ? syscall_exit_to_user_mode+0x7a/0x210
[148976.241442]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.241698]  ? do_syscall_64+0x8c/0x190
[148976.241945]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.242186]  ? do_syscall_64+0x8c/0x190
[148976.242425]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.242656]  ? syscall_exit_to_user_mode+0x7a/0x210
[148976.242887]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.243109]  ? do_syscall_64+0x8c/0x190
[148976.243322]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.243531]  ? srso_alias_return_thunk+0x5/0xfbef5
[148976.243736]  entry_SYSCALL_64_after_hwframe+0x76/0x7e
[148976.243941] RIP: 0033:0x7f9126823c5b
[148976.244142] Code: 00 48 89 44 24 18 31 c0 48 8d 44 24 60 c7 04 24 10 00 00 00 48 89 44 24 08 48 8d 44 24 20 48 89 44 24 10 b8 10 00 00 00 0f 05 <89> c2 3d 00 f0 ff ff 77 1c 48 8b 44 24 18 64 48 2b 04 25 28 00 00
[148976.244579] RSP: 002b:00007f8c15dff6e0 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[148976.244805] RAX: ffffffffffffffda RBX: 000055ab1b167f80 RCX: 00007f9126823c5b
[148976.245029] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000026
[148976.245251] RBP: 000000000000ae80 R08: 0000000000000000 R09: 0000000000000000
[148976.245470] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
[148976.245690] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[148976.245913]  </TASK>