Re: [PATCH 6/7] KVM: x86: Use common definition for kvm_nested_vmexit tracepoint

Vitaly Kuznetsov
2020-07-20T16:52:29Z

Sean Christopherson <sean.j.christopherson@intel.com> writes:

> Use the newly introduced TRACE_EVENT_KVM_EXIT to define the guts of
> kvm_nested_vmexit so that it captures and prints the same information as
> with kvm_exit. This has the bonus side effect of fixing the interrupt
> info and error code printing for the case where they're invalid, e.g. if
> the exit was a failed VM-Entry. This also sets the stage for retrieving
> EXIT_QUALIFICATION and VM_EXIT_INTR_INFO in nested_vmx_reflect_vmexit()
> if and only if the VM-Exit is being routed to L1.
>
> Signed-off-by: Sean Christopherson <sean.j.christopherson@intel.com>
> ---
> arch/x86/kvm/svm/svm.c | 7 +------
> arch/x86/kvm/trace.h | 34 +---------------------------------
> arch/x86/kvm/vmx/nested.c | 5 +----
> 3 files changed, 3 insertions(+), 43 deletions(-)
>
> diff --git a/arch/x86/kvm/svm/svm.c b/arch/x86/kvm/svm/svm.c
> index 8ab3413094500..133581c5b0dc0 100644
> --- a/arch/x86/kvm/svm/svm.c
> +++ b/arch/x86/kvm/svm/svm.c
> @@ -2950,12 +2950,7 @@ static int handle_exit(struct kvm_vcpu *vcpu, fastpath_t exit_fastpath)
> if (is_guest_mode(vcpu)) {
> int vmexit;
>
> - trace_kvm_nested_vmexit(vcpu, exit_code,
> - svm->vmcb->control.exit_info_1,
> - svm->vmcb->control.exit_info_2,
> - svm->vmcb->control.exit_int_info,
> - svm->vmcb->control.exit_int_info_err,
> - KVM_ISA_SVM);
> + trace_kvm_nested_vmexit(exit_code, vcpu, KVM_ISA_SVM);
>
> vmexit = nested_svm_exit_special(svm);
>
> diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
> index 6cb75ba494fcd..e29576985e03a 100644
> --- a/arch/x86/kvm/trace.h
> +++ b/arch/x86/kvm/trace.h
> @@ -579,39 +579,7 @@ TRACE_EVENT(kvm_nested_intercepts,
> /*
> * Tracepoint for #VMEXIT while nested
> */
> -TRACE_EVENT(kvm_nested_vmexit,
> - TP_PROTO(struct kvm_vcpu *vcpu, __u32 exit_code,
> - __u64 exit_info1, __u64 exit_info2,
> - __u32 exit_int_info, __u32 exit_int_info_err, __u32 isa),
> - TP_ARGS(vcpu, exit_code, exit_info1, exit_info2,
> - exit_int_info, exit_int_info_err, isa),
> -
> - TP_STRUCT__entry(
> - __field( __u64, rip )
> - __field( __u32, exit_code )
> - __field( __u64, exit_info1 )
> - __field( __u64, exit_info2 )
> - __field( __u32, exit_int_info )
> - __field( __u32, exit_int_info_err )
> - __field( __u32, isa )
> - ),
> -
> - TP_fast_assign(
> - __entry->rip = kvm_rip_read(vcpu);
> - __entry->exit_code = exit_code;
> - __entry->exit_info1 = exit_info1;
> - __entry->exit_info2 = exit_info2;
> - __entry->exit_int_info = exit_int_info;
> - __entry->exit_int_info_err = exit_int_info_err;
> - __entry->isa = isa;
> - ),
> - TP_printk("rip: 0x%016llx reason: %s%s%s ext_inf1: 0x%016llx "
> - "ext_inf2: 0x%016llx ext_int: 0x%08x ext_int_err: 0x%08x",
> - __entry->rip,
> - kvm_print_exit_reason(__entry->exit_code, __entry->isa),
> - __entry->exit_info1, __entry->exit_info2,
> - __entry->exit_int_info, __entry->exit_int_info_err)
> -);
> +TRACE_EVENT_KVM_EXIT(kvm_nested_vmexit);
>
> /*
> * Tracepoint for #VMEXIT reinjected to the guest
> diff --git a/arch/x86/kvm/vmx/nested.c b/arch/x86/kvm/vmx/nested.c
> index fc70644b916ca..f437d99f4db09 100644
> --- a/arch/x86/kvm/vmx/nested.c
> +++ b/arch/x86/kvm/vmx/nested.c
> @@ -5912,10 +5912,7 @@ bool nested_vmx_reflect_vmexit(struct kvm_vcpu *vcpu)
> exit_intr_info = vmx_get_intr_info(vcpu);
> exit_qual = vmx_get_exit_qual(vcpu);
>
> - trace_kvm_nested_vmexit(vcpu, exit_reason, exit_qual,
> - vmx->idt_vectoring_info, exit_intr_info,
> - vmcs_read32(VM_EXIT_INTR_ERROR_CODE),
> - KVM_ISA_VMX);
> + trace_kvm_nested_vmexit(exit_reason, vcpu, KVM_ISA_VMX);
>
> /* If L0 (KVM) wants the exit, it trumps L1's desires. */
> if (nested_vmx_l0_wants_exit(vcpu, exit_reason))

With so many lines removed I'm almost in love with the patch! However,
when testing on SVM (unrelated?) my trace log looks a bit ugly:

<...>-315119 [010] 3733.092646: kvm_nested_vmexit: CAN'T FIND FIELD "rip"<CANT FIND FIELD exit_code>vcpu 0 reason npf rip 0x400433 info1 0x0000000200000006 info2 0x0000000000641000 intr_info 0x00000000 error_code 0x00000000
<...>-315119 [010] 3733.092655: kvm_nested_vmexit: CAN'T FIND FIELD "rip"<CANT FIND FIELD exit_code>vcpu 0 reason npf rip 0x400433 info1 0x0000000100000014 info2 0x0000000000400000 intr_info 0x00000000 error_code 0x00000000

...

but after staring at this for some time I still don't see where this
comes from :-( ... but reverting this commit helps:

qemu-system-x86-9928 [022] 379.260656: kvm_nested_vmexit: rip 400433 reason EXIT_NPF info1 200000006 info2 641000 int_info 0 int_info_err 0
qemu-system-x86-9928 [022] 379.260666: kvm_nested_vmexit: rip 400433 reason EXIT_NPF info1 100000014 info2 400000 int_info 0 int_info_err 0

--
Vitaly