KVM: perf: a smart tool to analyse kvm events
Subsystems (5)
PATCH v2 1/1 KVM: perf: a smart tool to analyse kvm events
Changlog:
- calculate stddev.
- make it works both for old kernel and new kernel.
- dynamically inquire max vcpus and cpu isa.
This is a example result of vmexit:
# ./perf kvm-events report Warning: Error: expected type 5 but read 4 Warning: Error: expected type 5 but read 0 Warning: unknown op '}'
Analyze events for all VCPUs:
VM-EXIT Samples Samples% Time% Avg time
APIC_ACCESS 152367 34.07% 1.74% 15.69us ( +- 2.02% )
IO_INSTRUCTION 142663 31.90% 1.76% 16.91us ( +- 2.87% )
HLT 46681 10.44% 95.87% 2816.04us ( +- 2.94% )
EPT_VIOLATION 40184 8.98% 0.15% 5.17us ( +- 1.26% )
CPUID 21284 4.76% 0.04% 2.47us ( +- 0.66% )
EXTERNAL_INTERRUPT 21215 4.74% 0.36% 23.39us ( +- 2.83% )
EXCEPTION_NMI 11723 2.62% 0.04% 5.21us ( +- 2.46% )
CR_ACCESS 5810 1.30% 0.02% 5.06us ( +- 1.01% )
PENDING_INTERRUPT 5322 1.19% 0.01% 3.69us ( +- 1.73% )Total Samples:447249, Total events handled time:137125528.85us.
Any comments are welcome! :)
PATCH v2 1/3 KVM: x86: move kvm_exit related definitions into kvm_exit.h
From: Xiao Guangrong <[email protected]>
Move the definitions into a separate .h file so that 'perf kvm-events' can easily use these
--- arch/x86/include/asm/kvm_exit.h | 229 +++++++++++++++++++++++++++++++++++++++ arch/x86/include/asm/kvm_host.h | 17 +--- arch/x86/include/asm/svm.h | 77 +------------- arch/x86/include/asm/vmx.h | 44 +-------- arch/x86/kvm/trace.h | 89 --------------- 5 files changed, 233 insertions(+), 223 deletions(-) create mode 100644 arch/x86/include/asm/kvm_exit.h
arch/x86/include/asm/kvm_exit.h new file +229 -0
@@ -0,0 +1,229 @@ +/* +* The definitions in this file are shared between KVM modules +* and 'perf kvm-events'. +*/ +#ifndef _X86_KVM_EXIT +#define _X86_KVM_EXIT + +#define VMX_EXIT_REASONS_FAILED_VMENTRY 0x80000000 + +#define EXIT_REASON_EXCEPTION_NMI 0 +#define EXIT_REASON_EXTERNAL_INTERRUPT 1 +#define EXIT_REASON_TRIPLE_FAULT 2 + +#define EXIT_REASON_PENDING_INTERRUPT 7 +#define EXIT_REASON_NMI_WINDOW 8 +#define EXIT_REASON_TASK_SWITCH 9 +#define EXIT_REASON_CPUID 10 +#define EXIT_REASON_HLT 12 +#define EXIT_REASON_INVD 13 +#define EXIT_REASON_INVLPG 14 +#define EXIT_REASON_RDPMC 15 +#define EXIT_REASON_RDTSC 16 +#define EXIT_REASON_VMCALL 18 +#define EXIT_REASON_VMCLEAR 19 +#define EXIT_REASON_VMLAUNCH 20 +#define EXIT_REASON_VMPTRLD 21 +#define EXIT_REASON_VMPTRST 22 +#define EXIT_REASON_VMREAD 23 +#define EXIT_REASON_VMRESUME 24 +#define EXIT_REASON_VMWRITE 25 +#define EXIT_REASON_VMOFF 26 +#define EXIT_REASON_VMON 27 +#define EXIT_REASON_CR_ACCESS 28 +#define EXIT_REASON_DR_ACCESS 29 +#define EXIT_REASON_IO_INSTRUCTION 30 +#define EXIT_REASON_MSR_READ 31 +#define EXIT_REASON_MSR_WRITE 32 +#define EXIT_REASON_INVALID_STATE 33 +#define EXIT_REASON_MWAIT_INSTRUCTION 36 +#define EXIT_REASON_MONITOR_INSTRUCTION 39 +#define EXIT_REASON_PAUSE_INSTRUCTION 40 +#define EXIT_REASON_MCE_DURING_VMENTRY 41 +#define EXIT_REASON_TPR_BELOW_THRESHOLD 43 +#define EXIT_REASON_APIC_ACCESS 44 +#define EXIT_REASON_EPT_VIOLATION 48 +#define EXIT_REASON_EPT_MISCONFIG 49 +#define EXIT_REASON_WBINVD 54 +#define EXIT_REASON_XSETBV 55 + +#define SVM_EXIT_READ_CR0 0x000 +#define SVM_EXIT_READ_CR3 0x003 +#define SVM_EXIT_READ_CR4 0x004 +#define SVM_EXIT_READ_CR8 0x008 +#define SVM_EXIT_WRITE_CR0 0x010 +#define SVM_EXIT_WRITE_CR3 0x013 +#define SVM_EXIT_WRITE_CR4 0x014 +#define SVM_EXIT_WRITE_CR8 0x018 +#define SVM_EXIT_READ_DR0 0x020 +#define SVM_EXIT_READ_DR1 0x021 +#define SVM_EXIT_READ_DR2 0x022 +#define SVM_EXIT_READ_DR3 0x023 +#define SVM_EXIT_READ_DR4 0x024 +#define SVM_EXIT_READ_DR5 0x025 +#define SVM_EXIT_READ_DR6 0x026 +#define SVM_EXIT_READ_DR7 0x027 +#define SVM_EXIT_WRITE_DR0 0x030 +#define SVM_EXIT_WRITE_DR1 0x031 +#define SVM_EXIT_WRITE_DR2 0x032 +#define SVM_EXIT_WRITE_DR3 0x033 +#define SVM_EXIT_WRITE_DR4 0x034 +#define SVM_EXIT_WRITE_DR5 0x035 +#define SVM_EXIT_WRITE_DR6 0x036 +#define SVM_EXIT_WRITE_DR7 0x037 +#define SVM_EXIT_EXCP_BASE 0x040 +#define SVM_EXIT_INTR 0x060 +#define SVM_EXIT_NMI 0x061 +#define SVM_EXIT_SMI 0x062 +#define SVM_EXIT_INIT 0x063 +#define SVM_EXIT_VINTR 0x064 +#define SVM_EXIT_CR0_SEL_WRITE 0x065 +#define SVM_EXIT_IDTR_READ 0x066 +#define SVM_EXIT_GDTR_READ 0x067 +#define SVM_EXIT_LDTR_READ 0x068 +#define SVM_EXIT_TR_READ 0x069 +#define SVM_EXIT_IDTR_WRITE 0x06a +#define SVM_EXIT_GDTR_WRITE 0x06b +#define SVM_EXIT_LDTR_WRITE 0x06c +#define SVM_EXIT_TR_WRITE 0x06d +#define SVM_EXIT_RDTSC 0x06e +#define SVM_EXIT_RDPMC 0x06f +#define SVM_EXIT_PUSHF 0x070 +#define SVM_EXIT_POPF 0x071 +#define SVM_EXIT_CPUID 0x072 +#define SVM_EXIT_RSM 0x073 +#define SVM_EXIT_IRET 0x074 +#define SVM_EXIT_SWINT 0x075 +#define SVM_EXIT_INVD 0x076 +#define SVM_EXIT_PAUSE 0x077 +#define SVM_EXIT_HLT 0x078 +#define SVM_EXIT_INVLPG 0x079 +#define SVM_EXIT_INVLPGA 0x07a +#define SVM_EXIT_IOIO 0x07b +#define SVM_EXIT_MSR 0x07c +#define SVM_EXIT_TASK_SWITCH 0x07d +#define SVM_EXIT_FERR_FREEZE 0x07e +#define SVM_EXIT_SHUTDOWN 0x07f +#define SVM_EXIT_VMRUN 0x080 +#define SVM_EXIT_VMMCALL 0x081 +#define SVM_EXIT_VMLOAD 0x082 +#define SVM_EXIT_VMSAVE 0x083 +#define SVM_EXIT_STGI 0x084 +#define SVM_EXIT_CLGI 0x085 +#define SVM_EXIT_SKINIT 0x086 +#define SVM_EXIT_RDTSCP 0x087 +#define SVM_EXIT_ICEBP 0x088 +#define SVM_EXIT_WBINVD 0x089 +#define SVM_EXIT_MONITOR 0x08a +#define SVM_EXIT_MWAIT 0x08b +#define SVM_EXIT_MWAIT_COND 0x08c +#define SVM_EXIT_XSETBV 0x08d +#define SVM_EXIT_NPF 0x400 + +#define SVM_EXIT_ERR -1 + +#define DE_VECTOR 0 +#define DB_VECTOR 1 +#define BP_VECTOR 3 +#define OF_VECTOR 4 +#define BR_VECTOR 5 +#define UD_VECTOR 6 +#define NM_VECTOR 7 +#define DF_VECTOR 8 +#define TS_VECTOR 10 +#define NP_VECTOR 11 +#define SS_VECTOR 12 +#define GP_VECTOR 13 +#define PF_VECTOR 14 +#define MF_VECTOR 16 +#define MC_VECTOR 18 + +#define VMX_EXIT_REASONS \ + { EXIT_REASON_EXCEPTION_NMI, "EXCEPTION_NMI" }, \ + { EXIT_REASON_EXTERNAL_INTERRUPT, "EXTERNAL_INTERRUPT" }, \ + { EXIT_REASON_TRIPLE_FAULT, "TRIPLE_FAULT" }, \ + { EXIT_REASON_PENDING_INTERRUPT, "PENDING_INTERRUPT" }, \ + { EXIT_REASON_NMI_WINDOW, "NMI_WINDOW" }, \ + { EXIT_REASON_TASK_SWITCH, "TASK_SWITCH" }, \ + { EXIT_REASON_CPUID, "CPUID" }, \ + { EXIT_REASON_HLT, "HLT" }, \ + { EXIT_REASON_INVLPG, "INVLPG" }, \ + { EXIT_REASON_RDPMC, "RDPMC" }, \ + { EXIT_REASON_RDTSC, "RDTSC" }, \ + { EXIT_REASON_VMCALL, "VMCALL" }, \ + { EXIT_REASON_VMCLEAR, "VMCLEAR" }, \ + { EXIT_REASON_VMLAUNCH, "VMLAUNCH" }, \ + { EXIT_REASON_VMPTRLD, "VMPTRLD" }, \ + { EXIT_REASON_VMPTRST, "VMPTRST" }, \ + { EXIT_REASON_VMREAD, "VMREAD" }, \ + { EXIT_REASON_VMRESUME, "VMRESUME" }, \ + { EXIT_REASON_VMWRITE, "VMWRITE" }, \ + { EXIT_REASON_VMOFF, "VMOFF" }, \ + { EXIT_REASON_VMON, "VMON" }, \ + { EXIT_REASON_CR_ACCESS, "CR_ACCESS" }, \ + { EXIT_REASON_DR_ACCESS, "DR_ACCESS" }, \ + { EXIT_REASON_IO_INSTRUCTION, "IO_INSTRUCTION" }, \ + { EXIT_REASON_MSR_READ, "MSR_READ" }, \ + { EXIT_REASON_MSR_WRITE, "MSR_WRITE" }, \ + { EXIT_REASON_MWAIT_INSTRUCTION, "MWAIT_INSTRUCTION" }, \ + { EXIT_REASON_MONITOR_INSTRUCTION, "MONITOR_INSTRUCTION" }, \ + { EXIT_REASON_PAUSE_INSTRUCTION, "PAUSE_INSTRUCTION" }, \ + { EXIT_REASON_MCE_DURING_VMENTRY, "MCE_DURING_VMENTRY" }, \ + { EXIT_REASON_TPR_BELOW_THRESHOLD, "TPR_BELOW_THRESHOLD" }, \ + { EXIT_REASON_APIC_ACCESS, "APIC_ACCESS" }, \ + { EXIT_REASON_EPT_VIOLATION, "EPT_VIOLATION" }, \ + { EXIT_REASON_EPT_MISCONFIG, "EPT_MISCONFIG" }, \ + { EXIT_REASON_WBINVD, "WBINVD" } + +#define SVM_EXIT_REASONS \ + { SVM_EXIT_READ_CR0, "read_cr0" }, \ + { SVM_EXIT_READ_CR3, "read_cr3" }, \ + { SVM_EXIT_READ_CR4, "read_cr4" }, \ + { SVM_EXIT_READ_CR8, "read_cr8" }, \ + { SVM_EXIT_WRITE_CR0, "write_cr0" }, \ + { SVM_EXIT_WRITE_CR3, "write_cr3" }, \ + { SVM_EXIT_WRITE_CR4, "write_cr4" }, \ + { SVM_EXIT_WRITE_CR8, "write_cr8" }, \ + { SVM_EXIT_READ_DR0, "read_dr0" }, \ + { SVM_EXIT_READ_DR1, "read_dr1" }, \ + { SVM_EXIT_READ_DR2, "read_dr2" }, \ + { SVM_EXIT_READ_DR3, "read_dr3" }, \ + { SVM_EXIT_WRITE_DR0, "write_dr0" }, \ + { SVM_EXIT_WRITE_DR1, "write_dr1" }, \ + { SVM_EXIT_WRITE_DR2, "write_dr2" }, \ + { SVM_EXIT_WRITE_DR3, "write_dr3" }, \ + { SVM_EXIT_WRITE_DR5, "write_dr5" }, \ + { SVM_EXIT_WRITE_DR7, "write_dr7" }, \ + { SVM_EXIT_EXCP_BASE + DB_VECTOR, "DB excp" }, \ + { SVM_EXIT_EXCP_BASE + BP_VECTOR, "BP excp" }, \ + { SVM_EXIT_EXCP_BASE + UD_VECTOR, "UD excp" }, \ + { SVM_EXIT_EXCP_BASE + PF_VECTOR, "PF excp" }, \ + { SVM_EXIT_EXCP_BASE + NM_VECTOR, "NM excp" }, \ + { SVM_EXIT_EXCP_BASE + MC_VECTOR, "MC excp" }, \ + { SVM_EXIT_INTR, "interrupt" }, \ + { SVM_EXIT_NMI, "nmi" }, \ + { SVM_EXIT_SMI, "smi" }, \ + { SVM_EXIT_INIT, "init" }, \ + { SVM_EXIT_VINTR, "vintr" }, \ + { SVM_EXIT_CPUID, "cpuid" }, \ + { SVM_EXIT_INVD, "invd" }, \ + { SVM_EXIT_HLT, "hlt" }, \ + { SVM_EXIT_INVLPG, "invlpg" }, \ + { SVM_EXIT_INVLPGA, "invlpga" }, \ + { SVM_EXIT_IOIO, "io" }, \ + { SVM_EXIT_MSR, "msr" }, \ + { SVM_EXIT_TASK_SWITCH, "task_switch" }, \ + { SVM_EXIT_SHUTDOWN, "shutdown" }, \ + { SVM_EXIT_VMRUN, "vmrun" }, \ + { SVM_EXIT_VMMCALL, "hypercall" }, \ + { SVM_EXIT_VMLOAD, "vmload" }, \ + { SVM_EXIT_VMSAVE, "vmsave" }, \ + { SVM_EXIT_STGI, "stgi" }, \ + { SVM_EXIT_CLGI, "clgi" }, \ + { SVM_EXIT_SKINIT, "skinit" }, \ + { SVM_EXIT_WBINVD, "wbinvd" }, \ + { SVM_EXIT_MONITOR, "monitor" }, \ + { SVM_EXIT_MWAIT, "mwait" }, \ + { SVM_EXIT_XSETBV, "xsetbv" }, \ + { SVM_EXIT_NPF, "npf" } +#endif
arch/x86/include/asm/kvm_host.h +1 -16
@@ -27,6 +27,7 @@#include <asm/desc.h> #include <asm/mtrr.h> #include <asm/msr-index.h> +#include <asm/kvm_exit.h> #define KVM_MAX_VCPUS 254#define KVM_SOFT_MAX_VCPUS 64
@@ -73,22 +74,6 @@#define KVM_HPAGE_MASK (x) (~(KVM_HPAGE_SIZE(x) - 1))#define KVM_PAGES_PER_HPAGE (x) (KVM_HPAGE_SIZE(x) / PAGE_SIZE) -#define DE_VECTOR 0 -#define DB_VECTOR 1 -#define BP_VECTOR 3 -#define OF_VECTOR 4 -#define BR_VECTOR 5 -#define UD_VECTOR 6 -#define NM_VECTOR 7 -#define DF_VECTOR 8 -#define TS_VECTOR 10 -#define NP_VECTOR 11 -#define SS_VECTOR 12 -#define GP_VECTOR 13 -#define PF_VECTOR 14 -#define MF_VECTOR 16 -#define MC_VECTOR 18 -#define SELECTOR_TI_MASK (1 << 2)#define SELECTOR_RPL_MASK 0x03
arch/x86/include/asm/svm.h +2 -75
89 lines not on this page · raw message
arch/x86/include/asm/vmx.h +1 -43
60 lines not on this page · raw message
arch/x86/kvm/trace.h +0 -89
95 lines not on this page · raw message
Signature · 1 line
1.7.7.5
Re: [PATCH v2 1/3] KVM: x86: move kvm_exit related definitions into kvm_exit.h
Quoted 4 lines · Xiao Guangrong
From: Xiao Guangrong <[email protected]>
Move the definitions into a separate .h file so that 'perf kvm-events' can easily use these
Why not just include vmx.h and svm.h? I don't like scattering those definitions around.
Quoted 3 lines
Signed-off-by Xiao Guangrong <[email protected]>--- arch/x86/include/asm/kvm_exit.h | 229 +++++++++++++++++++++++++++++++++++++++
Especially as this file doesn't make a distinction between vmx and svm.
Signature · 1 line
error compiling committee.c: too many arguments to function
Re: [PATCH v2 1/3] KVM: x86: move kvm_exit related definitions into kvm_exit.h
Quoted 9 lines · Avi Kivity
Quoted 4 lines · Xiao Guangrong
From: Xiao Guangrong <[email protected]>
Move the definitions into a separate .h file so that 'perf kvm-events' can easily use these
Why not just include
vmx.handsvm.h? I don't like scattering those definitions around.
Err, if we directly include "vmx.h" and "svm.h" we should use "#ifdef __KERNEL__" to split the definition, it is ugly i think, but i do not have strong opinion on it, i will switch to your way :)
PATCH v2 2/3 KVM: x86: add tracepoints to trace mmio begin and complete
In reply to Xiao GuangrongFrom: Xiao Guangrong <[email protected]>
'perf kvm-events' will use kvm_exit and kvm_mmio(read...) to calculate mmio read emulated time for the old kernel, in order to trace mmio read event more exactly, we add kvm_mmio_begin to trace the time when mmio read begins
Also, add kvm_mmio_done to trace the time when mmio/pio is completed
--- arch/x86/kvm/x86.c | 21 ++++++++++++++------- include/trace/events/kvm.h | 37 +++++++++++++++++++++++++++++++++++++ 2 files changed, 51 insertions(+), 7 deletions(-)
arch/x86/kvm/x86.c +14 -7
@@ -3766,9 +3766,12 @@ mmio:/* * Is this MMIO handled locally? */ +trace_kvm_mmio_begin (vcpu->vcpu_id, write, gpa); handled = ops->read_write_mmio (vcpu, gpa, bytes, val); -if (handled == bytes) +if (handled == bytes) { +trace_kvm_mmio_done (vcpu->vcpu_id);return X86EMUL_CONTINUE ; + } gpa += handled; bytes -= handled;
@@ -3934,6 +3937,7 @@ static int emulator_pio_in_out(struct kvm_vcpu *vcpu, int size, vcpu->arch.pio.size = size;if (!kernel_pio (vcpu, vcpu->arch.pio_data)) { +trace_kvm_mmio_done (vcpu->vcpu_id); vcpu->arch.pio.count =0 ;return 1 ; }
@@ -4544,9 +4548,7 @@ restart:inject_emulated_exception (vcpu); r =EMULATE_DONE ; }else if (vcpu->arch.pio.count) { -if (!vcpu->arch.pio.in) - vcpu->arch.pio.count =0 ; -else +if (vcpu->arch.pio.in) writeback = false; r =EMULATE_DO_MMIO ; }else if (vcpu->mmio_needed) {
@@ -4577,8 +4579,6 @@ int kvm_fast_pio_out(struct kvm_vcpu *vcpu, int size, unsigned short port)unsigned long val =kvm_register_read (vcpu,VCPU_REGS_RAX );int ret =emulator_pio_out_emulated (&vcpu->arch.emulate_ctxt, size, port, &val,1 ); -/* do not return to emulator after return from userspace */ - vcpu->arch.pio.count =0 ;return ret; }EXPORT_SYMBOL_GPL (kvm_fast_pio_out);
@@ -5407,6 +5407,11 @@ static int complete_mmio(struct kvm_vcpu *vcpu)if (!(vcpu->arch.pio.count || vcpu->mmio_needed))return 1 ; +if (vcpu->arch.pio.count && !vcpu->arch.pio.in) { + vcpu->arch.pio.count =0 ; + goto exit; + } +if (vcpu->mmio_needed) { vcpu->mmio_needed =0 ;if (!vcpu->mmio_is_write)
@@ -5423,7 +5428,7 @@ static int complete_mmio(struct kvm_vcpu *vcpu)return 0 ; }if (vcpu->mmio_is_write) -return 1 ; + goto exit; vcpu->mmio_read_completed =1 ; } vcpu->srcu_idx =srcu_read_lock (&vcpu->kvm->srcu);
@@ -5431,6 +5436,8 @@ static int complete_mmio(struct kvm_vcpu *vcpu)srcu_read_unlock (&vcpu->kvm->srcu, vcpu->srcu_idx);if (r !=EMULATE_DONE )return 0 ; +exit: +trace_kvm_mmio_done (vcpu->vcpu_id);return 1 ; }
include/trace/events/kvm.h +37 -0
@@ -174,6 +174,43 @@ TRACE_EVENT(kvm_mmio, __entry->len, __entry->gpa, __entry->val) ); +TRACE_EVENT (kvm_mmio_begin, + TP_PROTO(unsigned int vcpu_id, bool rw, u64 gpa), +TP_ARGS (vcpu_id, rw, gpa), + +TP_STRUCT__entry ( + __field(unsigned int, vcpu_id) + __field(int, type) +__field (u64, gpa) + ), + +TP_fast_assign ( + __entry->vcpu_id = vcpu_id; + __entry->type = rw ? KVM_TRACE_MMIO_WRITE : + KVM_TRACE_MMIO_READ; + __entry->gpa = gpa; + ), + +TP_printk ("vcpu %u mmio %s gpa 0x%llx" , __entry->vcpu_id, +__print_symbolic (__entry->type, kvm_trace_symbol_mmio), + __entry->gpa) +); + +TRACE_EVENT (kvm_mmio_done, + TP_PROTO(unsigned int vcpu_id), +TP_ARGS (vcpu_id), + +TP_STRUCT__entry ( + __field( unsigned int, vcpu_id ) + ), + +TP_fast_assign ( + __entry->vcpu_id = vcpu_id; + ), + +TP_printk ("vcpu %u" , __entry->vcpu_id) +); +#define kvm_fpu_load_symbol \ {0, "unload"}, \ {1, "load"}
Signature · 1 line
1.7.7.5
Re: [PATCH v2 2/3] KVM: x86: add tracepoints to trace mmio begin and complete
Quoted 8 lines · Xiao Guangrong
From: Xiao Guangrong <[email protected]>
'perf kvm-events' will use
kvm_exitandkvm_mmio(read...)to calculate mmio read emulated time for the old kernel, in order to trace mmio read event more exactly, we addkvm_mmio_beginto trace the time when mmio read beginsAlso, add
kvm_mmio_doneto trace the time when mmio/pio is completed
Previously, we discussed using the kvm_entry to do this. This reduces the number of tracepoints, and is backwards compatible. What was the conclusion?
Signature · 1 line
error compiling committee.c: too many arguments to function
Re: [PATCH v2 2/3] KVM: x86: add tracepoints to trace mmio begin and complete
Quoted 8 lines · Avi Kivity
Quoted 7 lines · Xiao Guangrong
From: Xiao Guangrong <[email protected]>
'perf kvm-events' will use
kvm_exitandkvm_mmio(read...)to calculate mmio read emulated time for the old kernel, in order to trace mmio read event more exactly, we addkvm_mmio_beginto trace the time when mmio read begins
Quoted 6 lines
Quoted 1 line
Also, add
kvm_mmio_doneto trace the time when mmio/pio is completedPreviously, we discussed using the
kvm_entryto do this. This reduces the number of tracepoints, and is backwards compatible. What was the conclusion?
Since using kvm_entry can cause lots of unnecessary calculated, these new two tracepoints can let the result be exacter.
And, they are only used in new kernel, we will fall back to using kvm_entry if they are not existing, that means it does not break backwards compatible.
Re: [PATCH v2 2/3] KVM: x86: add tracepoints to trace mmio begin and complete
Quoted 12 lines · Xiao Guangrong
Quoted 10 lines · Avi Kivity
Quoted 8 lines · Xiao Guangrong
From: Xiao Guangrong <[email protected]>
'perf kvm-events' will use
kvm_exitandkvm_mmio(read...)to calculate mmio read emulated time for the old kernel, in order to trace mmio read event more exactly, we addkvm_mmio_beginto trace the time when mmio read beginsAlso, add
kvm_mmio_doneto trace the time when mmio/pio is completed
Quoted 8 lines
Quoted 4 lines
Previously, we discussed using the
kvm_entryto do this. This reduces the number of tracepoints, and is backwards compatible. What was the conclusion?Since using
kvm_entrycan cause lots of unnecessary calculated, these new two tracepoints can let the result be exacter.
Do you have numbers on the ratio between kvm_entry traces and kvm_mmio_begin/end traces?
Quoted 2 lines
And, they are only used in new kernel, we will fall back to using
kvm_entryif they are not existing, that means it does not break backwards compatible.
Ah ok.
Signature · 1 line
error compiling committee.c: too many arguments to function
Re: [PATCH v2 2/3] KVM: x86: add tracepoints to trace mmio begin and complete
Quoted 19 lines · Avi Kivity
Quoted 18 lines · Xiao Guangrong
Quoted 14 lines · Avi Kivity
Quoted 8 lines · Xiao Guangrong
From: Xiao Guangrong <[email protected]>
'perf kvm-events' will use
kvm_exitandkvm_mmio(read...)to calculate mmio read emulated time for the old kernel, in order to trace mmio read event more exactly, we addkvm_mmio_beginto trace the time when mmio read beginsAlso, add
kvm_mmio_doneto trace the time when mmio/pio is completedPreviously, we discussed using the
kvm_entryto do this. This reduces the number of tracepoints, and is backwards compatible. What was the conclusion?
Quoted 6 lines
Quoted 2 lines
Since using
kvm_entrycan cause lots of unnecessary calculated, these new two tracepoints can let the result be exacter.Do you have numbers on the ratio between
kvm_entrytraces and kvm_mmio_begin/end traces?
1: Using kvm_mmio_begin/end:
# ./perf kvm-events report --event mmio Warning: Error: expected type 5 but read 4 Warning: Error: expected type 5 but read 0 Warning: unknown op '}'
Analyze events for all VCPUs:
MMIO Access Samples Samples% Time% Avg time
0xfee00380:W 54926 58.45% 57.32% 3.90us ( +- 0.29% )
0xfee00300:W 12906 13.73% 28.70% 8.32us ( +- 0.50% )
0xfee00300:R 12906 13.73% 7.68% 2.23us ( +- 1.27% )
0xfee00310:W 12906 13.73% 6.07% 1.76us ( +- 1.05% )
0xfee00190:R 323 0.34% 0.23% 2.65us ( +- 2.85% )Total Samples:93967, Total events handled time:374012.26us.
2: kvm_mmio_begin/end is not used:
# ./perf kvm-events report --event mmio Warning: Error: expected type 5 but read 4 Warning: Error: expected type 5 but read 0 Warning: unknown op '}'
Analyze events for all VCPUs:
MMIO Access Samples Samples% Time% Avg time
0xfee00380:W 54926 58.45% 42.90% 3.90us ( +- 0.29% )
0xfee00300:W 12906 13.73% 21.48% 8.32us ( +- 0.50% )
0xfee00300:R 12906 13.73% 30.26% 11.72us ( +- 1.40% )
0xfee00310:W 12906 13.73% 4.54% 1.76us ( +- 1.05% )
0xfee00190:R 323 0.34% 0.82% 12.63us ( +- 2.85% )Total Samples:93967, Total events handled time:499755.82us.
In this sample, the time of MMIO Read has big different,
in the case 1(new tracepoints), the time is calculated by kvm_mmio_begin -> kvm_mmio(read...) in the case 2(existing tracepoints), the time is calculated by kvm_exit -> kvm_mmio(read...)
Re: [PATCH v2 2/3] KVM: x86: add tracepoints to trace mmio begin and complete
Quoted 67 lines · Xiao Guangrong
Quoted 19 lines · Avi Kivity
Quoted 18 lines · Xiao Guangrong
Quoted 14 lines · Avi Kivity
Quoted 8 lines · Xiao Guangrong
From: Xiao Guangrong <[email protected]>
'perf kvm-events' will use
kvm_exitandkvm_mmio(read...)to calculate mmio read emulated time for the old kernel, in order to trace mmio read event more exactly, we addkvm_mmio_beginto trace the time when mmio read beginsAlso, add
kvm_mmio_doneto trace the time when mmio/pio is completedPreviously, we discussed using the
kvm_entryto do this. This reduces the number of tracepoints, and is backwards compatible. What was the conclusion?Quoted 6 lines
Quoted 2 lines
Since using
kvm_entrycan cause lots of unnecessary calculated, these new two tracepoints can let the result be exacter.Do you have numbers on the ratio between
kvm_entrytraces and kvm_mmio_begin/end traces?1: Using kvm_mmio_begin/end:
# ./perf kvm-events report --event mmio Warning: Error: expected type 5 but read 4 Warning: Error: expected type 5 but read 0 Warning: unknown op '}'Analyze events for all VCPUs:
MMIO Access Samples Samples% Time% Avg time 0xfee00380:W 54926 58.45% 57.32% 3.90us ( +- 0.29% ) 0xfee00300:W 12906 13.73% 28.70% 8.32us ( +- 0.50% ) 0xfee00300:R 12906 13.73% 7.68% 2.23us ( +- 1.27% ) 0xfee00310:W 12906 13.73% 6.07% 1.76us ( +- 1.05% ) 0xfee00190:R 323 0.34% 0.23% 2.65us ( +- 2.85% )Total Samples:93967, Total events handled time:374012.26us.
2: kvm_mmio_begin/end is not used:
# ./perf kvm-events report --event mmio Warning: Error: expected type 5 but read 4 Warning: Error: expected type 5 but read 0 Warning: unknown op '}'Analyze events for all VCPUs:
MMIO Access Samples Samples% Time% Avg time 0xfee00380:W 54926 58.45% 42.90% 3.90us ( +- 0.29% ) 0xfee00300:W 12906 13.73% 21.48% 8.32us ( +- 0.50% ) 0xfee00300:R 12906 13.73% 30.26% 11.72us ( +- 1.40% ) 0xfee00310:W 12906 13.73% 4.54% 1.76us ( +- 1.05% ) 0xfee00190:R 323 0.34% 0.82% 12.63us ( +- 2.85% )
Quoted 5 lines
Total Samples:93967, Total events handled time:499755.82us.
In this sample, the time of MMIO Read has big different,
in the case 1(new tracepoints), the time is calculated bykvm_mmio_begin->kvm_mmio(read...)in the case 2(existing tracepoints), the time is calculated bykvm_exit->kvm_mmio(read...)
And the pio result:
1: Using kvm_mmio_begin/end:
# ./perf kvm-events report --event ioport --key time Warning: Error: expected type 5 but read 4 Warning: Error: expected type 5 but read 0 Warning: unknown op '}'
Analyze events for all VCPUs:
IO Port Access Samples Samples% Time% Avg time
0x1f0:PIN 3 0.00% 0.02% 115.91us ( +- 12.55% )
0xc026:PIN 645 0.32% 4.55% 105.21us ( +- 59.73% )
0x64:PIN 114 0.06% 0.14% 18.63us ( +- 5.02% )
0xc022:PIN 457 0.23% 0.53% 17.18us ( +- 4.15% )
0x60:PIN 114 0.06% 0.11% 14.56us ( +- 7.16% )
0xc000:POUT 22512 11.30% 17.21% 11.41us ( +- 6.84% )
0x1f7:PIN 30044 15.08% 22.53% 11.19us ( +- 10.37% )
0xc024:POUT 6 0.00% 0.00% 10.60us ( +- 54.28% )......
2: kvm_mmio_begin/end is not used:
# ./perf kvm-events report --event ioport --key time Warning: Error: expected type 5 but read 4 Warning: Error: expected type 5 but read 0 Warning: unknown op '}'
Analyze events for all VCPUs:
IO Port Access Samples Samples% Time% Avg time
0x1f0:PIN 3 0.00% 0.02% 118.37us ( +- 12.65% )
0xc026:PIN 645 0.32% 3.54% 107.89us ( +- 58.26% )
0x64:PIN 114 0.06% 0.13% 23.04us ( +- 6.44% )
0xc022:PIN 457 0.23% 0.48% 20.63us ( +- 3.65% )
0x60:PIN 114 0.06% 0.10% 17.70us ( +- 6.41% )
0xc000:POUT 22512 11.30% 16.19% 14.14us ( +- 6.27% )
0x1f7:PIN 30044 15.08% 21.18% 13.85us ( +- 8.39% )
0xc024:POUT 6 0.00% 0.00% 13.09us ( +- 47.40% )......
The time of case 1 is calculated by kvm_pio -> kvm_mmio_done The time of case 2 is calculated by kvm_pio -> kvm_entry
PATCH v2 3/3 KVM: perf: kvm events analysis tool
In reply to Xiao GuangrongFrom: Xiao Guangrong <[email protected]>
Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly
Usage:
- trace kvm events:
perf kvm-events record, or, if other tracepoints are also interesting, we can append the events like this:
perf kvm-events record -e timer:*
- show the result:
perf kvm-events report
--- tools/perf/Documentation/perf-kvm-events.txt | 56 ++ tools/perf/Makefile | 1 + tools/perf/builtin-kvm-events.c | 909 ++++++++++++++++++++++++++ tools/perf/builtin.h | 1 + tools/perf/command-list.txt | 1 + tools/perf/perf.c | 1 + 6 files changed, 969 insertions(+), 0 deletions(-) create mode 100644 tools/perf/Documentation/perf-kvm-events.txt create mode 100644 tools/perf/builtin-kvm-events.c
tools/perf/Documentation/perf-kvm-events.txt new file +56 -0
@@ -0,0 +1,56 @@ +perf-kvm-events(1) +============ + +NAME +---- +perf-kvm-events - Analyze kvm events + +SYNOPSIS +-------- +[verse] +'perf kvm-events' {record|report} + +DESCRIPTION +----------- +You can analyze some crucial kvm events and statistics with this +'perf kvm-events' command. Currently, vmexit, mmio and ioport events +are supported. + + 'perf kvm-events record <command>' records kvm events(vmexit, + mmio and ioport) and the events between start and end <command>. + And this command produces the file "perf.data" which contains + tracing results of kvm events. + + 'perf kvm-events report' reports statistical data which includes + events handled time, samples, and so on. + +COMMON OPTIONS +-------------- + +-i:: +--input=<file>:: + Input file name. (default: perf.data unless stdin is a fifo) + +-v:: +--verbose:: + Be more verbose (show symbol address, etc). + +-D:: +--dump-raw-trace:: + Dump raw trace in ASCII. + +REPORT OPTIONS +-------------- +--vcpu=<value>:: + analyze events which occures on this vcpu + +--events=<value>:: + events to be analyzed. Possible values: vmexit, mmio, ioport. +-k:: +--key=<value>:: + Sorting key. Possible values: sample(default, sort by samples number), +time(sort by average time). + +SEE ALSO +-------- +linkperf:perf[1]
tools/perf/Makefile +1 -0
@@ -382,6 +382,7 @@ BUILTIN_OBJS += $(OUTPUT)builtin-probe.o BUILTIN_OBJS += $(OUTPUT)builtin-kmem.o BUILTIN_OBJS += $(OUTPUT)builtin-lock.o BUILTIN_OBJS += $(OUTPUT)builtin-kvm.o +BUILTIN_OBJS += $(OUTPUT)builtin-kvm-events.o BUILTIN_OBJS += $(OUTPUT)builtin-test.o BUILTIN_OBJS += $(OUTPUT)builtin-inject.o
tools/perf/builtin-kvm-events.c new file +909 -0
909 lines not on this page · raw message
tools/perf/builtin.h +1 -0
@@ -33,6 +33,7 @@ extern int cmd_probe(int argc, const char **argv, const char *prefix);extern int cmd_kmem (int argc,const char **argv,const char *prefix);extern int cmd_lock (int argc,const char **argv,const char *prefix);extern int cmd_kvm (int argc,const char **argv,const char *prefix); +extern int cmd_kvm_events (int argc,const char **argv,const char *prefix);extern int cmd_test (int argc,const char **argv,const char *prefix);extern int cmd_inject (int argc,const char **argv,const char *prefix);
tools/perf/command-list.txt +1 -0
@@ -22,4 +22,5 @@ perf-probe mainporcelain common perf-kmem mainporcelain common perf-lock mainporcelain common perf-kvm mainporcelain common +perf-kvm-events mainporcelain common perf-test mainporcelain common
tools/perf/perf.c +1 -0
@@ -317,6 +317,7 @@ static void handle_internal_command(int argc, const char **argv) { "kmem", cmd_kmem, 0 }, { "lock", cmd_lock, 0 }, { "kvm", cmd_kvm, 0 }, + { "kvm-events", cmd_kvm_events, 0}, { "test", cmd_test, 0 }, { "inject", cmd_inject, 0 }, };
Signature · 1 line
1.7.7.5