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

[Vitaly Kuznetsov <vkuznets@redhat.com>]

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