On 12/10/21 18:57, David Matlack wrote:
While testing some patches I ran into a VM_BUG_ON that I have been able to
reproduce at kvm/queue commit 45af1bb99b72 ("KVM: VMX: Clean up PI
pre/post-block WARNs").
To repro run the kvm-unit-tests on a kernel built from kvm/queue with
CONFIG_DEBUG_VM=y. I was testing on an Intel Cascade Lake host and have not
tested in any other environments yet. The repro is not 100% reliable, although
it's fairly easy to trigger and always during a vmx* kvm-unit-tests
Given the details of the crash, commit 15ad9762d69f ("KVM: VMX: Save HOST_CR3
in vmx_prepare_switch_to_guest()") and surrounding commits look most suspect.
Yeah, vmx_prepare_switch_to_guest() doesn't update HOST_CR3 if no
preemption happens from one call of vcpu_enter_guest() to the next
(preemption would cause a call to kvm_arch_vcpu_put and from there to
vmx_prepare_switch_to_host, which clears vmx->guest_state_loaded).
During that time an MM switch is bumping the PCID; I would have expected
any such flush to require a preemption (in order to reach e.g.
switch_mm_irqs_off), but that must be wrong. In the splat below in fact
you can see that the values are 0x60674f2005 (RAX) and 0x60674f2006 (RCX
and CR3).
My fault for actually having seen the VM_BUG_ON, but erroneously
thinking that it started happening during the merge window rather than
with the new kvm/next patches. :(
Paolo
The splat:
[ 698.724442] ------------[ cut here ]------------
[ 698.729095] kernel BUG at arch/x86/mm/tlb.c:1082!
[ 698.733838] invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC NOPTI
[ 698.740475] CPU: 29 PID: 63256 Comm: qemu-kvm-system Tainted: G S O 5.16.0-dbg-DEV #1
[ 698.756882] RIP: 0010:__get_current_cr3_fast+0xe6/0x110
[ 698.762134] Code: 3b 4d f8 75 27 48 83 c4 10 5d c3 0f 0b eb df 0f 0b eb 98 0f 0b eb a2 66 85 c9 75 15 48 39 d0 76 17 48 8b 0d dc a7 b9 01 eb 1c <0f> 0b e8 23 8c ba 00 0f 0b 48 39 d0 77 e9 48 c7 c1 00 00 00 80 48
[ 698.780967] RSP: 0018:ffffc90039c6fa50 EFLAGS: 00010297
[ 698.786209] RAX: 00000060674f2005 RBX: ffff88e0911d5380 RCX: 00000060674f2006
[ 698.793366] RDX: 0000000000000004 RSI: 0000000000000000 RDI: ffff88e0985eec18
[ 698.800524] RBP: ffffc90039c6fa60 R08: ffff893e5bf40000 R09: 0000000000000000
[ 698.807682] R10: 00000000000206dd R11: 0000000000000000 R12: ffff88e0985ec8c0
[ 698.814838] R13: 0000000000000000 R14: ffff88e0985eec18 R15: ffff893e5bf40000
[ 698.821997] FS: 00007f5b823ff700(0000) GS:ffff893e5bf40000(0000) knlGS:0000000000000000
[ 698.830114] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 698.835877] CR2: 0000000000000000 CR3: 00000060674f2006 CR4: 00000000003726e0
[ 698.843034] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 698.850192] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 698.857349] Call Trace:
[ 698.859801] <TASK>
[ 698.861907] vmx_prepare_switch_to_guest+0x11f/0x290 [kvm_intel]
[ 698.867945] vcpu_enter_guest+0x128b/0x24b0 [kvm]
[ 698.872719] ? __this_cpu_preempt_check+0x13/0x20
[ 698.877446] ? lock_is_held_type+0xff/0x170
[ 698.881646] ? __this_cpu_preempt_check+0x13/0x20
[ 698.886371] ? lock_is_held_type+0xff/0x170
[ 698.890568] ? __lock_acquire+0x91e/0xf00
[ 698.894599] ? __lock_acquire+0x91e/0xf00
[ 698.898622] ? __this_cpu_preempt_check+0x13/0x20
[ 698.903348] ? lock_acquire+0xda/0x210
[ 698.907111] ? trace_kvm_pio+0x2c/0xd0 [kvm]
[ 698.911422] vcpu_run+0x90/0x370 [kvm]
[ 698.915211] kvm_arch_vcpu_ioctl_run+0x173/0x330 [kvm]
[ 698.920394] kvm_vcpu_ioctl+0x5e3/0x6b0 [kvm]
[ 698.924792] ? rcu_lock_release+0x10/0x20
[ 698.928824] ? __fget_files+0x1bb/0x1d0
[ 698.932672] __se_sys_ioctl+0x77/0xc0
[ 698.936355] __x64_sys_ioctl+0x1d/0x20
[ 698.940116] do_syscall_64+0x44/0xa0
[ 698.943702] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 698.948769] RIP: 0033:0x7f5b8b60b947
[ 698.952355] Code: 73 01 c3 48 8b 0d 31 f5 16 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 01 f5 16 00 f7 d8 64 89 01 48
[ 698.971187] RSP: 002b:00007f5b823fe4d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 698.978780] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f5b8b60b947
[ 698.985937] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 000000000000000e
[ 698.993093] RBP: 00007f5b823fe5c0 R08: 0000000000000400 R09: 00000000000000ff
[ 699.000251] R10: 0000550e7e92ed00 R11: 0000000000000246 R12: 00007f5b8a4a6000
[ 699.007410] R13: 0000550e7f95c000 R14: 0000000000000000 R15: 0000550e7f95c000
[ 699.014571] </TASK>
[ 699.034357] ---[ end trace ee35b3363814d971 ]---
... which is the following VM_BUG_ON:
1074 unsigned long __get_current_cr3_fast(void)
1075 {
1076 unsigned long cr3 = build_cr3(this_cpu_read(cpu_tlbstate.loaded_mm)->pgd,
1077 this_cpu_read(cpu_tlbstate.loaded_mm_asid));
1078
1079 /* For now, be very restrictive about when this can be called. */
1080 VM_WARN_ON(in_nmi() || preemptible());
1081
1082 VM_BUG_ON(cr3 != __read_cr3()); <------------
1083 return cr3;
1084 }
