On Fri, Mar 08, 2019 at 03:16:43PM -0800, Sean Christopherson wrote:
> Debugging VM-Enter failures has been the bane of my existence for years.
> Seeing KVM's VMCS dump format pop up on a console triggers a Pavlovian
> response of swear words and sighs. As KVM's coverage of VM-Enter checks
> improve, so too do the odds of being able to triage/debug a KVM (or any
> other hypervisor) bug by running the bad KVM build as an L1 guest.
>
> Improve support for using KVM to debug a buggy VMM by adding tracepoints
> to capture the basic gist of a VM-Enter failure so that extracting said
> information from KVM doesn't require attaching a debugger or modifying
> L0 KVM to manually log failures.
>
> The captured information is by no means complete or perfect, e.g. I'd
> love to capture *exactly* why a consistency check failed, but logging
> that level of detail would require invasive code changes and might even
> act as a deterrent to adding more checks in KVM.
Sample trace from kvm-unit-tests attached for your viewing pleasure.
>
> Sean Christopherson (2):
> KVM: nVMX: add tracepoints for nested VM-Enter failures
> KVM: nVMX: trace nested VM-Enter failures detected by H/W
>
> arch/x86/include/asm/vmx.h | 14 +++
> arch/x86/kvm/trace.h | 22 ++++
> arch/x86/kvm/vmx/nested.c | 234 ++++++++++++++++++++-----------------
> arch/x86/kvm/x86.c | 1 +
> 4 files changed, 161 insertions(+), 110 deletions(-)
>
> --
> 2.21.0
>
# tracer: nop
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
stable-1090 [002] .... 41.278784: kvm_nested_vmenter_failed: e->index == MSR_FS_BASE
stable-1090 [002] .... 46.076974: kvm_nested_vmenter_failed: !vmx_control_verify(vmcs12->pin_based_vm_exec_control, vmx->nested.msrs.pinbased_ctls_low, vmx->nested.msrs.pinbased_ctls_high)
stable-1090 [002] .... 47.295958: kvm_nested_vmenter_failed: !vmx_control_verify(vmcs12->secondary_vm_exec_control, vmx->nested.msrs.secondary_ctls_low, vmx->nested.msrs.secondary_ctls_high)
stable-1090 [002] .... 47.350132: kvm_nested_vmenter_failed: vmcs12->cr3_target_count > nested_cpu_vmx_misc_cr3_count(vcpu)
stable-1090 [002] .... 48.087071: kvm_nested_vmenter_failed: !page_address_valid(vcpu, vmcs12->io_bitmap_a)
stable-1090 [002] .... 49.246247: kvm_nested_vmenter_failed: !page_address_valid(vcpu, vmcs12->io_bitmap_b)
stable-1090 [002] .... 50.374388: kvm_nested_vmenter_failed: !page_address_valid(vcpu, vmcs12->msr_bitmap)
stable-1090 [002] .... 51.000446: kvm_nested_vmenter_failed: !page_address_valid(vcpu, vmcs12->virtual_apic_page_addr)
stable-1090 [002] .... 51.221134: kvm_nested_vmenter_failed: hardware VM-instruction error: VMENTRY_INVALID_CONTROL_FIELD
stable-1090 [002] .... 51.619408: kvm_nested_vmenter_failed: !page_address_valid(vcpu, vmcs12->virtual_apic_page_addr)
stable-1090 [002] .... 52.984226: kvm_nested_vmenter_failed: !page_address_valid(vcpu, vmcs12->apic_access_addr)
stable-1090 [002] .... 53.808556: kvm_nested_vmenter_failed: !nested_cpu_has(vmcs12, CPU_BASED_TPR_SHADOW)
stable-1090 [002] .... 57.649088: kvm_nested_vmenter_failed: early hardware check VM-instruction error: VMENTRY_INVALID_CONTROL_FIELD
stable-1090 [002] .... 61.205292: kvm_nested_vmenter_failed: !nested_cpu_has_nmi_exiting(vmcs12) && nested_cpu_has_virtual_nmis(vmcs12)
stable-1090 [002] .... 61.229436: kvm_nested_vmenter_failed: !nested_cpu_has_virtual_nmis(vmcs12) && nested_cpu_has(vmcs12, CPU_BASED_VIRTUAL_NMI_PENDING)
stable-1090 [002] .... 61.266647: kvm_nested_vmenter_failed: !nested_cpu_has_ept(vmcs12)
stable-1090 [002] .... 61.872170: kvm_nested_vmenter_failed: !page_address_valid(vcpu, vmcs12->pml_address)
stable-1090 [002] .... 62.248220: kvm_nested_vmenter_failed: nested_cpu_has_vpid(vmcs12) && !vmcs12->virtual_processor_id
stable-1090 [002] .... 62.334492: kvm_nested_vmenter_failed: !(vmx->nested.msrs.ept_caps & VMX_EPTP_UC_BIT)
stable-1090 [002] .... 62.416625: kvm_nested_vmenter_failed: !valid_ept_address(vcpu, vmcs12->ept_pointer)
stable-1090 [002] .... 62.428231: kvm_nested_vmenter_failed: (address & VMX_EPTP_PWL_MASK) != VMX_EPTP_PWL_4
stable-1090 [002] .... 62.548236: kvm_nested_vmenter_failed: address >> maxphyaddr || ((address >> 7) & 0x1f)
stable-1090 [002] .... 63.241056: kvm_nested_vmenter_failed: nested_cpu_has2(vmcs12, SECONDARY_EXEC_UNRESTRICTED_GUEST) && !nested_cpu_has_ept(vmcs12)
stable-1090 [002] .... 63.301056: kvm_nested_vmenter_failed: nested_vmx_check_msr_switch(vcpu, vmcs12->vm_exit_msr_store_count, vmcs12->vm_exit_msr_store_addr)
stable-1090 [002] .... 63.301058: kvm_nested_vmenter_failed: nested_vmx_check_exit_msr_switch_controls(vcpu, vmcs12)
stable-1090 [002] .... 63.996467: kvm_nested_vmenter_failed: intr_type == INTR_TYPE_RESERVED
stable-1090 [002] .... 64.024819: kvm_nested_vmenter_failed: intr_type == INTR_TYPE_OTHER_EVENT && vector != 0
stable-1090 [002] .... 64.046913: kvm_nested_vmenter_failed: intr_type == INTR_TYPE_NMI_INTR && vector != NMI_VECTOR
stable-1090 [002] .... 64.077116: kvm_nested_vmenter_failed: intr_type == INTR_TYPE_HARD_EXCEPTION && vector > 31
stable-1090 [002] .... 64.099163: kvm_nested_vmenter_failed: has_error_code != should_have_error_code
stable-1090 [002] .... 64.120625: kvm_nested_vmenter_failed: !nested_guest_cr0_valid(vcpu, vmcs12->guest_cr0)
stable-1090 [002] .... 66.180989: kvm_nested_vmenter_failed: has_error_code && vmcs12->vm_entry_exception_error_code & GENMASK(31, 15)
stable-1090 [002] .... 66.207602: kvm_nested_vmenter_failed: vmcs12->vm_entry_instruction_len > 15
stable-1090 [002] .... 66.389619: kvm_nested_vmenter_failed: nested_vmx_check_msr_switch(vcpu, vmcs12->vm_entry_msr_load_count, vmcs12->vm_entry_msr_load_addr)
stable-1090 [002] .... 66.400114: kvm_nested_vmenter_failed: e->reserved != 0
stable-1090 [002] .... 67.383581: kvm_nested_vmenter_failed: !nested_host_cr0_valid(vcpu, vmcs12->host_cr0)
stable-1090 [002] .... 67.396616: kvm_nested_vmenter_failed: !nested_host_cr4_valid(vcpu, vmcs12->host_cr4)
stable-1090 [002] .... 68.010870: kvm_nested_vmenter_failed: !nested_cr3_valid(vcpu, vmcs12->host_cr3)
