| Message ID | 20200718063854.16017-7-sean.j.christopherson@intel.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | KVM: x86: Tracepoint improvements and fixes | expand |
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
On Mon, Jul 20, 2020 at 06:52:15PM +0200, Vitaly Kuznetsov wrote: > Sean Christopherson <sean.j.christopherson@intel.com> writes: > > +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: The CAN'T FIND FIELD blurb comes from tools/lib/traceevent/event-parse.c. I assume you are using tooling of some form to generate the trace, i.e. the issue doesn't show up in /sys/kernel/debug/tracing/trace. If that's the case, this is more or less ABI breakage :-( > 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 >
Sean Christopherson <sean.j.christopherson@intel.com> writes: > On Mon, Jul 20, 2020 at 06:52:15PM +0200, Vitaly Kuznetsov wrote: >> Sean Christopherson <sean.j.christopherson@intel.com> writes: >> > +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: > > The CAN'T FIND FIELD blurb comes from tools/lib/traceevent/event-parse.c. > > I assume you are using tooling of some form to generate the trace, i.e. the > issue doesn't show up in /sys/kernel/debug/tracing/trace. If that's the > case, this is more or less ABI breakage :-( > Right you are, the tool is called 'trace-cmd record -e kvm ...' / 'trace-cmd report' but I always thought it's not any different from looking at /sys/kernel/debug/tracing/trace directly. Apparently I was wrong. 'cat /sys/kernel/debug/tracing/trace' seems to be OK, e.g.: qemu-system-x86-20263 [006] .... 75982.292657: kvm_nested_vmexit: vcpu 0 reason hypercall rip 0x40122f info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
+Steve Background: KVM has two tracepoints that effectively trace the same thing (VM-Exit vs. nested VM-Exit), but use completely different formatting and nomenclature for each of the existing tracepoints. I want to add a common macro to create the tracepoints so that they capture the exact same info and report it with the exact same format. But that means breaking the "ABI" for one of the tracepoints, e.g. trace-cmd barfs on the rename of exit_code to exit_reason. Was there ever a verdict on whether or not tracepoints are considered ABI and thus must retain backwards compatibility? If not, what's the proper way to upstream changes to trace-cmd? Thanks! On Tue, Jul 21, 2020 at 03:59:06PM +0200, Vitaly Kuznetsov wrote: > Sean Christopherson <sean.j.christopherson@intel.com> writes: > >> Sean Christopherson <sean.j.christopherson@intel.com> writes: > >> 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: > > > > The CAN'T FIND FIELD blurb comes from tools/lib/traceevent/event-parse.c. > > > > I assume you are using tooling of some form to generate the trace, i.e. the > > issue doesn't show up in /sys/kernel/debug/tracing/trace. If that's the > > case, this is more or less ABI breakage :-( > > > > Right you are, > > the tool is called 'trace-cmd record -e kvm ...' / 'trace-cmd report' > but I always thought it's not any different from looking at > /sys/kernel/debug/tracing/trace directly. Apparently I was wrong. 'cat > /sys/kernel/debug/tracing/trace' seems to be OK, e.g.: > > qemu-system-x86-20263 [006] .... 75982.292657: kvm_nested_vmexit: vcpu 0 reason hypercall rip 0x40122f info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000 > > -- > Vitaly >
On Tue, 21 Jul 2020 12:31:30 -0700 Sean Christopherson <sean.j.christopherson@intel.com> wrote: > +Steve > > Background: KVM has two tracepoints that effectively trace the same thing > (VM-Exit vs. nested VM-Exit), but use completely different formatting and > nomenclature for each of the existing tracepoints. I want to add a common > macro to create the tracepoints so that they capture the exact same info > and report it with the exact same format. But that means breaking the > "ABI" for one of the tracepoints, e.g. trace-cmd barfs on the rename of > exit_code to exit_reason. Feel free to update it. > > Was there ever a verdict on whether or not tracepoints are considered ABI > and thus must retain backwards compatibility? > > If not, what's the proper way to upstream changes to trace-cmd? > There's a kvm plugin in the libtraceevent code. https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/tools/lib/traceevent/plugins/plugin_kvm.c This overrides how the events are read. In the callback handler (e.g. kvm_nested_vmexit_handle()), you can test if "rip" is there or not. If it is not, you can do something different. For example: struct tep_format_field *field; field = tep_find_any_field(event, "rip"); if (field) { tep_print_num_field(s, "rip %llx ", event, "rip", record, 1) [..] } else { /* do something new */ } You can test if fields exist and have the plugins do different things depending on the format of an event. This is what I do in case an event changes in the future. -- Steve
On Tue, Jul 21, 2020 at 03:59:06PM +0200, Vitaly Kuznetsov wrote: > Sean Christopherson <sean.j.christopherson@intel.com> writes: > > > On Mon, Jul 20, 2020 at 06:52:15PM +0200, Vitaly Kuznetsov wrote: > >> Sean Christopherson <sean.j.christopherson@intel.com> writes: > >> > +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: > > > > The CAN'T FIND FIELD blurb comes from tools/lib/traceevent/event-parse.c. > > > > I assume you are using tooling of some form to generate the trace, i.e. the > > issue doesn't show up in /sys/kernel/debug/tracing/trace. If that's the > > case, this is more or less ABI breakage :-( > > > > Right you are, > > the tool is called 'trace-cmd record -e kvm ...' / 'trace-cmd report' Paolo, any thoughts on how to proceed with this series? E.g. merge KVM first and fix trace-cmd second? Something else?
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))
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(-)