2012-02-09 09:07:01

by Xiao Guangrong

[permalink] [raw]
Subject: [PATCH v4 0/3] KVM: perf: kvm events analysis tool

Changlog:
There are some changes from David Ahern's review:
- let the tool to be off-box analysis by getting cpu isa
from HEADER_CPUID feature and removing max-vcpu related code.

- attach per vcpu record structure to the thread by adding a void pointer
in "struct thread".

- remove unnecessary tool argument(-v).

The output example is following:
# ./perf kvm-events report --event mmio --vcpu 3
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'


Analyze events for VCPU 3:

MMIO Access Samples Samples% Time% Avg time

0xfee00380:W 45534 78.00% 84.76% 5.27us ( +- 0.77% )
0xfee00300:W 4280 7.33% 9.37% 6.20us ( +- 1.91% )
0xfee00300:R 4280 7.33% 3.34% 2.21us ( +- 1.53% )
0xfee00310:W 4280 7.33% 2.52% 1.67us ( +- 0.71% )

Total Samples:58374, Total events handled time:283257.68us.


2012-02-09 09:08:11

by Xiao Guangrong

[permalink] [raw]
Subject: [PATCH 1/3] KVM: x86: export svm/vmx exit code and vector code to userspace

They will be needed by 'perf kvm-events'

Signed-off-by: Xiao Guangrong <[email protected]>
---
arch/x86/include/asm/kvm_host.h | 36 ++++---
arch/x86/include/asm/svm.h | 205 +++++++++++++++++++++++++--------------
arch/x86/include/asm/vmx.h | 125 ++++++++++++++++--------
arch/x86/kvm/trace.h | 89 -----------------
4 files changed, 233 insertions(+), 222 deletions(-)

diff --git a/arch/x86/include/asm/kvm_host.h b/arch/x86/include/asm/kvm_host.h
index 4610166..01c1b19 100644
--- a/arch/x86/include/asm/kvm_host.h
+++ b/arch/x86/include/asm/kvm_host.h
@@ -11,6 +11,24 @@
#ifndef _ASM_X86_KVM_HOST_H
#define _ASM_X86_KVM_HOST_H

+#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
+
+#ifdef __KERNEL__
+
#include <linux/types.h>
#include <linux/mm.h>
#include <linux/mmu_notifier.h>
@@ -73,22 +91,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

@@ -939,4 +941,6 @@ int kvm_pmu_read_pmc(struct kvm_vcpu *vcpu, unsigned pmc, u64 *data);
void kvm_handle_pmu_event(struct kvm_vcpu *vcpu);
void kvm_deliver_pmi(struct kvm_vcpu *vcpu);

+#endif
+
#endif /* _ASM_X86_KVM_HOST_H */
diff --git a/arch/x86/include/asm/svm.h b/arch/x86/include/asm/svm.h
index f2b83bc..d9f0290f 100644
--- a/arch/x86/include/asm/svm.h
+++ b/arch/x86/include/asm/svm.h
@@ -1,6 +1,135 @@
#ifndef __SVM_H
#define __SVM_H

+#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 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" }
+
+#ifdef __KERNEL__
+
enum {
INTERCEPT_INTR,
INTERCEPT_NMI,
@@ -264,81 +393,6 @@ struct __attribute__ ((__packed__)) vmcb {

#define SVM_EXITINFO_REG_MASK 0x0F

-#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 SVM_CR0_SELECTIVE_MASK (X86_CR0_TS | X86_CR0_MP)

#define SVM_VMLOAD ".byte 0x0f, 0x01, 0xda"
@@ -350,3 +404,4 @@ struct __attribute__ ((__packed__)) vmcb {

#endif

+#endif
diff --git a/arch/x86/include/asm/vmx.h b/arch/x86/include/asm/vmx.h
index 31f180c..c644034 100644
--- a/arch/x86/include/asm/vmx.h
+++ b/arch/x86/include/asm/vmx.h
@@ -25,6 +25,87 @@
*
*/

+#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 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" }
+
+#ifdef __KERNEL__
+
#include <linux/types.h>

/*
@@ -240,48 +321,6 @@ enum vmcs_field {
HOST_RIP = 0x00006c16,
};

-#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
-
/*
* Interruption-information format
*/
@@ -482,3 +521,5 @@ enum vm_instruction_error_number {
};

#endif
+
+#endif
diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index 911d264..89cbbe5 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -183,95 +183,6 @@ TRACE_EVENT(kvm_apic,
#define KVM_ISA_VMX 1
#define KVM_ISA_SVM 2

-#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" }
-
/*
* Tracepoint for kvm guest exit:
*/

2012-02-09 09:09:20

by Xiao Guangrong

[permalink] [raw]
Subject: [PATCH 2/3] KVM: x86: add tracepoints to trace mmio begin and complete

'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

Signed-off-by: Xiao Guangrong <[email protected]>
---
arch/x86/kvm/x86.c | 21 ++++++++++++++-------
include/trace/events/kvm.h | 37 +++++++++++++++++++++++++++++++++++++
2 files changed, 51 insertions(+), 7 deletions(-)

diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index 2bd77a3..6750978 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -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;
}

diff --git a/include/trace/events/kvm.h b/include/trace/events/kvm.h
index 46e3cd8..16c8a6d 100644
--- a/include/trace/events/kvm.h
+++ b/include/trace/events/kvm.h
@@ -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"}
--
1.7.7.6

2012-02-09 09:10:00

by Xiao Guangrong

[permalink] [raw]
Subject: [PATCH 3/3] KVM: perf: kvm events analysis tool

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

Signed-off-by: Xiao Guangrong <[email protected]>
---
tools/perf/Documentation/perf-kvm-events.txt | 52 ++
tools/perf/Makefile | 1 +
tools/perf/builtin-kvm-events.c | 851 ++++++++++++++++++++++++++
tools/perf/builtin.h | 1 +
tools/perf/command-list.txt | 1 +
tools/perf/perf.c | 1 +
tools/perf/util/header.c | 54 ++-
tools/perf/util/header.h | 1 +
tools/perf/util/thread.h | 2 +
9 files changed, 963 insertions(+), 1 deletions(-)
create mode 100644 tools/perf/Documentation/perf-kvm-events.txt
create mode 100644 tools/perf/builtin-kvm-events.c

diff --git a/tools/perf/Documentation/perf-kvm-events.txt b/tools/perf/Documentation/perf-kvm-events.txt
new file mode 100644
index 0000000..ed36550
--- /dev/null
+++ b/tools/perf/Documentation/perf-kvm-events.txt
@@ -0,0 +1,52 @@
+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)
+
+-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]
diff --git a/tools/perf/Makefile b/tools/perf/Makefile
index ac86d67..ee43451 100644
--- a/tools/perf/Makefile
+++ b/tools/perf/Makefile
@@ -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

diff --git a/tools/perf/builtin-kvm-events.c b/tools/perf/builtin-kvm-events.c
new file mode 100644
index 0000000..9903d2b
--- /dev/null
+++ b/tools/perf/builtin-kvm-events.c
@@ -0,0 +1,851 @@
+#include "builtin.h"
+#include "perf.h"
+#include "util/util.h"
+#include "util/cache.h"
+#include "util/symbol.h"
+#include "util/thread.h"
+#include "util/header.h"
+#include "util/parse-options.h"
+#include "util/trace-event.h"
+#include "util/debug.h"
+#include "util/debugfs.h"
+#include "util/session.h"
+#include "util/tool.h"
+
+#include <math.h>
+
+#include <linux/kvm.h>
+
+#include "../../arch/x86/include/asm/svm.h"
+#include "../../arch/x86/include/asm/vmx.h"
+#include "../../arch/x86/include/asm/kvm_host.h"
+
+struct event_key {
+ #define INVALID_KEY (~0ULL)
+ u64 key;
+ int info;
+};
+
+struct kvm_events_ops {
+ bool (*is_begin_event)(struct event *event, void *data,
+ struct event_key *key);
+ bool (*is_end_event)(struct event *event, void *data,
+ struct event_key *key);
+ void (*decode_key)(struct event_key *key, char decode[20]);
+ const char *name;
+};
+
+static int cpu_isa;
+
+static void exit_event_get_key(struct event *event, void *data,
+ struct event_key *key)
+{
+ key->info = cpu_isa;
+ key->key = raw_field_value(event, "exit_reason", data);
+}
+
+static bool kvm_exit_event(struct event *event)
+{
+ return !strcmp(event->name, "kvm_exit");
+}
+
+static bool exit_event_begin(struct event *event, void *data,
+ struct event_key *key)
+{
+ if (kvm_exit_event(event)) {
+ exit_event_get_key(event, data, key);
+ return true;
+ }
+
+ return false;
+}
+
+static bool kvm_entry_event(struct event *event)
+{
+ return !strcmp(event->name, "kvm_entry");
+}
+
+static bool exit_event_end(struct event *event, void *data __unused,
+ struct event_key *key __unused)
+{
+ return kvm_entry_event(event);
+}
+
+struct exit_reasons_table {
+ unsigned long exit_code;
+ const char *reason;
+};
+
+struct exit_reasons_table vmx_exit_reasons[] = {
+ VMX_EXIT_REASONS
+};
+
+struct exit_reasons_table svm_exit_reasons[] = {
+ SVM_EXIT_REASONS
+};
+
+static const char *get_exit_reason(u64 exit_code, int isa)
+{
+ int table_size = ARRAY_SIZE(svm_exit_reasons);
+ struct exit_reasons_table *table = svm_exit_reasons;
+
+ if (isa == 1) {
+ table = vmx_exit_reasons;
+ table_size = ARRAY_SIZE(vmx_exit_reasons);
+ }
+
+ while (table_size--) {
+ if (table->exit_code == exit_code)
+ return table->reason;
+ table++;
+ }
+
+ die("unknown kvm exit code:%ld on %s\n", exit_code,
+ isa ? "VMX" : "SVM");
+}
+
+static void exit_event_decode_key(struct event_key *key, char decode[20])
+{
+ const char *exit_reason = get_exit_reason(key->key, key->info);
+
+ snprintf(decode, 20, "%s", exit_reason);
+}
+
+static struct kvm_events_ops exit_events = {
+ .is_begin_event = exit_event_begin,
+ .is_end_event = exit_event_end,
+ .decode_key = exit_event_decode_key,
+ .name = "VM-EXIT"
+};
+
+/*
+ * For the old kernel, we treat:
+ * the time of MMIO write: kvm_mmio(KVM_TRACE_MMIO_WRITE...) -> kvm_entry
+ * the time of MMIO read: kvm_exit -> kvm_mmio(KVM_TRACE_MMIO_READ...).
+ *
+ * For the new kernel, we use kvm_mmio_begin and kvm_mmio_done to make
+ * things better.
+ */
+static void mmio_event_get_key(struct event *event, void *data,
+ struct event_key *key)
+{
+ key->key = raw_field_value(event, "gpa", data);
+ key->info = raw_field_value(event, "type", data);
+}
+
+#define KVM_TRACE_MMIO_READ_UNSATISFIED 0
+#define KVM_TRACE_MMIO_READ 1
+#define KVM_TRACE_MMIO_WRITE 2
+
+static bool kvm_mmio_done_event(struct event *event)
+{
+ return !strcmp(event->name, "kvm_mmio_done");
+}
+
+static bool mmio_event_begin(struct event *event, void *data,
+ struct event_key *key)
+{
+ /* MMIO read begin in old kernel. */
+ if (kvm_exit_event(event))
+ return true;
+
+ /* MMIO write begin in old kernel. */
+ if (!strcmp(event->name, "kvm_mmio") &&
+ raw_field_value(event, "type", data) == KVM_TRACE_MMIO_WRITE) {
+ mmio_event_get_key(event, data, key);
+ return true;
+ }
+
+ /* MMIO read/write begin in new kernel. */
+ if (!strcmp(event->name, "kvm_mmio_begin")) {
+ mmio_event_get_key(event, data, key);
+ return true;
+ }
+
+ return false;
+}
+
+static bool mmio_event_end(struct event *event, void *data,
+ struct event_key *key)
+{
+ /* MMIO write end in old kernel. */
+ if (kvm_entry_event(event))
+ return true;
+
+ /* MMIO read end in the old kernel.*/
+ if (!strcmp(event->name, "kvm_mmio") &&
+ raw_field_value(event, "type", data) == KVM_TRACE_MMIO_READ) {
+ mmio_event_get_key(event, data, key);
+ return true;
+ }
+
+ /* MMIO read/write end event in the new kernel.*/
+ return kvm_mmio_done_event(event);
+}
+
+static void mmio_event_decode_key(struct event_key *key, char decode[20])
+{
+ snprintf(decode, 20, "%#lx:%s", key->key,
+ key->info == KVM_TRACE_MMIO_WRITE ? "W" : "R");
+}
+
+static struct kvm_events_ops mmio_events = {
+ .is_begin_event = mmio_event_begin,
+ .is_end_event = mmio_event_end,
+ .decode_key = mmio_event_decode_key,
+ .name = "MMIO Access"
+};
+
+/*
+ * For the old kernel, the time of emulation pio access is from kvm_pio to
+ * kvm_entry. In the new kernel, the end time is indicated by kvm_mmio_done.
+ */
+static void ioport_event_get_key(struct event *event, void *data,
+ struct event_key *key)
+{
+ key->key = raw_field_value(event, "port", data);
+ key->info = raw_field_value(event, "rw", data);
+}
+
+static bool ioport_event_begin(struct event *event, void *data,
+ struct event_key *key)
+{
+ if (!strcmp(event->name, "kvm_pio")) {
+ ioport_event_get_key(event, data, key);
+ return true;
+ }
+
+ return false;
+}
+
+static bool ioport_event_end(struct event *event, void *data __unused,
+ struct event_key *key __unused)
+{
+ if (kvm_entry_event(event))
+ return true;
+
+ return kvm_mmio_done_event(event);
+}
+
+static void ioport_event_decode_key(struct event_key *key, char decode[20])
+{
+ snprintf(decode, 20, "%#lx:%s", key->key, key->info ? "POUT" : "PIN");
+}
+
+static struct kvm_events_ops ioport_events = {
+ .is_begin_event = ioport_event_begin,
+ .is_end_event = ioport_event_end,
+ .decode_key = ioport_event_decode_key,
+ .name = "IO Port Access"
+};
+
+static const char *report_event = "vmexit";
+struct kvm_events_ops *events_ops;
+
+static void register_kvm_events_ops(void)
+{
+ if (!strcmp(report_event, "vmexit"))
+ events_ops = &exit_events;
+ else if (!strcmp(report_event, "mmio"))
+ events_ops = &mmio_events;
+ else if (!strcmp(report_event, "ioport"))
+ events_ops = &ioport_events;
+ else
+ die("Unknown report event:%s\n", report_event);
+}
+
+struct event_stats {
+ u64 count;
+ u64 time;
+
+ /* used to calculate stddev. */
+ double mean;
+ double M2;
+};
+
+struct kvm_event {
+ struct list_head hash_entry;
+ struct rb_node rb;
+
+ struct event_key key;
+
+ struct event_stats total;
+
+ #define DEFAULT_VCPU_NUM 32
+ int max_vcpu;
+ struct event_stats *vcpu;
+};
+
+struct vcpu_event_record {
+ int vcpu_id;
+ u64 start_time;
+ struct kvm_event *last_event;
+};
+
+#define EVENTS_BITS 12
+#define EVENTS_CACHE_SIZE (1UL << EVENTS_BITS)
+
+static u64 total_time;
+static u64 total_count;
+static struct list_head kvm_events_cache[EVENTS_CACHE_SIZE];
+
+static void init_kvm_event_record(void)
+{
+ int i;
+
+ for (i = 0; i < (int)EVENTS_CACHE_SIZE; i++)
+ INIT_LIST_HEAD(&kvm_events_cache[i]);
+}
+
+static int kvm_events_hash_fn(u64 key)
+{
+ return key & (EVENTS_CACHE_SIZE - 1);
+}
+
+static void kvm_event_expand(struct kvm_event *event, int vcpu_id)
+{
+ int old_max_vcpu = event->max_vcpu;
+
+ if (vcpu_id < event->max_vcpu)
+ return;
+
+ while (event->max_vcpu <= vcpu_id)
+ event->max_vcpu += DEFAULT_VCPU_NUM;
+
+ event->vcpu = realloc(event->vcpu,
+ event->max_vcpu * sizeof(*event->vcpu));
+ if (!event->vcpu)
+ die("Not enough memory\n");
+
+ memset(event->vcpu + old_max_vcpu, 0,
+ (event->max_vcpu - old_max_vcpu) * sizeof(*event->vcpu));
+}
+
+static struct kvm_event *kvm_alloc_init_event(struct event_key *key)
+{
+ struct kvm_event *event;
+
+ event = zalloc(sizeof(*event));
+ if (!event)
+ die("Not enough memory\n");
+
+ event->key = *key;
+ return event;
+}
+
+static struct kvm_event *find_create_kvm_event(struct event_key *key)
+{
+ struct kvm_event *event;
+ struct list_head *head;
+
+ BUG_ON(key->key == INVALID_KEY);
+
+ head = &kvm_events_cache[kvm_events_hash_fn(key->key)];
+ list_for_each_entry(event, head, hash_entry)
+ if (event->key.key == key->key && event->key.info == key->info)
+ return event;
+
+ event = kvm_alloc_init_event(key);
+ list_add(&event->hash_entry, head);
+ return event;
+}
+
+static void handle_begin_event(struct vcpu_event_record *vcpu_record,
+ struct event_key *key, u64 timestamp)
+{
+ struct kvm_event *event = NULL;
+
+ if (key->key != INVALID_KEY)
+ event = find_create_kvm_event(key);
+
+ vcpu_record->last_event = event;
+ vcpu_record->start_time = timestamp;
+}
+
+static void update_event_stats(struct event_stats *stats, u64 time_diff)
+{
+ double delta;
+
+ stats->count++;
+ stats->time += time_diff;
+
+ delta = time_diff - stats->mean;
+ stats->mean += delta / stats->count;
+ stats->M2 += delta*(time_diff - stats->mean);
+}
+
+static double event_stats_stddev(int vcpu_id, struct kvm_event *event)
+{
+ struct event_stats *stats = &event->total;
+ double variance, variance_mean, stddev;
+
+ if (vcpu_id != -1)
+ stats = &event->vcpu[vcpu_id];
+
+ BUG_ON(!stats->count);
+
+ variance = stats->M2 / (stats->count - 1);
+ variance_mean = variance / stats->count;
+ stddev = sqrt(variance_mean);
+
+ return stddev * 100 / stats->mean;
+}
+
+static void update_kvm_event(struct kvm_event *event, int vcpu_id,
+ u64 time_diff)
+{
+ update_event_stats(&event->total, time_diff);
+ kvm_event_expand(event, vcpu_id);
+ update_event_stats(&event->vcpu[vcpu_id], time_diff);
+}
+
+static void handle_end_event(struct vcpu_event_record *vcpu_record,
+ struct event_key *key, u64 timestamp)
+{
+ struct kvm_event *event;
+ u64 time_begin, time_diff;
+
+ event = vcpu_record->last_event;
+ time_begin = vcpu_record->start_time;
+
+ /* The begin event is not caught. */
+ if (!time_begin)
+ return;
+
+ /* Both begin and end events did not get the key. */
+ if (!event && key->key == INVALID_KEY)
+ return;
+
+ if (!event)
+ event = find_create_kvm_event(key);
+
+ vcpu_record->last_event = NULL;
+ vcpu_record->start_time = 0;
+
+ BUG_ON(timestamp < time_begin);
+
+ time_diff = timestamp - time_begin;
+ update_kvm_event(event, vcpu_record->vcpu_id, time_diff);
+}
+
+static struct vcpu_event_record
+*per_vcpu_record(struct thread *thread, struct event *event, void *data)
+{
+ /* Only kvm_entry records vcpu id. */
+ if (!thread->private && kvm_entry_event(event)) {
+ struct vcpu_event_record *vcpu_record;
+
+ vcpu_record = zalloc(sizeof(struct vcpu_event_record));
+ if (!vcpu_record)
+ die("Not enough memory\n");
+
+ vcpu_record->vcpu_id = raw_field_value(event, "vcpu_id", data);
+ thread->private = vcpu_record;
+ }
+
+ return (struct vcpu_event_record *)thread->private;
+}
+
+static void handle_kvm_event(struct thread *thread, struct event *event,
+ void *data, u64 timestamp)
+{
+ struct vcpu_event_record *vcpu_record;
+ struct event_key key = {.key = INVALID_KEY};
+
+ vcpu_record = per_vcpu_record(thread, event, data);
+ if (!vcpu_record)
+ return;
+
+ if (events_ops->is_begin_event(event, data, &key))
+ return handle_begin_event(vcpu_record, &key, timestamp);
+
+ if (events_ops->is_end_event(event, data, &key))
+ return handle_end_event(vcpu_record, &key, timestamp);
+}
+
+typedef int (*key_cmp_fun)(struct kvm_event*, struct kvm_event*, int);
+struct kvm_event_key {
+ const char *name;
+ key_cmp_fun key;
+};
+
+static int trace_vcpu = -1;
+#define GET_EVENT_KEY(member) \
+static u64 get_event_ ##member(struct kvm_event *event, int vcpu) \
+{ \
+ if (vcpu == -1) \
+ return event->total.member; \
+ \
+ if (vcpu >= event->max_vcpu) \
+ return 0; \
+ \
+ return event->vcpu[vcpu].member; \
+}
+
+#define COMPARE_EVENT_KEY(member) \
+GET_EVENT_KEY(member) \
+static int compare_kvm_event_ ## member(struct kvm_event *one, \
+ struct kvm_event *two, int vcpu)\
+{ \
+ return get_event_ ##member(one, vcpu) > \
+ get_event_ ##member(two, vcpu); \
+}
+
+GET_EVENT_KEY(time);
+COMPARE_EVENT_KEY(count);
+COMPARE_EVENT_KEY(mean);
+
+#define DEF_SORT_NAME_KEY(name, compare_key) \
+ { #name, compare_kvm_event_ ## compare_key }
+
+static struct kvm_event_key keys[] = {
+ DEF_SORT_NAME_KEY(sample, count),
+ DEF_SORT_NAME_KEY(time, mean),
+ { NULL, NULL }
+};
+
+static const char *sort_key = "sample";
+static key_cmp_fun compare;
+
+static void select_key(void)
+{
+ int i;
+
+ for (i = 0; keys[i].name; i++) {
+ if (!strcmp(keys[i].name, sort_key)) {
+ compare = keys[i].key;
+ return;
+ }
+ }
+
+ die("Unknown compare key:%s\n", sort_key);
+}
+
+static struct rb_root result;
+static void insert_to_result(struct kvm_event *event, key_cmp_fun bigger,
+ int vcpu)
+{
+ struct rb_node **rb = &result.rb_node;
+ struct rb_node *parent = NULL;
+ struct kvm_event *p;
+
+ while (*rb) {
+ p = container_of(*rb, struct kvm_event, rb);
+ parent = *rb;
+
+ if (bigger(event, p, vcpu))
+ rb = &(*rb)->rb_left;
+ else
+ rb = &(*rb)->rb_right;
+ }
+
+ rb_link_node(&event->rb, parent, rb);
+ rb_insert_color(&event->rb, &result);
+}
+
+static void update_total_count(struct kvm_event *event, int vcpu)
+{
+ total_count += get_event_count(event, vcpu);
+ total_time += get_event_time(event, vcpu);
+}
+
+static bool event_is_valid(struct kvm_event *event, int vcpu)
+{
+ return get_event_count(event, vcpu);
+}
+
+static void sort_result(int vcpu)
+{
+ unsigned int i;
+ struct kvm_event *event;
+
+ for (i = 0; i < EVENTS_CACHE_SIZE; i++)
+ list_for_each_entry(event, &kvm_events_cache[i], hash_entry)
+ if (event_is_valid(event, vcpu)) {
+ update_total_count(event, vcpu);
+ insert_to_result(event, compare, vcpu);
+ }
+}
+
+/* returns left most element of result, and erase it */
+static struct kvm_event *pop_from_result(void)
+{
+ struct rb_node *node = result.rb_node;
+
+ if (!node)
+ return NULL;
+
+ while (node->rb_left)
+ node = node->rb_left;
+
+ rb_erase(node, &result);
+ return container_of(node, struct kvm_event, rb);
+}
+
+static void print_vcpu_info(int vcpu)
+{
+ pr_info("Analyze events for ");
+
+ if (vcpu == -1)
+ pr_info("all VCPUs:\n\n");
+ else
+ pr_info("VCPU %d:\n\n", vcpu);
+}
+
+static void print_result(int vcpu)
+{
+ char decode[20];
+ struct kvm_event *event;
+
+ pr_info("\n\n");
+ print_vcpu_info(vcpu);
+ pr_info("%20s ", events_ops->name);
+ pr_info("%10s ", "Samples");
+ pr_info("%9s ", "Samples%");
+
+ pr_info("%9s ", "Time%");
+ pr_info("%16s ", "Avg time");
+ pr_info("\n\n");
+
+ while ((event = pop_from_result())) {
+ u64 ecount, etime;
+
+ ecount = get_event_count(event, vcpu);
+ etime = get_event_time(event, vcpu);
+
+ events_ops->decode_key(&event->key, decode);
+ pr_info("%20s ", decode);
+ pr_info("%10lu ", ecount);
+ pr_info("%8.2f%% ", (double)ecount / total_count * 100);
+ pr_info("%8.2f%% ", (double)etime / total_time * 100);
+ pr_info("%9.2fus ( +-%7.2f%% )", (double)etime / ecount/1e3,
+ event_stats_stddev(trace_vcpu, event));
+ pr_info("\n");
+ }
+
+ pr_info("\nTotal Samples:%ld, Total events handled time:%.2fus.\n\n",
+ total_count, total_time / 1e3);
+}
+
+static void process_raw_event(struct thread *thread, void *data, u64 timestamp)
+{
+ struct event *event;
+ int type;
+
+ type = trace_parse_common_type(data);
+ event = trace_find_event(type);
+
+ return handle_kvm_event(thread, event, data, timestamp);
+}
+
+static int process_sample_event(struct perf_tool *tool __used,
+ union perf_event *event,
+ struct perf_sample *sample,
+ struct perf_evsel *evsel __used,
+ struct machine *machine)
+{
+ struct thread *thread = machine__findnew_thread(machine, sample->tid);
+
+ if (thread == NULL) {
+ pr_debug("problem processing %d event, skipping it.\n",
+ event->header.type);
+ return -1;
+ }
+
+ process_raw_event(thread, sample->raw_data, sample->time);
+
+ return 0;
+}
+
+static struct perf_tool eops = {
+ .sample = process_sample_event,
+ .comm = perf_event__process_comm,
+ .ordered_samples = true,
+};
+
+static char const *input_name = "perf.data";
+
+static int get_cpu_isa(struct perf_session *session)
+{
+ char *cpuid;
+ int isa;
+
+ cpuid = perf_header__read_feature(session, HEADER_CPUID);
+
+ if (!cpuid)
+ die("read HEADER_CPUID failed.\n");
+
+ if (strstr(cpuid, "Intel"))
+ isa = 1;
+ else if (strstr(cpuid, "AMD"))
+ isa = 0;
+ else
+ die("CPU %s is not supported.\n", cpuid);
+
+ free(cpuid);
+ return isa;
+}
+
+static int read_events(void)
+{
+ struct perf_session *session;
+
+ session = perf_session__new(input_name, O_RDONLY, 0, false, &eops);
+ if (!session)
+ die("Initializing perf session failed\n");
+
+ if (!perf_session__has_traces(session, "kvm record"))
+ return -1;
+
+ /*
+ * Do not use 'isa' recorded in kvm_exit tracepoint since it is not
+ * traced in the old kernel.
+ */
+ cpu_isa = get_cpu_isa(session);
+
+ return perf_session__process_events(session, &eops);
+}
+
+static void verify_vcpu(int vcpu)
+{
+ if (vcpu != -1 && vcpu < 0)
+ die("Invalid vcpu:%d.\n", vcpu);
+}
+
+static int kvm_events_report(int vcpu)
+{
+ init_kvm_event_record();
+ verify_vcpu(vcpu);
+ select_key();
+ register_kvm_events_ops();
+ setup_pager();
+
+ read_events();
+
+ sort_result(vcpu);
+ print_result(vcpu);
+ return 0;
+}
+
+static const char * const record_args[] = {
+ "record",
+ "-a",
+ "-R",
+ "-f",
+ "-m", "1024",
+ "-c", "1",
+ "-e", "kvm:kvm_entry",
+ "-e", "kvm:kvm_exit",
+ "-e", "kvm:kvm_mmio",
+ "-e", "kvm:kvm_pio",
+};
+
+static const char * const new_event[] = {
+ "kvm_mmio_begin",
+ "kvm_mmio_done"
+};
+
+static bool kvm_events_exist(const char *event)
+{
+ char evt_path[MAXPATHLEN];
+ int fd;
+
+ snprintf(evt_path, MAXPATHLEN, "%s/kvm/%s/id", tracing_events_path,
+ event);
+
+ fd = open(evt_path, O_RDONLY);
+
+ if (fd < 0)
+ return false;
+
+ close(fd);
+
+ return true;
+}
+
+static int kvm_events_record(int argc, const char **argv)
+{
+ unsigned int rec_argc, i, j;
+ const char **rec_argv;
+
+ rec_argc = ARRAY_SIZE(record_args) + argc - 1;
+ rec_argc += ARRAY_SIZE(new_event) * 2;
+ rec_argv = calloc(rec_argc + 1, sizeof(char *));
+
+ if (rec_argv == NULL)
+ return -ENOMEM;
+
+ for (i = 0; i < ARRAY_SIZE(record_args); i++)
+ rec_argv[i] = strdup(record_args[i]);
+
+ for (j = 0; j < ARRAY_SIZE(new_event); j++)
+ if (kvm_events_exist(new_event[j])) {
+ char event[256];
+
+ sprintf(event, "kvm:%s", new_event[j]);
+
+ rec_argv[i++] = strdup("-e");
+ rec_argv[i++] = strdup(event);
+ }
+
+ for (j = 1; j < (unsigned int)argc; j++, i++)
+ rec_argv[i] = argv[j];
+
+ return cmd_record(i, rec_argv, NULL);
+}
+
+static const char * const kvm_events_report_usage[] = {
+ "perf kvm events report [<options>]",
+ NULL
+};
+
+static const struct option kvm_events_report_options[] = {
+ OPT_STRING(0, "event", &report_event, "reprot event",
+ "event for reporting: vmexit, mmio, ioport"),
+ OPT_INTEGER(0, "vcpu", &trace_vcpu,
+ "vcpu id to report"),
+ OPT_STRING('k', "key", &sort_key, "sort-key",
+ "key for sorting: sample(sort by samples number)"
+ " time (sort by avg time)"),
+ OPT_END()
+};
+
+static const char * const kvm_events_usage[] = {
+ "perf kvm events [<options>] {record|report}",
+ NULL
+};
+
+static const struct option kvm_events_options[] = {
+ OPT_STRING('i', "input", &input_name, "file", "input file name"),
+ OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
+ "dump raw trace in ASCII"),
+ OPT_END()
+};
+
+int cmd_kvm_events(int argc, const char **argv, const char *prefix __used)
+{
+ argc = parse_options(argc, argv, kvm_events_options, kvm_events_usage,
+ PARSE_OPT_STOP_AT_NON_OPTION);
+ if (!argc)
+ usage_with_options(kvm_events_usage, kvm_events_options);
+
+ symbol__init();
+
+ if (!strncmp(argv[0], "rec", 3))
+ return kvm_events_record(argc, argv);
+
+ if (!strncmp(argv[0], "rep", 3)) {
+ if (argc) {
+ argc = parse_options(argc, argv,
+ kvm_events_report_options,
+ kvm_events_report_usage, 0);
+ if (argc)
+ usage_with_options(kvm_events_report_usage,
+ kvm_events_report_options);
+ }
+ return kvm_events_report(trace_vcpu);
+ }
+
+ usage_with_options(kvm_events_usage, kvm_events_options);
+ return 0;
+}
diff --git a/tools/perf/builtin.h b/tools/perf/builtin.h
index b382bd5..fb19e3d 100644
--- a/tools/perf/builtin.h
+++ b/tools/perf/builtin.h
@@ -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);

diff --git a/tools/perf/command-list.txt b/tools/perf/command-list.txt
index d695fe4..c5e97d8 100644
--- a/tools/perf/command-list.txt
+++ b/tools/perf/command-list.txt
@@ -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
diff --git a/tools/perf/perf.c b/tools/perf/perf.c
index 2b2e225..ab85ea5 100644
--- a/tools/perf/perf.c
+++ b/tools/perf/perf.c
@@ -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 },
};
diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index 3e7e0b0..73f2a6f 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -1305,9 +1305,15 @@ static void print_cpuid(struct perf_header *ph, int fd, FILE *fp)
free(str);
}

+static char *read_cpuid(struct perf_header *ph, int fd)
+{
+ return do_read_string(fd, ph);
+}
+
struct feature_ops {
int (*write)(int fd, struct perf_header *h, struct perf_evlist *evlist);
void (*print)(struct perf_header *h, int fd, FILE *fp);
+ char *(*read)(struct perf_header *h, int fd);
const char *name;
bool full_only;
};
@@ -1316,6 +1322,8 @@ struct feature_ops {
[n] = { .name = #n, .write = write_##func, .print = print_##func }
#define FEAT_OPF(n, func) \
[n] = { .name = #n, .write = write_##func, .print = print_##func, .full_only = true }
+#define FEAT_OPA_R(n, func) \
+ [n] = { .name = #n, .write = write_##func, .print = print_##func, .read = read_##func }

/* feature_ops not implemented: */
#define print_trace_info NULL
@@ -1330,7 +1338,7 @@ static const struct feature_ops feat_ops[HEADER_LAST_FEATURE] = {
FEAT_OPA(HEADER_ARCH, arch),
FEAT_OPA(HEADER_NRCPUS, nrcpus),
FEAT_OPA(HEADER_CPUDESC, cpudesc),
- FEAT_OPA(HEADER_CPUID, cpuid),
+ FEAT_OPA_R(HEADER_CPUID, cpuid),
FEAT_OPA(HEADER_TOTAL_MEM, total_mem),
FEAT_OPA(HEADER_EVENT_DESC, event_desc),
FEAT_OPA(HEADER_CMDLINE, cmdline),
@@ -1383,6 +1391,50 @@ int perf_header__fprintf_info(struct perf_session *session, FILE *fp, bool full)
return 0;
}

+struct header_read_data {
+ int feat;
+ char *result;
+};
+
+static int perf_file_section__read_feature(struct perf_file_section *section,
+ struct perf_header *ph,
+ int feat, int fd, void *data)
+{
+ struct header_read_data *hd = data;
+
+ if (feat != hd->feat)
+ return 0;
+
+ if (lseek(fd, section->offset, SEEK_SET) == (off_t)-1) {
+ pr_debug("Failed to lseek to %" PRIu64 " offset for feature "
+ "%d, continuing...\n", section->offset, feat);
+ return 0;
+ }
+
+ if (feat >= HEADER_LAST_FEATURE) {
+ pr_warning("unknown feature %d\n", feat);
+ return 0;
+ }
+
+ hd->result = feat_ops[feat].read(ph, fd);
+ return 0;
+}
+
+char *perf_header__read_feature(struct perf_session *session, int feat)
+{
+ struct perf_header *header = &session->header;
+ struct header_read_data hd;
+ int fd = session->fd;
+
+ hd.feat = feat;
+ hd.result = NULL;
+
+
+ perf_header__process_sections(header, fd, &hd,
+ perf_file_section__read_feature);
+ return hd.result;
+}
+
static int do_write_feat(int fd, struct perf_header *h, int type,
struct perf_file_section **p,
struct perf_evlist *evlist)
diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
index ac4ec95..41ddfad 100644
--- a/tools/perf/util/header.h
+++ b/tools/perf/util/header.h
@@ -92,6 +92,7 @@ int perf_header__process_sections(struct perf_header *header, int fd,
int feat, int fd, void *data));

int perf_header__fprintf_info(struct perf_session *s, FILE *fp, bool full);
+char *perf_header__read_feature(struct perf_session *session, int feat);

int build_id_cache__add_s(const char *sbuild_id, const char *debugdir,
const char *name, bool is_kallsyms);
diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
index 70c2c13..c48ebf3 100644
--- a/tools/perf/util/thread.h
+++ b/tools/perf/util/thread.h
@@ -16,6 +16,8 @@ struct thread {
bool comm_set;
char *comm;
int comm_len;
+
+ void *private;
};

struct machine;

2012-02-13 03:04:13

by David Ahern

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

Compile fails on Fedora 16, x86_64 with latest tip-perf-core branch:


In file included from builtin-kvm-events.c:19:0:
../../arch/x86/include/asm/svm.h:133:1: error: packed attribute is
unnecessary for ‘vmcb_seg’ [-Werror=packed]
../../arch/x86/include/asm/svm.h:178:1: error: packed attribute is
unnecessary for ‘vmcb_save_area’ [-Werror=packed]
../../arch/x86/include/asm/svm.h:183:1: error: packed attribute is
unnecessary for ‘vmcb’ [-Werror=packed]
In file included from builtin-kvm-events.c:20:0:
../../arch/x86/include/asm/vmx.h:334:0: error: "REG_R8" redefined [-Werror]
/usr/include/sys/ucontext.h:46:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:335:0: error: "REG_R9" redefined [-Werror]
/usr/include/sys/ucontext.h:48:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:336:0: error: "REG_R10" redefined [-Werror]
/usr/include/sys/ucontext.h:50:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:337:0: error: "REG_R11" redefined [-Werror]
/usr/include/sys/ucontext.h:52:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:338:0: error: "REG_R12" redefined [-Werror]
/usr/include/sys/ucontext.h:54:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:339:0: error: "REG_R13" redefined [-Werror]
/usr/include/sys/ucontext.h:56:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:340:0: error: "REG_R14" redefined [-Werror]
/usr/include/sys/ucontext.h:58:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:341:0: error: "REG_R15" redefined [-Werror]
/usr/include/sys/ucontext.h:60:0: note: this is the location of the
previous definition
../../arch/x86/include/asm/vmx.h:443:13: error: expected declaration
specifiers or ‘...’ before numeric constant
In file included from builtin-kvm-events.c:21:0:
../../arch/x86/include/asm/kvm_host.h:15:22: fatal error: linux/mm.h: No
such file or directory
cc1: all warnings being treated as errors


On 02/09/2012 02:09 AM, Xiao Guangrong wrote:
> 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
>
> Signed-off-by: Xiao Guangrong <[email protected]>
> ---
> tools/perf/Documentation/perf-kvm-events.txt | 52 ++
> tools/perf/Makefile | 1 +
> tools/perf/builtin-kvm-events.c | 851 ++++++++++++++++++++++++++
> tools/perf/builtin.h | 1 +
> tools/perf/command-list.txt | 1 +
> tools/perf/perf.c | 1 +
> tools/perf/util/header.c | 54 ++-
> tools/perf/util/header.h | 1 +
> tools/perf/util/thread.h | 2 +
> 9 files changed, 963 insertions(+), 1 deletions(-)
> create mode 100644 tools/perf/Documentation/perf-kvm-events.txt
> create mode 100644 tools/perf/builtin-kvm-events.c
>
> diff --git a/tools/perf/Documentation/perf-kvm-events.txt b/tools/perf/Documentation/perf-kvm-events.txt
> new file mode 100644
> index 0000000..ed36550
> --- /dev/null
> +++ b/tools/perf/Documentation/perf-kvm-events.txt
> @@ -0,0 +1,52 @@
> +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)
> +
> +-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]
> diff --git a/tools/perf/Makefile b/tools/perf/Makefile
> index ac86d67..ee43451 100644
> --- a/tools/perf/Makefile
> +++ b/tools/perf/Makefile
> @@ -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
>
> diff --git a/tools/perf/builtin-kvm-events.c b/tools/perf/builtin-kvm-events.c
> new file mode 100644
> index 0000000..9903d2b
> --- /dev/null
> +++ b/tools/perf/builtin-kvm-events.c
> @@ -0,0 +1,851 @@
> +#include "builtin.h"
> +#include "perf.h"
> +#include "util/util.h"
> +#include "util/cache.h"
> +#include "util/symbol.h"
> +#include "util/thread.h"
> +#include "util/header.h"
> +#include "util/parse-options.h"
> +#include "util/trace-event.h"
> +#include "util/debug.h"
> +#include "util/debugfs.h"
> +#include "util/session.h"
> +#include "util/tool.h"
> +
> +#include <math.h>
> +
> +#include <linux/kvm.h>
> +
> +#include "../../arch/x86/include/asm/svm.h"
> +#include "../../arch/x86/include/asm/vmx.h"
> +#include "../../arch/x86/include/asm/kvm_host.h"
> +
> +struct event_key {
> + #define INVALID_KEY (~0ULL)
> + u64 key;
> + int info;
> +};
> +
> +struct kvm_events_ops {
> + bool (*is_begin_event)(struct event *event, void *data,
> + struct event_key *key);
> + bool (*is_end_event)(struct event *event, void *data,
> + struct event_key *key);
> + void (*decode_key)(struct event_key *key, char decode[20]);
> + const char *name;
> +};
> +
> +static int cpu_isa;
> +
> +static void exit_event_get_key(struct event *event, void *data,
> + struct event_key *key)
> +{
> + key->info = cpu_isa;
> + key->key = raw_field_value(event, "exit_reason", data);
> +}
> +
> +static bool kvm_exit_event(struct event *event)
> +{
> + return !strcmp(event->name, "kvm_exit");
> +}
> +
> +static bool exit_event_begin(struct event *event, void *data,
> + struct event_key *key)
> +{
> + if (kvm_exit_event(event)) {
> + exit_event_get_key(event, data, key);
> + return true;
> + }
> +
> + return false;
> +}
> +
> +static bool kvm_entry_event(struct event *event)
> +{
> + return !strcmp(event->name, "kvm_entry");
> +}
> +
> +static bool exit_event_end(struct event *event, void *data __unused,
> + struct event_key *key __unused)
> +{
> + return kvm_entry_event(event);
> +}
> +
> +struct exit_reasons_table {
> + unsigned long exit_code;
> + const char *reason;
> +};
> +
> +struct exit_reasons_table vmx_exit_reasons[] = {
> + VMX_EXIT_REASONS
> +};
> +
> +struct exit_reasons_table svm_exit_reasons[] = {
> + SVM_EXIT_REASONS
> +};
> +
> +static const char *get_exit_reason(u64 exit_code, int isa)
> +{
> + int table_size = ARRAY_SIZE(svm_exit_reasons);
> + struct exit_reasons_table *table = svm_exit_reasons;
> +
> + if (isa == 1) {
> + table = vmx_exit_reasons;
> + table_size = ARRAY_SIZE(vmx_exit_reasons);
> + }
> +
> + while (table_size--) {
> + if (table->exit_code == exit_code)
> + return table->reason;
> + table++;
> + }
> +
> + die("unknown kvm exit code:%ld on %s\n", exit_code,
> + isa ? "VMX" : "SVM");
> +}
> +
> +static void exit_event_decode_key(struct event_key *key, char decode[20])
> +{
> + const char *exit_reason = get_exit_reason(key->key, key->info);
> +
> + snprintf(decode, 20, "%s", exit_reason);
> +}
> +
> +static struct kvm_events_ops exit_events = {
> + .is_begin_event = exit_event_begin,
> + .is_end_event = exit_event_end,
> + .decode_key = exit_event_decode_key,
> + .name = "VM-EXIT"
> +};
> +
> +/*
> + * For the old kernel, we treat:
> + * the time of MMIO write: kvm_mmio(KVM_TRACE_MMIO_WRITE...) -> kvm_entry
> + * the time of MMIO read: kvm_exit -> kvm_mmio(KVM_TRACE_MMIO_READ...).
> + *
> + * For the new kernel, we use kvm_mmio_begin and kvm_mmio_done to make
> + * things better.
> + */
> +static void mmio_event_get_key(struct event *event, void *data,
> + struct event_key *key)
> +{
> + key->key = raw_field_value(event, "gpa", data);
> + key->info = raw_field_value(event, "type", data);
> +}
> +
> +#define KVM_TRACE_MMIO_READ_UNSATISFIED 0
> +#define KVM_TRACE_MMIO_READ 1
> +#define KVM_TRACE_MMIO_WRITE 2
> +
> +static bool kvm_mmio_done_event(struct event *event)
> +{
> + return !strcmp(event->name, "kvm_mmio_done");
> +}
> +
> +static bool mmio_event_begin(struct event *event, void *data,
> + struct event_key *key)
> +{
> + /* MMIO read begin in old kernel. */
> + if (kvm_exit_event(event))
> + return true;
> +
> + /* MMIO write begin in old kernel. */
> + if (!strcmp(event->name, "kvm_mmio") &&
> + raw_field_value(event, "type", data) == KVM_TRACE_MMIO_WRITE) {
> + mmio_event_get_key(event, data, key);
> + return true;
> + }
> +
> + /* MMIO read/write begin in new kernel. */
> + if (!strcmp(event->name, "kvm_mmio_begin")) {
> + mmio_event_get_key(event, data, key);
> + return true;
> + }
> +
> + return false;
> +}
> +
> +static bool mmio_event_end(struct event *event, void *data,
> + struct event_key *key)
> +{
> + /* MMIO write end in old kernel. */
> + if (kvm_entry_event(event))
> + return true;
> +
> + /* MMIO read end in the old kernel.*/
> + if (!strcmp(event->name, "kvm_mmio") &&
> + raw_field_value(event, "type", data) == KVM_TRACE_MMIO_READ) {
> + mmio_event_get_key(event, data, key);
> + return true;
> + }
> +
> + /* MMIO read/write end event in the new kernel.*/
> + return kvm_mmio_done_event(event);
> +}
> +
> +static void mmio_event_decode_key(struct event_key *key, char decode[20])
> +{
> + snprintf(decode, 20, "%#lx:%s", key->key,
> + key->info == KVM_TRACE_MMIO_WRITE ? "W" : "R");
> +}
> +
> +static struct kvm_events_ops mmio_events = {
> + .is_begin_event = mmio_event_begin,
> + .is_end_event = mmio_event_end,
> + .decode_key = mmio_event_decode_key,
> + .name = "MMIO Access"
> +};
> +
> +/*
> + * For the old kernel, the time of emulation pio access is from kvm_pio to
> + * kvm_entry. In the new kernel, the end time is indicated by kvm_mmio_done.
> + */
> +static void ioport_event_get_key(struct event *event, void *data,
> + struct event_key *key)
> +{
> + key->key = raw_field_value(event, "port", data);
> + key->info = raw_field_value(event, "rw", data);
> +}
> +
> +static bool ioport_event_begin(struct event *event, void *data,
> + struct event_key *key)
> +{
> + if (!strcmp(event->name, "kvm_pio")) {
> + ioport_event_get_key(event, data, key);
> + return true;
> + }
> +
> + return false;
> +}
> +
> +static bool ioport_event_end(struct event *event, void *data __unused,
> + struct event_key *key __unused)
> +{
> + if (kvm_entry_event(event))
> + return true;
> +
> + return kvm_mmio_done_event(event);
> +}
> +
> +static void ioport_event_decode_key(struct event_key *key, char decode[20])
> +{
> + snprintf(decode, 20, "%#lx:%s", key->key, key->info ? "POUT" : "PIN");
> +}
> +
> +static struct kvm_events_ops ioport_events = {
> + .is_begin_event = ioport_event_begin,
> + .is_end_event = ioport_event_end,
> + .decode_key = ioport_event_decode_key,
> + .name = "IO Port Access"
> +};
> +
> +static const char *report_event = "vmexit";
> +struct kvm_events_ops *events_ops;
> +
> +static void register_kvm_events_ops(void)
> +{
> + if (!strcmp(report_event, "vmexit"))
> + events_ops = &exit_events;
> + else if (!strcmp(report_event, "mmio"))
> + events_ops = &mmio_events;
> + else if (!strcmp(report_event, "ioport"))
> + events_ops = &ioport_events;
> + else
> + die("Unknown report event:%s\n", report_event);
> +}
> +
> +struct event_stats {
> + u64 count;
> + u64 time;
> +
> + /* used to calculate stddev. */
> + double mean;
> + double M2;
> +};
> +
> +struct kvm_event {
> + struct list_head hash_entry;
> + struct rb_node rb;
> +
> + struct event_key key;
> +
> + struct event_stats total;
> +
> + #define DEFAULT_VCPU_NUM 32
> + int max_vcpu;
> + struct event_stats *vcpu;
> +};
> +
> +struct vcpu_event_record {
> + int vcpu_id;
> + u64 start_time;
> + struct kvm_event *last_event;
> +};
> +
> +#define EVENTS_BITS 12
> +#define EVENTS_CACHE_SIZE (1UL << EVENTS_BITS)
> +
> +static u64 total_time;
> +static u64 total_count;
> +static struct list_head kvm_events_cache[EVENTS_CACHE_SIZE];
> +
> +static void init_kvm_event_record(void)
> +{
> + int i;
> +
> + for (i = 0; i < (int)EVENTS_CACHE_SIZE; i++)
> + INIT_LIST_HEAD(&kvm_events_cache[i]);
> +}
> +
> +static int kvm_events_hash_fn(u64 key)
> +{
> + return key & (EVENTS_CACHE_SIZE - 1);
> +}
> +
> +static void kvm_event_expand(struct kvm_event *event, int vcpu_id)
> +{
> + int old_max_vcpu = event->max_vcpu;
> +
> + if (vcpu_id < event->max_vcpu)
> + return;
> +
> + while (event->max_vcpu <= vcpu_id)
> + event->max_vcpu += DEFAULT_VCPU_NUM;
> +
> + event->vcpu = realloc(event->vcpu,
> + event->max_vcpu * sizeof(*event->vcpu));
> + if (!event->vcpu)
> + die("Not enough memory\n");
> +
> + memset(event->vcpu + old_max_vcpu, 0,
> + (event->max_vcpu - old_max_vcpu) * sizeof(*event->vcpu));
> +}
> +
> +static struct kvm_event *kvm_alloc_init_event(struct event_key *key)
> +{
> + struct kvm_event *event;
> +
> + event = zalloc(sizeof(*event));
> + if (!event)
> + die("Not enough memory\n");
> +
> + event->key = *key;
> + return event;
> +}
> +
> +static struct kvm_event *find_create_kvm_event(struct event_key *key)
> +{
> + struct kvm_event *event;
> + struct list_head *head;
> +
> + BUG_ON(key->key == INVALID_KEY);
> +
> + head = &kvm_events_cache[kvm_events_hash_fn(key->key)];
> + list_for_each_entry(event, head, hash_entry)
> + if (event->key.key == key->key && event->key.info == key->info)
> + return event;
> +
> + event = kvm_alloc_init_event(key);
> + list_add(&event->hash_entry, head);
> + return event;
> +}
> +
> +static void handle_begin_event(struct vcpu_event_record *vcpu_record,
> + struct event_key *key, u64 timestamp)
> +{
> + struct kvm_event *event = NULL;
> +
> + if (key->key != INVALID_KEY)
> + event = find_create_kvm_event(key);
> +
> + vcpu_record->last_event = event;
> + vcpu_record->start_time = timestamp;
> +}
> +
> +static void update_event_stats(struct event_stats *stats, u64 time_diff)
> +{
> + double delta;
> +
> + stats->count++;
> + stats->time += time_diff;
> +
> + delta = time_diff - stats->mean;
> + stats->mean += delta / stats->count;
> + stats->M2 += delta*(time_diff - stats->mean);
> +}
> +
> +static double event_stats_stddev(int vcpu_id, struct kvm_event *event)
> +{
> + struct event_stats *stats = &event->total;
> + double variance, variance_mean, stddev;
> +
> + if (vcpu_id != -1)
> + stats = &event->vcpu[vcpu_id];
> +
> + BUG_ON(!stats->count);
> +
> + variance = stats->M2 / (stats->count - 1);
> + variance_mean = variance / stats->count;
> + stddev = sqrt(variance_mean);
> +
> + return stddev * 100 / stats->mean;
> +}
> +
> +static void update_kvm_event(struct kvm_event *event, int vcpu_id,
> + u64 time_diff)
> +{
> + update_event_stats(&event->total, time_diff);
> + kvm_event_expand(event, vcpu_id);
> + update_event_stats(&event->vcpu[vcpu_id], time_diff);
> +}
> +
> +static void handle_end_event(struct vcpu_event_record *vcpu_record,
> + struct event_key *key, u64 timestamp)
> +{
> + struct kvm_event *event;
> + u64 time_begin, time_diff;
> +
> + event = vcpu_record->last_event;
> + time_begin = vcpu_record->start_time;
> +
> + /* The begin event is not caught. */
> + if (!time_begin)
> + return;
> +
> + /* Both begin and end events did not get the key. */
> + if (!event && key->key == INVALID_KEY)
> + return;
> +
> + if (!event)
> + event = find_create_kvm_event(key);
> +
> + vcpu_record->last_event = NULL;
> + vcpu_record->start_time = 0;
> +
> + BUG_ON(timestamp < time_begin);
> +
> + time_diff = timestamp - time_begin;
> + update_kvm_event(event, vcpu_record->vcpu_id, time_diff);
> +}
> +
> +static struct vcpu_event_record
> +*per_vcpu_record(struct thread *thread, struct event *event, void *data)
> +{
> + /* Only kvm_entry records vcpu id. */
> + if (!thread->private && kvm_entry_event(event)) {
> + struct vcpu_event_record *vcpu_record;
> +
> + vcpu_record = zalloc(sizeof(struct vcpu_event_record));
> + if (!vcpu_record)
> + die("Not enough memory\n");
> +
> + vcpu_record->vcpu_id = raw_field_value(event, "vcpu_id", data);
> + thread->private = vcpu_record;
> + }
> +
> + return (struct vcpu_event_record *)thread->private;
> +}
> +
> +static void handle_kvm_event(struct thread *thread, struct event *event,
> + void *data, u64 timestamp)
> +{
> + struct vcpu_event_record *vcpu_record;
> + struct event_key key = {.key = INVALID_KEY};
> +
> + vcpu_record = per_vcpu_record(thread, event, data);
> + if (!vcpu_record)
> + return;
> +
> + if (events_ops->is_begin_event(event, data, &key))
> + return handle_begin_event(vcpu_record, &key, timestamp);
> +
> + if (events_ops->is_end_event(event, data, &key))
> + return handle_end_event(vcpu_record, &key, timestamp);
> +}
> +
> +typedef int (*key_cmp_fun)(struct kvm_event*, struct kvm_event*, int);
> +struct kvm_event_key {
> + const char *name;
> + key_cmp_fun key;
> +};
> +
> +static int trace_vcpu = -1;
> +#define GET_EVENT_KEY(member) \
> +static u64 get_event_ ##member(struct kvm_event *event, int vcpu) \
> +{ \
> + if (vcpu == -1) \
> + return event->total.member; \
> + \
> + if (vcpu >= event->max_vcpu) \
> + return 0; \
> + \
> + return event->vcpu[vcpu].member; \
> +}
> +
> +#define COMPARE_EVENT_KEY(member) \
> +GET_EVENT_KEY(member) \
> +static int compare_kvm_event_ ## member(struct kvm_event *one, \
> + struct kvm_event *two, int vcpu)\
> +{ \
> + return get_event_ ##member(one, vcpu) > \
> + get_event_ ##member(two, vcpu); \
> +}
> +
> +GET_EVENT_KEY(time);
> +COMPARE_EVENT_KEY(count);
> +COMPARE_EVENT_KEY(mean);
> +
> +#define DEF_SORT_NAME_KEY(name, compare_key) \
> + { #name, compare_kvm_event_ ## compare_key }
> +
> +static struct kvm_event_key keys[] = {
> + DEF_SORT_NAME_KEY(sample, count),
> + DEF_SORT_NAME_KEY(time, mean),
> + { NULL, NULL }
> +};
> +
> +static const char *sort_key = "sample";
> +static key_cmp_fun compare;
> +
> +static void select_key(void)
> +{
> + int i;
> +
> + for (i = 0; keys[i].name; i++) {
> + if (!strcmp(keys[i].name, sort_key)) {
> + compare = keys[i].key;
> + return;
> + }
> + }
> +
> + die("Unknown compare key:%s\n", sort_key);
> +}
> +
> +static struct rb_root result;
> +static void insert_to_result(struct kvm_event *event, key_cmp_fun bigger,
> + int vcpu)
> +{
> + struct rb_node **rb = &result.rb_node;
> + struct rb_node *parent = NULL;
> + struct kvm_event *p;
> +
> + while (*rb) {
> + p = container_of(*rb, struct kvm_event, rb);
> + parent = *rb;
> +
> + if (bigger(event, p, vcpu))
> + rb = &(*rb)->rb_left;
> + else
> + rb = &(*rb)->rb_right;
> + }
> +
> + rb_link_node(&event->rb, parent, rb);
> + rb_insert_color(&event->rb, &result);
> +}
> +
> +static void update_total_count(struct kvm_event *event, int vcpu)
> +{
> + total_count += get_event_count(event, vcpu);
> + total_time += get_event_time(event, vcpu);
> +}
> +
> +static bool event_is_valid(struct kvm_event *event, int vcpu)
> +{
> + return get_event_count(event, vcpu);
> +}
> +
> +static void sort_result(int vcpu)
> +{
> + unsigned int i;
> + struct kvm_event *event;
> +
> + for (i = 0; i < EVENTS_CACHE_SIZE; i++)
> + list_for_each_entry(event, &kvm_events_cache[i], hash_entry)
> + if (event_is_valid(event, vcpu)) {
> + update_total_count(event, vcpu);
> + insert_to_result(event, compare, vcpu);
> + }
> +}
> +
> +/* returns left most element of result, and erase it */
> +static struct kvm_event *pop_from_result(void)
> +{
> + struct rb_node *node = result.rb_node;
> +
> + if (!node)
> + return NULL;
> +
> + while (node->rb_left)
> + node = node->rb_left;
> +
> + rb_erase(node, &result);
> + return container_of(node, struct kvm_event, rb);
> +}
> +
> +static void print_vcpu_info(int vcpu)
> +{
> + pr_info("Analyze events for ");
> +
> + if (vcpu == -1)
> + pr_info("all VCPUs:\n\n");
> + else
> + pr_info("VCPU %d:\n\n", vcpu);
> +}
> +
> +static void print_result(int vcpu)
> +{
> + char decode[20];
> + struct kvm_event *event;
> +
> + pr_info("\n\n");
> + print_vcpu_info(vcpu);
> + pr_info("%20s ", events_ops->name);
> + pr_info("%10s ", "Samples");
> + pr_info("%9s ", "Samples%");
> +
> + pr_info("%9s ", "Time%");
> + pr_info("%16s ", "Avg time");
> + pr_info("\n\n");
> +
> + while ((event = pop_from_result())) {
> + u64 ecount, etime;
> +
> + ecount = get_event_count(event, vcpu);
> + etime = get_event_time(event, vcpu);
> +
> + events_ops->decode_key(&event->key, decode);
> + pr_info("%20s ", decode);
> + pr_info("%10lu ", ecount);
> + pr_info("%8.2f%% ", (double)ecount / total_count * 100);
> + pr_info("%8.2f%% ", (double)etime / total_time * 100);
> + pr_info("%9.2fus ( +-%7.2f%% )", (double)etime / ecount/1e3,
> + event_stats_stddev(trace_vcpu, event));
> + pr_info("\n");
> + }
> +
> + pr_info("\nTotal Samples:%ld, Total events handled time:%.2fus.\n\n",
> + total_count, total_time / 1e3);
> +}
> +
> +static void process_raw_event(struct thread *thread, void *data, u64 timestamp)
> +{
> + struct event *event;
> + int type;
> +
> + type = trace_parse_common_type(data);
> + event = trace_find_event(type);
> +
> + return handle_kvm_event(thread, event, data, timestamp);
> +}
> +
> +static int process_sample_event(struct perf_tool *tool __used,
> + union perf_event *event,
> + struct perf_sample *sample,
> + struct perf_evsel *evsel __used,
> + struct machine *machine)
> +{
> + struct thread *thread = machine__findnew_thread(machine, sample->tid);
> +
> + if (thread == NULL) {
> + pr_debug("problem processing %d event, skipping it.\n",
> + event->header.type);
> + return -1;
> + }
> +
> + process_raw_event(thread, sample->raw_data, sample->time);
> +
> + return 0;
> +}
> +
> +static struct perf_tool eops = {
> + .sample = process_sample_event,
> + .comm = perf_event__process_comm,
> + .ordered_samples = true,
> +};
> +
> +static char const *input_name = "perf.data";
> +
> +static int get_cpu_isa(struct perf_session *session)
> +{
> + char *cpuid;
> + int isa;
> +
> + cpuid = perf_header__read_feature(session, HEADER_CPUID);
> +
> + if (!cpuid)
> + die("read HEADER_CPUID failed.\n");
> +
> + if (strstr(cpuid, "Intel"))
> + isa = 1;
> + else if (strstr(cpuid, "AMD"))
> + isa = 0;
> + else
> + die("CPU %s is not supported.\n", cpuid);
> +
> + free(cpuid);
> + return isa;
> +}
> +
> +static int read_events(void)
> +{
> + struct perf_session *session;
> +
> + session = perf_session__new(input_name, O_RDONLY, 0, false, &eops);
> + if (!session)
> + die("Initializing perf session failed\n");
> +
> + if (!perf_session__has_traces(session, "kvm record"))
> + return -1;
> +
> + /*
> + * Do not use 'isa' recorded in kvm_exit tracepoint since it is not
> + * traced in the old kernel.
> + */
> + cpu_isa = get_cpu_isa(session);
> +
> + return perf_session__process_events(session, &eops);
> +}
> +
> +static void verify_vcpu(int vcpu)
> +{
> + if (vcpu != -1 && vcpu < 0)
> + die("Invalid vcpu:%d.\n", vcpu);
> +}
> +
> +static int kvm_events_report(int vcpu)
> +{
> + init_kvm_event_record();
> + verify_vcpu(vcpu);
> + select_key();
> + register_kvm_events_ops();
> + setup_pager();
> +
> + read_events();
> +
> + sort_result(vcpu);
> + print_result(vcpu);
> + return 0;
> +}
> +
> +static const char * const record_args[] = {
> + "record",
> + "-a",
> + "-R",
> + "-f",
> + "-m", "1024",
> + "-c", "1",
> + "-e", "kvm:kvm_entry",
> + "-e", "kvm:kvm_exit",
> + "-e", "kvm:kvm_mmio",
> + "-e", "kvm:kvm_pio",
> +};
> +
> +static const char * const new_event[] = {
> + "kvm_mmio_begin",
> + "kvm_mmio_done"
> +};
> +
> +static bool kvm_events_exist(const char *event)
> +{
> + char evt_path[MAXPATHLEN];
> + int fd;
> +
> + snprintf(evt_path, MAXPATHLEN, "%s/kvm/%s/id", tracing_events_path,
> + event);
> +
> + fd = open(evt_path, O_RDONLY);
> +
> + if (fd < 0)
> + return false;
> +
> + close(fd);
> +
> + return true;
> +}
> +
> +static int kvm_events_record(int argc, const char **argv)
> +{
> + unsigned int rec_argc, i, j;
> + const char **rec_argv;
> +
> + rec_argc = ARRAY_SIZE(record_args) + argc - 1;
> + rec_argc += ARRAY_SIZE(new_event) * 2;
> + rec_argv = calloc(rec_argc + 1, sizeof(char *));
> +
> + if (rec_argv == NULL)
> + return -ENOMEM;
> +
> + for (i = 0; i < ARRAY_SIZE(record_args); i++)
> + rec_argv[i] = strdup(record_args[i]);
> +
> + for (j = 0; j < ARRAY_SIZE(new_event); j++)
> + if (kvm_events_exist(new_event[j])) {
> + char event[256];
> +
> + sprintf(event, "kvm:%s", new_event[j]);
> +
> + rec_argv[i++] = strdup("-e");
> + rec_argv[i++] = strdup(event);
> + }
> +
> + for (j = 1; j < (unsigned int)argc; j++, i++)
> + rec_argv[i] = argv[j];
> +
> + return cmd_record(i, rec_argv, NULL);
> +}
> +
> +static const char * const kvm_events_report_usage[] = {
> + "perf kvm events report [<options>]",
> + NULL
> +};
> +
> +static const struct option kvm_events_report_options[] = {
> + OPT_STRING(0, "event", &report_event, "reprot event",
> + "event for reporting: vmexit, mmio, ioport"),
> + OPT_INTEGER(0, "vcpu", &trace_vcpu,
> + "vcpu id to report"),
> + OPT_STRING('k', "key", &sort_key, "sort-key",
> + "key for sorting: sample(sort by samples number)"
> + " time (sort by avg time)"),
> + OPT_END()
> +};
> +
> +static const char * const kvm_events_usage[] = {
> + "perf kvm events [<options>] {record|report}",
> + NULL
> +};
> +
> +static const struct option kvm_events_options[] = {
> + OPT_STRING('i', "input", &input_name, "file", "input file name"),
> + OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
> + "dump raw trace in ASCII"),
> + OPT_END()
> +};
> +
> +int cmd_kvm_events(int argc, const char **argv, const char *prefix __used)
> +{
> + argc = parse_options(argc, argv, kvm_events_options, kvm_events_usage,
> + PARSE_OPT_STOP_AT_NON_OPTION);
> + if (!argc)
> + usage_with_options(kvm_events_usage, kvm_events_options);
> +
> + symbol__init();
> +
> + if (!strncmp(argv[0], "rec", 3))
> + return kvm_events_record(argc, argv);
> +
> + if (!strncmp(argv[0], "rep", 3)) {
> + if (argc) {
> + argc = parse_options(argc, argv,
> + kvm_events_report_options,
> + kvm_events_report_usage, 0);
> + if (argc)
> + usage_with_options(kvm_events_report_usage,
> + kvm_events_report_options);
> + }
> + return kvm_events_report(trace_vcpu);
> + }
> +
> + usage_with_options(kvm_events_usage, kvm_events_options);
> + return 0;
> +}
> diff --git a/tools/perf/builtin.h b/tools/perf/builtin.h
> index b382bd5..fb19e3d 100644
> --- a/tools/perf/builtin.h
> +++ b/tools/perf/builtin.h
> @@ -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);
>
> diff --git a/tools/perf/command-list.txt b/tools/perf/command-list.txt
> index d695fe4..c5e97d8 100644
> --- a/tools/perf/command-list.txt
> +++ b/tools/perf/command-list.txt
> @@ -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
> diff --git a/tools/perf/perf.c b/tools/perf/perf.c
> index 2b2e225..ab85ea5 100644
> --- a/tools/perf/perf.c
> +++ b/tools/perf/perf.c
> @@ -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 },
> };
> diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
> index 3e7e0b0..73f2a6f 100644
> --- a/tools/perf/util/header.c
> +++ b/tools/perf/util/header.c
> @@ -1305,9 +1305,15 @@ static void print_cpuid(struct perf_header *ph, int fd, FILE *fp)
> free(str);
> }
>
> +static char *read_cpuid(struct perf_header *ph, int fd)
> +{
> + return do_read_string(fd, ph);
> +}
> +
> struct feature_ops {
> int (*write)(int fd, struct perf_header *h, struct perf_evlist *evlist);
> void (*print)(struct perf_header *h, int fd, FILE *fp);
> + char *(*read)(struct perf_header *h, int fd);
> const char *name;
> bool full_only;
> };
> @@ -1316,6 +1322,8 @@ struct feature_ops {
> [n] = { .name = #n, .write = write_##func, .print = print_##func }
> #define FEAT_OPF(n, func) \
> [n] = { .name = #n, .write = write_##func, .print = print_##func, .full_only = true }
> +#define FEAT_OPA_R(n, func) \
> + [n] = { .name = #n, .write = write_##func, .print = print_##func, .read = read_##func }
>
> /* feature_ops not implemented: */
> #define print_trace_info NULL
> @@ -1330,7 +1338,7 @@ static const struct feature_ops feat_ops[HEADER_LAST_FEATURE] = {
> FEAT_OPA(HEADER_ARCH, arch),
> FEAT_OPA(HEADER_NRCPUS, nrcpus),
> FEAT_OPA(HEADER_CPUDESC, cpudesc),
> - FEAT_OPA(HEADER_CPUID, cpuid),
> + FEAT_OPA_R(HEADER_CPUID, cpuid),
> FEAT_OPA(HEADER_TOTAL_MEM, total_mem),
> FEAT_OPA(HEADER_EVENT_DESC, event_desc),
> FEAT_OPA(HEADER_CMDLINE, cmdline),
> @@ -1383,6 +1391,50 @@ int perf_header__fprintf_info(struct perf_session *session, FILE *fp, bool full)
> return 0;
> }
>
> +struct header_read_data {
> + int feat;
> + char *result;
> +};
> +
> +static int perf_file_section__read_feature(struct perf_file_section *section,
> + struct perf_header *ph,
> + int feat, int fd, void *data)
> +{
> + struct header_read_data *hd = data;
> +
> + if (feat != hd->feat)
> + return 0;
> +
> + if (lseek(fd, section->offset, SEEK_SET) == (off_t)-1) {
> + pr_debug("Failed to lseek to %" PRIu64 " offset for feature "
> + "%d, continuing...\n", section->offset, feat);
> + return 0;
> + }
> +
> + if (feat >= HEADER_LAST_FEATURE) {
> + pr_warning("unknown feature %d\n", feat);
> + return 0;
> + }
> +
> + hd->result = feat_ops[feat].read(ph, fd);
> + return 0;
> +}
> +
> +char *perf_header__read_feature(struct perf_session *session, int feat)
> +{
> + struct perf_header *header = &session->header;
> + struct header_read_data hd;
> + int fd = session->fd;
> +
> + hd.feat = feat;
> + hd.result = NULL;
> +
> +
> + perf_header__process_sections(header, fd, &hd,
> + perf_file_section__read_feature);
> + return hd.result;
> +}
> +
> static int do_write_feat(int fd, struct perf_header *h, int type,
> struct perf_file_section **p,
> struct perf_evlist *evlist)
> diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
> index ac4ec95..41ddfad 100644
> --- a/tools/perf/util/header.h
> +++ b/tools/perf/util/header.h
> @@ -92,6 +92,7 @@ int perf_header__process_sections(struct perf_header *header, int fd,
> int feat, int fd, void *data));
>
> int perf_header__fprintf_info(struct perf_session *s, FILE *fp, bool full);
> +char *perf_header__read_feature(struct perf_session *session, int feat);
>
> int build_id_cache__add_s(const char *sbuild_id, const char *debugdir,
> const char *name, bool is_kallsyms);
> diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
> index 70c2c13..c48ebf3 100644
> --- a/tools/perf/util/thread.h
> +++ b/tools/perf/util/thread.h
> @@ -16,6 +16,8 @@ struct thread {
> bool comm_set;
> char *comm;
> int comm_len;
> +
> + void *private;
> };
>
> struct machine;
>

2012-02-13 05:00:23

by Xiao Guangrong

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 02/13/2012 11:04 AM, David Ahern wrote:

> Compile fails on Fedora 16, x86_64 with latest tip-perf-core branch:
>
>
> In file included from builtin-kvm-events.c:19:0:
> ../../arch/x86/include/asm/svm.h:133:1: error: packed attribute is
> unnecessary for ‘vmcb_seg’ [-Werror=packed]
> ../../arch/x86/include/asm/svm.h:178:1: error: packed attribute is
> unnecessary for ‘vmcb_save_area’ [-Werror=packed]
> ../../arch/x86/include/asm/svm.h:183:1: error: packed attribute is
> unnecessary for ‘vmcb’ [-Werror=packed]
> In file included from builtin-kvm-events.c:20:0:
> ../../arch/x86/include/asm/vmx.h:334:0: error: "REG_R8" redefined [-Werror]
> /usr/include/sys/ucontext.h:46:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:335:0: error: "REG_R9" redefined [-Werror]
> /usr/include/sys/ucontext.h:48:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:336:0: error: "REG_R10" redefined [-Werror]
> /usr/include/sys/ucontext.h:50:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:337:0: error: "REG_R11" redefined [-Werror]
> /usr/include/sys/ucontext.h:52:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:338:0: error: "REG_R12" redefined [-Werror]
> /usr/include/sys/ucontext.h:54:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:339:0: error: "REG_R13" redefined [-Werror]
> /usr/include/sys/ucontext.h:56:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:340:0: error: "REG_R14" redefined [-Werror]
> /usr/include/sys/ucontext.h:58:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:341:0: error: "REG_R15" redefined [-Werror]
> /usr/include/sys/ucontext.h:60:0: note: this is the location of the
> previous definition
> ../../arch/x86/include/asm/vmx.h:443:13: error: expected declaration
> specifiers or ‘...’ before numeric constant
> In file included from builtin-kvm-events.c:21:0:
> ../../arch/x86/include/asm/kvm_host.h:15:22: fatal error: linux/mm.h: No
> such file or directory
> cc1: all warnings being treated as errors
>


The first patch(patch 1/3) should be applied!

Thank you, David! :)

2012-02-13 05:32:15

by David Ahern

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

[sorry for the top post - you would think Android would have a better mail client]

If the first patch is needed then kvm-events will not work with older, unpatched kernels. That's a big limitation from a perf perpective.

David

Sent from my ASUS Eee Pad

Xiao Guangrong <[email protected]> wrote:

>On 02/13/2012 11:04 AM, David Ahern wrote:
>
>> Compile fails on Fedora 16, x86_64 with latest tip-perf-core branch:
>>
>>
>> In file included from builtin-kvm-events.c:19:0:
>> ../../arch/x86/include/asm/svm.h:133:1: error: packed attribute is
>> unnecessary for ‘vmcb_seg’ [-Werror=packed]
>> ../../arch/x86/include/asm/svm.h:178:1: error: packed attribute is
>> unnecessary for ‘vmcb_save_area’ [-Werror=packed]
>> ../../arch/x86/include/asm/svm.h:183:1: error: packed attribute is
>> unnecessary for ‘vmcb’ [-Werror=packed]
>> In file included from builtin-kvm-events.c:20:0:
>> ../../arch/x86/include/asm/vmx.h:334:0: error: "REG_R8" redefined [-Werror]
>> /usr/include/sys/ucontext.h:46:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:335:0: error: "REG_R9" redefined [-Werror]
>> /usr/include/sys/ucontext.h:48:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:336:0: error: "REG_R10" redefined [-Werror]
>> /usr/include/sys/ucontext.h:50:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:337:0: error: "REG_R11" redefined [-Werror]
>> /usr/include/sys/ucontext.h:52:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:338:0: error: "REG_R12" redefined [-Werror]
>> /usr/include/sys/ucontext.h:54:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:339:0: error: "REG_R13" redefined [-Werror]
>> /usr/include/sys/ucontext.h:56:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:340:0: error: "REG_R14" redefined [-Werror]
>> /usr/include/sys/ucontext.h:58:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:341:0: error: "REG_R15" redefined [-Werror]
>> /usr/include/sys/ucontext.h:60:0: note: this is the location of the
>> previous definition
>> ../../arch/x86/include/asm/vmx.h:443:13: error: expected declaration
>> specifiers or ‘...’ before numeric constant
>> In file included from builtin-kvm-events.c:21:0:
>> ../../arch/x86/include/asm/kvm_host.h:15:22: fatal error: linux/mm.h: No
>> such file or directory
>> cc1: all warnings being treated as errors
>>
>
>
>The first patch(patch 1/3) should be applied!
>
>Thank you, David! :)
>
????{.n?+???????+%?????ݶ??w??{.n?+????{??G?????{ay?ʇڙ?,j??f???h?????????z_??(?階?Ý¢j"???m??????G????????????&???~???iO???z??v?^?m???? ????????I?

2012-02-13 10:06:20

by Xiao Guangrong

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 02/13/2012 01:32 PM, David Ahern wrote:

> [sorry for the top post - you would think Android would have a better mail client]
>
> If the first patch is needed then kvm-events will not work with older, unpatched kernels. That's a big limitation from a perf perpective.
>


The first patch is only needed for code compilation, after kvm-events is
compiled, you can analyse any kernels. :)

2012-02-13 15:53:00

by David Ahern

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool



On 02/13/2012 03:06 AM, Xiao Guangrong wrote:
> On 02/13/2012 01:32 PM, David Ahern wrote:
>
>> [sorry for the top post - you would think Android would have a better mail client]
>>
>> If the first patch is needed then kvm-events will not work with older, unpatched kernels. That's a big limitation from a perf perpective.
>>
>
>
> The first patch is only needed for code compilation, after kvm-events is
> compiled, you can analyse any kernels. :)

understood.

Now that I recall perf's way of handling out of tree builds, a couple of
comments:

1. you need to add the following to tools/perf/MANIFEST
arch/x86/include/asm/svm.h
arch/x86/include/asm/vmx.h
arch/x86/include/asm/kvm_host.h

2.scripts/checkpatch.pl is an unhappy camper.

I'll take a look at the code and try out the command when I get some time.

David

2012-02-16 05:00:19

by Xiao Guangrong

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 02/13/2012 11:52 PM, David Ahern wrote:


>> The first patch is only needed for code compilation, after kvm-events is
>> compiled, you can analyse any kernels. :)
>
> understood.
>
> Now that I recall perf's way of handling out of tree builds, a couple of
> comments:
>
> 1. you need to add the following to tools/perf/MANIFEST
> arch/x86/include/asm/svm.h
> arch/x86/include/asm/vmx.h
> arch/x86/include/asm/kvm_host.h
>


Right.

> 2.scripts/checkpatch.pl is an unhappy camper.
>


It seems checkpath always complains about TRACE_EVENT and many more
than-80-characters lines in perf tools.

> I'll take a look at the code and try out the command when I get some time.
>


Okay, i will post the next version after collecting your new comments!

Thanks for your time, David! :)

2012-02-16 05:05:16

by David Ahern

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 2/15/12 9:59 PM, Xiao Guangrong wrote:
>
>
> Okay, i will post the next version after collecting your new comments!
>
> Thanks for your time, David! :)
>

I had more comments, but got sidetracked and forgot to come back to
this. I still haven't looked at the code yet, but some comments from
testing:

1. The error message:
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'

is fixed by this patch which has not yet made its way into perf:
https://lkml.org/lkml/2011/9/4/41

The most recent request:
https://lkml.org/lkml/2012/2/8/479

Arnaldo: the patch still applies cleanly (but with an offset of -2 lines).


2. negatve testing:

perf kvm-events record -e kvm:* -p 2603 -- sleep 10

Warning: Error: expected type 4 but read 7
Warning: Error: expected type 5 but read 0
Warning: failed to read event print fmt for kvm_apic
Warning: Error: expected type 4 but read 7
Warning: Error: expected type 5 but read 0
Warning: failed to read event print fmt for kvm_inj_exception
Fatal: bad op token {

If other kvm events are specified in the record line they appear to be
silently ignored in the report in which case why allow the -e option to
record?


3. What is happening for multiple VMs?

a. perf kvm-events report
data is collected for all VMs. What is displayed in the report? An
average for all VMs?

b. perf kvm-events report --vcpu 1
Does this given an average of all vcpu 1's?

Perhaps a -p option for the report to pull out events related to a
single VM. Really this could be a generic option (to perf-report and
perf-script as well) to only show/analyze events for the specified pid.
ie., data is recorded for all VMs (or system wide for the regular
perf-record) and you want to only consider events for a specific pid.
e.g., in process_sample_event() skip event if event->ip.pid !=
report_pid (works for perf code because PERF_SAMPLE_TID attribute is
always set).

David

2012-02-16 05:34:35

by Xiao Guangrong

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 02/16/2012 01:05 PM, David Ahern wrote:

> On 2/15/12 9:59 PM, Xiao Guangrong wrote:
>>
>>
>> Okay, i will post the next version after collecting your new comments!
>>
>> Thanks for your time, David! :)
>>
>
> I had more comments, but got sidetracked and forgot to come back to this. I still haven't looked at the code yet, but some comments from testing:
>
> 1. The error message:
> Warning: Error: expected type 5 but read 4
> Warning: Error: expected type 5 but read 0
> Warning: unknown op '}'
>
> is fixed by this patch which has not yet made its way into perf:
> https://lkml.org/lkml/2011/9/4/41
>
> The most recent request:
> https://lkml.org/lkml/2012/2/8/479
>
> Arnaldo: the patch still applies cleanly (but with an offset of -2 lines).
>


Great, it is a good fix.

But, it does not hurt the development of kvm-events.

>
> 2. negatve testing:
>
> perf kvm-events record -e kvm:* -p 2603 -- sleep 10
>
> Warning: Error: expected type 4 but read 7
> Warning: Error: expected type 5 but read 0
> Warning: failed to read event print fmt for kvm_apic
> Warning: Error: expected type 4 but read 7
> Warning: Error: expected type 5 but read 0
> Warning: failed to read event print fmt for kvm_inj_exception
> Fatal: bad op token {
>
> If other kvm events are specified in the record line they appear to be silently ignored in the report in which case why allow the -e option to record?
>


Yes, kvm-events doese not analyse these events specified by -e option since
these events are not needed by vmexit/ioport/mmio analysis.

And after kvm-evnets record, you can see these events by perf script

>
> 3. What is happening for multiple VMs?
>
> a. perf kvm-events report
> data is collected for all VMs. What is displayed in the report? An
> average for all VMs?
>


Yes

> b. perf kvm-events report --vcpu 1
> Does this given an average of all vcpu 1's?
>


Yes

> Perhaps a -p option for the report to pull out events related to a single VM. Really this could be a generic option (to perf-report and perf-script as well) to only show/analyze events for the specified pid. ie., data is recorded for all VMs (or system wide for the regular perf-record) and you want to only consider events for a specific pid. e.g., in process_sample_event() skip event if event->ip.pid != report_pid (works for perf code because PERF_SAMPLE_TID attribute is always set).

Analysis for per VMs is good idea, but please allow me put it into my TODO list. :)

2012-02-16 16:36:00

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

Em Wed, Feb 15, 2012 at 10:05:08PM -0700, David Ahern escreveu:
> On 2/15/12 9:59 PM, Xiao Guangrong wrote:
> >
> >
> >Okay, i will post the next version after collecting your new comments!
> >
> >Thanks for your time, David! :)
> >
>
> I had more comments, but got sidetracked and forgot to come back to
> this. I still haven't looked at the code yet, but some comments from
> testing:
>
> 1. The error message:
> Warning: Error: expected type 5 but read 4
> Warning: Error: expected type 5 but read 0
> Warning: unknown op '}'
>
> is fixed by this patch which has not yet made its way into perf:
> https://lkml.org/lkml/2011/9/4/41
>
> The most recent request:
> https://lkml.org/lkml/2012/2/8/479
>
> Arnaldo: the patch still applies cleanly (but with an offset of -2 lines).

I'll merge this one now, recall Steven asked me to, thanks for the
reminder,

- Arnaldo

2012-02-20 23:47:47

by David Ahern

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

Finally got back to this. Overall nicely written command. Few comments
and one for Arnaldo at the bottom.

On 2/9/12 2:09 AM, Xiao Guangrong wrote:
> 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

It would be nice to have example reports in this commit message.

>
>
> Signed-off-by: Xiao Guangrong<[email protected]>
> ---
> tools/perf/Documentation/perf-kvm-events.txt | 52 ++
> tools/perf/Makefile | 1 +
> tools/perf/builtin-kvm-events.c | 851 ++++++++++++++++++++++++++
> tools/perf/builtin.h | 1 +
> tools/perf/command-list.txt | 1 +
> tools/perf/perf.c | 1 +
> tools/perf/util/header.c | 54 ++-
> tools/perf/util/header.h | 1 +
> tools/perf/util/thread.h | 2 +
> 9 files changed, 963 insertions(+), 1 deletions(-)
> create mode 100644 tools/perf/Documentation/perf-kvm-events.txt
> create mode 100644 tools/perf/builtin-kvm-events.c
>
> diff --git a/tools/perf/Documentation/perf-kvm-events.txt b/tools/perf/Documentation/perf-kvm-events.txt
> new file mode 100644
> index 0000000..ed36550
> --- /dev/null
> +++ b/tools/perf/Documentation/perf-kvm-events.txt
> @@ -0,0 +1,52 @@
> +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.
First sentence should be written in the 3rd person. eg.,
This command generates a statistical analysis of KVM events.

>
> +
> + '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)
> +
> +-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.

Add a comment stating which event type is the default.

>
> +-k::
> +--key=<value>::
> + Sorting key. Possible values: sample(default, sort by samples number),
> +time(sort by average time).
Space before both of the '('.

>
> +
> +SEE ALSO
> +--------
> +linkperf:perf[1]
> diff --git a/tools/perf/Makefile b/tools/perf/Makefile
> index ac86d67..ee43451 100644
> --- a/tools/perf/Makefile
> +++ b/tools/perf/Makefile
> @@ -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
>
> diff --git a/tools/perf/builtin-kvm-events.c b/tools/perf/builtin-kvm-events.c
> new file mode 100644
> index 0000000..9903d2b
> --- /dev/null
> +++ b/tools/perf/builtin-kvm-events.c
> @@ -0,0 +1,851 @@
> +#include "builtin.h"
> +#include "perf.h"
> +#include "util/util.h"
> +#include "util/cache.h"
> +#include "util/symbol.h"
> +#include "util/thread.h"
> +#include "util/header.h"
> +#include "util/parse-options.h"
> +#include "util/trace-event.h"
> +#include "util/debug.h"
> +#include "util/debugfs.h"
> +#include "util/session.h"
> +#include "util/tool.h"
> +
> +#include<math.h>
> +
> +#include<linux/kvm.h>
> +
> +#include "../../arch/x86/include/asm/svm.h"
> +#include "../../arch/x86/include/asm/vmx.h"
> +#include "../../arch/x86/include/asm/kvm_host.h"
> +
> +struct event_key {
> + #define INVALID_KEY (~0ULL)
> + u64 key;
> + int info;
> +};
> +
> +struct kvm_events_ops {
> + bool (*is_begin_event)(struct event *event, void *data,
> + struct event_key *key);
> + bool (*is_end_event)(struct event *event, void *data,
> + struct event_key *key);
> + void (*decode_key)(struct event_key *key, char decode[20]);
> + const char *name;
> +};
> +
> +static int cpu_isa;
> +
> +static void exit_event_get_key(struct event *event, void *data,
> + struct event_key *key)
> +{
> + key->info = cpu_isa;
> + key->key = raw_field_value(event, "exit_reason", data);
> +}
> +
> +static bool kvm_exit_event(struct event *event)
> +{
> + return !strcmp(event->name, "kvm_exit");
> +}
> +
> +static bool exit_event_begin(struct event *event, void *data,
> + struct event_key *key)
> +{
> + if (kvm_exit_event(event)) {
> + exit_event_get_key(event, data, key);
> + return true;
> + }
> +
> + return false;
> +}
> +
> +static bool kvm_entry_event(struct event *event)
> +{
> + return !strcmp(event->name, "kvm_entry");
> +}
> +
> +static bool exit_event_end(struct event *event, void *data __unused,
> + struct event_key *key __unused)
> +{
> + return kvm_entry_event(event);
> +}
> +
> +struct exit_reasons_table {
> + unsigned long exit_code;
> + const char *reason;
> +};
> +
> +struct exit_reasons_table vmx_exit_reasons[] = {
> + VMX_EXIT_REASONS
> +};
> +
> +struct exit_reasons_table svm_exit_reasons[] = {
> + SVM_EXIT_REASONS
> +};
> +
> +static const char *get_exit_reason(u64 exit_code, int isa)
> +{
> + int table_size = ARRAY_SIZE(svm_exit_reasons);
> + struct exit_reasons_table *table = svm_exit_reasons;
> +
> + if (isa == 1) {
> + table = vmx_exit_reasons;
> + table_size = ARRAY_SIZE(vmx_exit_reasons);
> + }
Why not use globals that are set once in read_events() after looking up
cpu_isa? Then you don't have to state a preference on default init here
-- AMD or Intel. And the isa argument will not be needed here.

> +
> + while (table_size--) {
> + if (table->exit_code == exit_code)
> + return table->reason;
> + table++;
> + }
> +
> + die("unknown kvm exit code:%ld on %s\n", exit_code,
> + isa ? "VMX" : "SVM");
> +}
> +
> +static void exit_event_decode_key(struct event_key *key, char decode[20])
> +{
> + const char *exit_reason = get_exit_reason(key->key, key->info);
> +
> + snprintf(decode, 20, "%s", exit_reason);
> +}
> +
> +static struct kvm_events_ops exit_events = {
> + .is_begin_event = exit_event_begin,
> + .is_end_event = exit_event_end,
> + .decode_key = exit_event_decode_key,
> + .name = "VM-EXIT"
> +};
> +
> +/*
> + * For the old kernel, we treat:
> + * the time of MMIO write: kvm_mmio(KVM_TRACE_MMIO_WRITE...) -> kvm_entry
> + * the time of MMIO read: kvm_exit -> kvm_mmio(KVM_TRACE_MMIO_READ...).
> + *
> + * For the new kernel, we use kvm_mmio_begin and kvm_mmio_done to make
> + * things better.
> + */
> +static void mmio_event_get_key(struct event *event, void *data,
> + struct event_key *key)
> +{
> + key->key = raw_field_value(event, "gpa", data);
> + key->info = raw_field_value(event, "type", data);
> +}
> +
> +#define KVM_TRACE_MMIO_READ_UNSATISFIED 0
> +#define KVM_TRACE_MMIO_READ 1
> +#define KVM_TRACE_MMIO_WRITE 2
> +
> +static bool kvm_mmio_done_event(struct event *event)
> +{
> + return !strcmp(event->name, "kvm_mmio_done");
> +}
> +
> +static bool mmio_event_begin(struct event *event, void *data,
> + struct event_key *key)
> +{
> + /* MMIO read begin in old kernel. */
> + if (kvm_exit_event(event))
> + return true;
> +
> + /* MMIO write begin in old kernel. */
> + if (!strcmp(event->name, "kvm_mmio")&&
> + raw_field_value(event, "type", data) == KVM_TRACE_MMIO_WRITE) {
> + mmio_event_get_key(event, data, key);
> + return true;
> + }
> +
> + /* MMIO read/write begin in new kernel. */
> + if (!strcmp(event->name, "kvm_mmio_begin")) {
> + mmio_event_get_key(event, data, key);
> + return true;
> + }
> +
> + return false;
> +}
> +
> +static bool mmio_event_end(struct event *event, void *data,
> + struct event_key *key)
> +{
> + /* MMIO write end in old kernel. */
> + if (kvm_entry_event(event))
> + return true;
> +
> + /* MMIO read end in the old kernel.*/
> + if (!strcmp(event->name, "kvm_mmio")&&
> + raw_field_value(event, "type", data) == KVM_TRACE_MMIO_READ) {
> + mmio_event_get_key(event, data, key);
> + return true;
> + }
> +
> + /* MMIO read/write end event in the new kernel.*/
> + return kvm_mmio_done_event(event);
> +}
> +
> +static void mmio_event_decode_key(struct event_key *key, char decode[20])
> +{
> + snprintf(decode, 20, "%#lx:%s", key->key,
> + key->info == KVM_TRACE_MMIO_WRITE ? "W" : "R");
> +}
> +
> +static struct kvm_events_ops mmio_events = {
> + .is_begin_event = mmio_event_begin,
> + .is_end_event = mmio_event_end,
> + .decode_key = mmio_event_decode_key,
> + .name = "MMIO Access"
> +};
> +
> +/*
> + * For the old kernel, the time of emulation pio access is from kvm_pio to
> + * kvm_entry. In the new kernel, the end time is indicated by kvm_mmio_done.
> + */
> +static void ioport_event_get_key(struct event *event, void *data,
> + struct event_key *key)
> +{
> + key->key = raw_field_value(event, "port", data);
> + key->info = raw_field_value(event, "rw", data);
> +}
> +
> +static bool ioport_event_begin(struct event *event, void *data,
> + struct event_key *key)
> +{
> + if (!strcmp(event->name, "kvm_pio")) {
> + ioport_event_get_key(event, data, key);
> + return true;
> + }
> +
> + return false;
> +}
> +
> +static bool ioport_event_end(struct event *event, void *data __unused,
> + struct event_key *key __unused)
> +{
> + if (kvm_entry_event(event))
> + return true;
> +
> + return kvm_mmio_done_event(event);
> +}
> +
> +static void ioport_event_decode_key(struct event_key *key, char decode[20])
> +{
> + snprintf(decode, 20, "%#lx:%s", key->key, key->info ? "POUT" : "PIN");
> +}
> +
> +static struct kvm_events_ops ioport_events = {
> + .is_begin_event = ioport_event_begin,
> + .is_end_event = ioport_event_end,
> + .decode_key = ioport_event_decode_key,
> + .name = "IO Port Access"
> +};
> +
> +static const char *report_event = "vmexit";
> +struct kvm_events_ops *events_ops;
> +
> +static void register_kvm_events_ops(void)
> +{
> + if (!strcmp(report_event, "vmexit"))
> + events_ops =&exit_events;
> + else if (!strcmp(report_event, "mmio"))
> + events_ops =&mmio_events;
> + else if (!strcmp(report_event, "ioport"))
> + events_ops =&ioport_events;
> + else
> + die("Unknown report event:%s\n", report_event);
> +}
> +
> +struct event_stats {
> + u64 count;
> + u64 time;
> +
> + /* used to calculate stddev. */
> + double mean;
> + double M2;
> +};
> +
> +struct kvm_event {
> + struct list_head hash_entry;
> + struct rb_node rb;
> +
> + struct event_key key;
> +
> + struct event_stats total;
> +
> + #define DEFAULT_VCPU_NUM 32
Why 32 for the default number of vcpus in a guest? Seems like a lot for
the typical VM. Versus something like 4 or 8.
>
> + int max_vcpu;
> + struct event_stats *vcpu;
> +};
> +
> +struct vcpu_event_record {
> + int vcpu_id;
> + u64 start_time;
> + struct kvm_event *last_event;
> +};
> +
> +#define EVENTS_BITS 12
> +#define EVENTS_CACHE_SIZE (1UL<< EVENTS_BITS)
> +
> +static u64 total_time;
> +static u64 total_count;
> +static struct list_head kvm_events_cache[EVENTS_CACHE_SIZE];
> +
> +static void init_kvm_event_record(void)
> +{
> + int i;
> +
> + for (i = 0; i< (int)EVENTS_CACHE_SIZE; i++)
> + INIT_LIST_HEAD(&kvm_events_cache[i]);
> +}
> +
> +static int kvm_events_hash_fn(u64 key)
> +{
> + return key& (EVENTS_CACHE_SIZE - 1);
> +}
> +
> +static void kvm_event_expand(struct kvm_event *event, int vcpu_id)
> +{
> + int old_max_vcpu = event->max_vcpu;
> +
> + if (vcpu_id< event->max_vcpu)
> + return;
> +
> + while (event->max_vcpu<= vcpu_id)
> + event->max_vcpu += DEFAULT_VCPU_NUM;
> +
> + event->vcpu = realloc(event->vcpu,
> + event->max_vcpu * sizeof(*event->vcpu));
> + if (!event->vcpu)
> + die("Not enough memory\n");
> +
> + memset(event->vcpu + old_max_vcpu, 0,
> + (event->max_vcpu - old_max_vcpu) * sizeof(*event->vcpu));
> +}
> +
> +static struct kvm_event *kvm_alloc_init_event(struct event_key *key)
> +{
> + struct kvm_event *event;
> +
> + event = zalloc(sizeof(*event));
> + if (!event)
> + die("Not enough memory\n");
> +
> + event->key = *key;
> + return event;
> +}
> +
> +static struct kvm_event *find_create_kvm_event(struct event_key *key)
> +{
> + struct kvm_event *event;
> + struct list_head *head;
> +
> + BUG_ON(key->key == INVALID_KEY);
> +
> + head =&kvm_events_cache[kvm_events_hash_fn(key->key)];
> + list_for_each_entry(event, head, hash_entry)
> + if (event->key.key == key->key&& event->key.info == key->info)
> + return event;
> +
> + event = kvm_alloc_init_event(key);
> + list_add(&event->hash_entry, head);
> + return event;
> +}
> +
> +static void handle_begin_event(struct vcpu_event_record *vcpu_record,
> + struct event_key *key, u64 timestamp)
> +{
> + struct kvm_event *event = NULL;
> +
> + if (key->key != INVALID_KEY)
> + event = find_create_kvm_event(key);
> +
> + vcpu_record->last_event = event;
> + vcpu_record->start_time = timestamp;
> +}
> +
> +static void update_event_stats(struct event_stats *stats, u64 time_diff)
> +{
> + double delta;
> +
> + stats->count++;
> + stats->time += time_diff;
> +
> + delta = time_diff - stats->mean;
> + stats->mean += delta / stats->count;
> + stats->M2 += delta*(time_diff - stats->mean);
> +}
> +
> +static double event_stats_stddev(int vcpu_id, struct kvm_event *event)
> +{
> + struct event_stats *stats =&event->total;
> + double variance, variance_mean, stddev;
> +
> + if (vcpu_id != -1)
> + stats =&event->vcpu[vcpu_id];
> +
> + BUG_ON(!stats->count);
> +
> + variance = stats->M2 / (stats->count - 1);
> + variance_mean = variance / stats->count;
> + stddev = sqrt(variance_mean);
> +
> + return stddev * 100 / stats->mean;
> +}
> +
> +static void update_kvm_event(struct kvm_event *event, int vcpu_id,
> + u64 time_diff)
> +{
> + update_event_stats(&event->total, time_diff);
> + kvm_event_expand(event, vcpu_id);
> + update_event_stats(&event->vcpu[vcpu_id], time_diff);
> +}
> +
> +static void handle_end_event(struct vcpu_event_record *vcpu_record,
> + struct event_key *key, u64 timestamp)
> +{
> + struct kvm_event *event;
> + u64 time_begin, time_diff;
> +
> + event = vcpu_record->last_event;
> + time_begin = vcpu_record->start_time;
> +
> + /* The begin event is not caught. */
> + if (!time_begin)
> + return;
> +
> + /* Both begin and end events did not get the key. */
> + if (!event&& key->key == INVALID_KEY)
> + return;
> +
Should not be able to get here with event unset, so the next 2 lines
should not be needed. ie., you only want to process events where the
begin event was seen in which case event is defined.
> + if (!event)
> + event = find_create_kvm_event(key);
> +
> + vcpu_record->last_event = NULL;
> + vcpu_record->start_time = 0;
> +
> + BUG_ON(timestamp< time_begin);
> +
> + time_diff = timestamp - time_begin;
> + update_kvm_event(event, vcpu_record->vcpu_id, time_diff);
> +}
> +
> +static struct vcpu_event_record
> +*per_vcpu_record(struct thread *thread, struct event *event, void *data)
> +{
> + /* Only kvm_entry records vcpu id. */
> + if (!thread->private&& kvm_entry_event(event)) {
> + struct vcpu_event_record *vcpu_record;
> +
> + vcpu_record = zalloc(sizeof(struct vcpu_event_record));
> + if (!vcpu_record)
> + die("Not enough memory\n");
> +
> + vcpu_record->vcpu_id = raw_field_value(event, "vcpu_id", data);
> + thread->private = vcpu_record;
> + }
> +
> + return (struct vcpu_event_record *)thread->private;
> +}
> +
> +static void handle_kvm_event(struct thread *thread, struct event *event,
> + void *data, u64 timestamp)
> +{
> + struct vcpu_event_record *vcpu_record;
> + struct event_key key = {.key = INVALID_KEY};
> +
> + vcpu_record = per_vcpu_record(thread, event, data);
> + if (!vcpu_record)
> + return;
> +
> + if (events_ops->is_begin_event(event, data,&key))
> + return handle_begin_event(vcpu_record,&key, timestamp);
> +
> + if (events_ops->is_end_event(event, data,&key))
> + return handle_end_event(vcpu_record,&key, timestamp);
> +}
> +
> +typedef int (*key_cmp_fun)(struct kvm_event*, struct kvm_event*, int);
> +struct kvm_event_key {
> + const char *name;
> + key_cmp_fun key;
> +};
> +
> +static int trace_vcpu = -1;
> +#define GET_EVENT_KEY(member) \
> +static u64 get_event_ ##member(struct kvm_event *event, int vcpu) \
> +{ \
> + if (vcpu == -1) \
> + return event->total.member; \
> + \
> + if (vcpu>= event->max_vcpu) \
> + return 0; \
> + \
> + return event->vcpu[vcpu].member; \
> +}
> +
> +#define COMPARE_EVENT_KEY(member) \
> +GET_EVENT_KEY(member) \
> +static int compare_kvm_event_ ## member(struct kvm_event *one, \
> + struct kvm_event *two, int vcpu)\
> +{ \
> + return get_event_ ##member(one, vcpu)> \
> + get_event_ ##member(two, vcpu); \
> +}
> +
> +GET_EVENT_KEY(time);
> +COMPARE_EVENT_KEY(count);
> +COMPARE_EVENT_KEY(mean);
> +
> +#define DEF_SORT_NAME_KEY(name, compare_key) \
> + { #name, compare_kvm_event_ ## compare_key }
> +
> +static struct kvm_event_key keys[] = {
> + DEF_SORT_NAME_KEY(sample, count),
> + DEF_SORT_NAME_KEY(time, mean),
> + { NULL, NULL }
> +};
> +
> +static const char *sort_key = "sample";
> +static key_cmp_fun compare;
> +
> +static void select_key(void)
> +{
> + int i;
> +
> + for (i = 0; keys[i].name; i++) {
> + if (!strcmp(keys[i].name, sort_key)) {
> + compare = keys[i].key;
> + return;
> + }
> + }
> +
> + die("Unknown compare key:%s\n", sort_key);
> +}
> +
> +static struct rb_root result;
> +static void insert_to_result(struct kvm_event *event, key_cmp_fun bigger,
> + int vcpu)
> +{
> + struct rb_node **rb =&result.rb_node;
> + struct rb_node *parent = NULL;
> + struct kvm_event *p;
> +
> + while (*rb) {
> + p = container_of(*rb, struct kvm_event, rb);
> + parent = *rb;
> +
> + if (bigger(event, p, vcpu))
> + rb =&(*rb)->rb_left;
> + else
> + rb =&(*rb)->rb_right;
> + }
> +
> + rb_link_node(&event->rb, parent, rb);
> + rb_insert_color(&event->rb,&result);
> +}
> +
> +static void update_total_count(struct kvm_event *event, int vcpu)
> +{
> + total_count += get_event_count(event, vcpu);
> + total_time += get_event_time(event, vcpu);
> +}
> +
> +static bool event_is_valid(struct kvm_event *event, int vcpu)
> +{
> + return get_event_count(event, vcpu);
> +}
> +
> +static void sort_result(int vcpu)
> +{
> + unsigned int i;
> + struct kvm_event *event;
> +
> + for (i = 0; i< EVENTS_CACHE_SIZE; i++)
> + list_for_each_entry(event,&kvm_events_cache[i], hash_entry)
> + if (event_is_valid(event, vcpu)) {
> + update_total_count(event, vcpu);
> + insert_to_result(event, compare, vcpu);
> + }
> +}
> +
> +/* returns left most element of result, and erase it */
> +static struct kvm_event *pop_from_result(void)
> +{
> + struct rb_node *node = result.rb_node;
> +
> + if (!node)
> + return NULL;
> +
> + while (node->rb_left)
> + node = node->rb_left;
> +
> + rb_erase(node,&result);
> + return container_of(node, struct kvm_event, rb);
> +}
> +
> +static void print_vcpu_info(int vcpu)
> +{
> + pr_info("Analyze events for ");
> +
> + if (vcpu == -1)
> + pr_info("all VCPUs:\n\n");
> + else
> + pr_info("VCPU %d:\n\n", vcpu);
> +}
> +
> +static void print_result(int vcpu)
> +{
> + char decode[20];
> + struct kvm_event *event;
> +
> + pr_info("\n\n");
> + print_vcpu_info(vcpu);
> + pr_info("%20s ", events_ops->name);
> + pr_info("%10s ", "Samples");
> + pr_info("%9s ", "Samples%");
> +
> + pr_info("%9s ", "Time%");
> + pr_info("%16s ", "Avg time");
> + pr_info("\n\n");
> +
> + while ((event = pop_from_result())) {
> + u64 ecount, etime;
> +
> + ecount = get_event_count(event, vcpu);
> + etime = get_event_time(event, vcpu);
> +
> + events_ops->decode_key(&event->key, decode);
> + pr_info("%20s ", decode);
> + pr_info("%10lu ", ecount);
> + pr_info("%8.2f%% ", (double)ecount / total_count * 100);
> + pr_info("%8.2f%% ", (double)etime / total_time * 100);
> + pr_info("%9.2fus ( +-%7.2f%% )", (double)etime / ecount/1e3,
> + event_stats_stddev(trace_vcpu, event));
> + pr_info("\n");
> + }
> +
> + pr_info("\nTotal Samples:%ld, Total events handled time:%.2fus.\n\n",
> + total_count, total_time / 1e3);
> +}
> +
> +static void process_raw_event(struct thread *thread, void *data, u64 timestamp)
> +{
> + struct event *event;
> + int type;
> +
> + type = trace_parse_common_type(data);
> + event = trace_find_event(type);
> +
> + return handle_kvm_event(thread, event, data, timestamp);
> +}
> +
> +static int process_sample_event(struct perf_tool *tool __used,
> + union perf_event *event,
> + struct perf_sample *sample,
> + struct perf_evsel *evsel __used,
> + struct machine *machine)
> +{
> + struct thread *thread = machine__findnew_thread(machine, sample->tid);
> +
> + if (thread == NULL) {
> + pr_debug("problem processing %d event, skipping it.\n",
> + event->header.type);
> + return -1;
> + }
> +
> + process_raw_event(thread, sample->raw_data, sample->time);
> +
> + return 0;
> +}
> +
> +static struct perf_tool eops = {
> + .sample = process_sample_event,
> + .comm = perf_event__process_comm,
> + .ordered_samples = true,
> +};
> +
> +static char const *input_name = "perf.data";
> +
> +static int get_cpu_isa(struct perf_session *session)
> +{
> + char *cpuid;
> + int isa;
> +
> + cpuid = perf_header__read_feature(session, HEADER_CPUID);
> +
> + if (!cpuid)
> + die("read HEADER_CPUID failed.\n");
> +
> + if (strstr(cpuid, "Intel"))
> + isa = 1;
> + else if (strstr(cpuid, "AMD"))
> + isa = 0;
> + else
> + die("CPU %s is not supported.\n", cpuid);
> +
> + free(cpuid);
> + return isa;
> +}
> +
> +static int read_events(void)
> +{
> + struct perf_session *session;
> +
> + session = perf_session__new(input_name, O_RDONLY, 0, false,&eops);
> + if (!session)
> + die("Initializing perf session failed\n");
> +
> + if (!perf_session__has_traces(session, "kvm record"))
> + return -1;
> +
> + /*
> + * Do not use 'isa' recorded in kvm_exit tracepoint since it is not
> + * traced in the old kernel.
> + */
> + cpu_isa = get_cpu_isa(session);
> +
> + return perf_session__process_events(session,&eops);
> +}
> +
> +static void verify_vcpu(int vcpu)
> +{
> + if (vcpu != -1&& vcpu< 0)
> + die("Invalid vcpu:%d.\n", vcpu);
> +}
> +
> +static int kvm_events_report(int vcpu)
> +{
> + init_kvm_event_record();
> + verify_vcpu(vcpu);
> + select_key();
> + register_kvm_events_ops();
> + setup_pager();
> +
> + read_events();
> +
> + sort_result(vcpu);
> + print_result(vcpu);
> + return 0;
> +}
> +
> +static const char * const record_args[] = {
> + "record",
> + "-a",
> + "-R",
> + "-f",
> + "-m", "1024",
> + "-c", "1",
> + "-e", "kvm:kvm_entry",
> + "-e", "kvm:kvm_exit",
> + "-e", "kvm:kvm_mmio",
> + "-e", "kvm:kvm_pio",
> +};
> +
> +static const char * const new_event[] = {
> + "kvm_mmio_begin",
> + "kvm_mmio_done"
> +};
> +
> +static bool kvm_events_exist(const char *event)
> +{
> + char evt_path[MAXPATHLEN];
> + int fd;
> +
> + snprintf(evt_path, MAXPATHLEN, "%s/kvm/%s/id", tracing_events_path,
> + event);
> +
> + fd = open(evt_path, O_RDONLY);
> +
> + if (fd< 0)
> + return false;
> +
> + close(fd);
> +
> + return true;
> +}
> +
> +static int kvm_events_record(int argc, const char **argv)
> +{
> + unsigned int rec_argc, i, j;
> + const char **rec_argv;
> +
> + rec_argc = ARRAY_SIZE(record_args) + argc - 1;
> + rec_argc += ARRAY_SIZE(new_event) * 2;
> + rec_argv = calloc(rec_argc + 1, sizeof(char *));
> +
> + if (rec_argv == NULL)
> + return -ENOMEM;
> +
> + for (i = 0; i< ARRAY_SIZE(record_args); i++)
> + rec_argv[i] = strdup(record_args[i]);
> +
> + for (j = 0; j< ARRAY_SIZE(new_event); j++)
> + if (kvm_events_exist(new_event[j])) {
> + char event[256];
> +
> + sprintf(event, "kvm:%s", new_event[j]);
> +
> + rec_argv[i++] = strdup("-e");
> + rec_argv[i++] = strdup(event);
> + }
> +
> + for (j = 1; j< (unsigned int)argc; j++, i++)
> + rec_argv[i] = argv[j];
> +
> + return cmd_record(i, rec_argv, NULL);
> +}
> +
> +static const char * const kvm_events_report_usage[] = {
> + "perf kvm events report [<options>]",
missing '-' between kvm and events

>
> + NULL
> +};
> +
> +static const struct option kvm_events_report_options[] = {
> + OPT_STRING(0, "event",&report_event, "reprot event",
report is misspelled in the above line.
>
> + "event for reporting: vmexit, mmio, ioport"),
> + OPT_INTEGER(0, "vcpu",&trace_vcpu,
> + "vcpu id to report"),
> + OPT_STRING('k', "key",&sort_key, "sort-key",
> + "key for sorting: sample(sort by samples number)"
> + " time (sort by avg time)"),
> + OPT_END()
> +};
> +
> +static const char * const kvm_events_usage[] = {
> + "perf kvm events [<options>] {record|report}",
missing '-' between kvm and events
>
> + NULL
> +};
> +
> +static const struct option kvm_events_options[] = {
> + OPT_STRING('i', "input",&input_name, "file", "input file name"),
> + OPT_BOOLEAN('D', "dump-raw-trace",&dump_trace,
> + "dump raw trace in ASCII"),
> + OPT_END()
> +};
> +
> +int cmd_kvm_events(int argc, const char **argv, const char *prefix __used)
> +{
> + argc = parse_options(argc, argv, kvm_events_options, kvm_events_usage,
> + PARSE_OPT_STOP_AT_NON_OPTION);
> + if (!argc)
> + usage_with_options(kvm_events_usage, kvm_events_options);
> +
> + symbol__init();
> +
> + if (!strncmp(argv[0], "rec", 3))
> + return kvm_events_record(argc, argv);
> +
> + if (!strncmp(argv[0], "rep", 3)) {
> + if (argc) {
> + argc = parse_options(argc, argv,
> + kvm_events_report_options,
> + kvm_events_report_usage, 0);
> + if (argc)
> + usage_with_options(kvm_events_report_usage,
> + kvm_events_report_options);
> + }
> + return kvm_events_report(trace_vcpu);
> + }
> +
> + usage_with_options(kvm_events_usage, kvm_events_options);
> + return 0;
> +}
> diff --git a/tools/perf/builtin.h b/tools/perf/builtin.h
> index b382bd5..fb19e3d 100644
> --- a/tools/perf/builtin.h
> +++ b/tools/perf/builtin.h
> @@ -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);
>
> diff --git a/tools/perf/command-list.txt b/tools/perf/command-list.txt
> index d695fe4..c5e97d8 100644
> --- a/tools/perf/command-list.txt
> +++ b/tools/perf/command-list.txt
> @@ -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
> diff --git a/tools/perf/perf.c b/tools/perf/perf.c
> index 2b2e225..ab85ea5 100644
> --- a/tools/perf/perf.c
> +++ b/tools/perf/perf.c
> @@ -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 },
> };
> diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
> index 3e7e0b0..73f2a6f 100644
> --- a/tools/perf/util/header.c
> +++ b/tools/perf/util/header.c
> @@ -1305,9 +1305,15 @@ static void print_cpuid(struct perf_header *ph, int fd, FILE *fp)
> free(str);
> }
>
> +static char *read_cpuid(struct perf_header *ph, int fd)
> +{
> + return do_read_string(fd, ph);
> +}
> +
> struct feature_ops {
> int (*write)(int fd, struct perf_header *h, struct perf_evlist *evlist);
> void (*print)(struct perf_header *h, int fd, FILE *fp);
> + char *(*read)(struct perf_header *h, int fd);
> const char *name;
> bool full_only;
> };
> @@ -1316,6 +1322,8 @@ struct feature_ops {
> [n] = { .name = #n, .write = write_##func, .print = print_##func }
> #define FEAT_OPF(n, func) \
> [n] = { .name = #n, .write = write_##func, .print = print_##func, .full_only = true }
> +#define FEAT_OPA_R(n, func) \
> + [n] = { .name = #n, .write = write_##func, .print = print_##func, .read = read_##func }
>
> /* feature_ops not implemented: */
> #define print_trace_info NULL
> @@ -1330,7 +1338,7 @@ static const struct feature_ops feat_ops[HEADER_LAST_FEATURE] = {
> FEAT_OPA(HEADER_ARCH, arch),
> FEAT_OPA(HEADER_NRCPUS, nrcpus),
> FEAT_OPA(HEADER_CPUDESC, cpudesc),
> - FEAT_OPA(HEADER_CPUID, cpuid),
> + FEAT_OPA_R(HEADER_CPUID, cpuid),
> FEAT_OPA(HEADER_TOTAL_MEM, total_mem),
> FEAT_OPA(HEADER_EVENT_DESC, event_desc),
> FEAT_OPA(HEADER_CMDLINE, cmdline),
> @@ -1383,6 +1391,50 @@ int perf_header__fprintf_info(struct perf_session *session, FILE *fp, bool full)
> return 0;
> }
>
> +struct header_read_data {
> + int feat;
> + char *result;
> +};
> +
> +static int perf_file_section__read_feature(struct perf_file_section *section,
> + struct perf_header *ph,
> + int feat, int fd, void *data)
> +{
> + struct header_read_data *hd = data;
> +
> + if (feat != hd->feat)
> + return 0;
> +
> + if (lseek(fd, section->offset, SEEK_SET) == (off_t)-1) {
> + pr_debug("Failed to lseek to %" PRIu64 " offset for feature "
> + "%d, continuing...\n", section->offset, feat);
> + return 0;
> + }
> +
> + if (feat>= HEADER_LAST_FEATURE) {
> + pr_warning("unknown feature %d\n", feat);
> + return 0;
> + }
> +
> + hd->result = feat_ops[feat].read(ph, fd);
> + return 0;
> +}
> +
> +char *perf_header__read_feature(struct perf_session *session, int feat)
> +{
> + struct perf_header *header =&session->header;
> + struct header_read_data hd;
> + int fd = session->fd;
> +
> + hd.feat = feat;
> + hd.result = NULL;
> +
> +
> + perf_header__process_sections(header, fd,&hd,
> + perf_file_section__read_feature);
> + return hd.result;
> +}
> +
> static int do_write_feat(int fd, struct perf_header *h, int type,
> struct perf_file_section **p,
> struct perf_evlist *evlist)
> diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
> index ac4ec95..41ddfad 100644
> --- a/tools/perf/util/header.h
> +++ b/tools/perf/util/header.h
> @@ -92,6 +92,7 @@ int perf_header__process_sections(struct perf_header *header, int fd,
> int feat, int fd, void *data));
>
> int perf_header__fprintf_info(struct perf_session *s, FILE *fp, bool full);
> +char *perf_header__read_feature(struct perf_session *session, int feat);
>
> int build_id_cache__add_s(const char *sbuild_id, const char *debugdir,
> const char *name, bool is_kallsyms);
> diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
> index 70c2c13..c48ebf3 100644
> --- a/tools/perf/util/thread.h
> +++ b/tools/perf/util/thread.h
> @@ -16,6 +16,8 @@ struct thread {
> bool comm_set;
> char *comm;
> int comm_len;
> +
> + void *private;
Arnaldo: Are you ok with this design for now? I can fix this command to
whatever API we agree to when it gets committed.

David
>
> };
>
> struct machine;
>
> --
> To unsubscribe from this list: send the line "unsubscribe kvm" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html

2012-02-21 03:53:08

by Xiao Guangrong

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 02/21/2012 07:47 AM, David Ahern wrote:

- show the result:
>> perf kvm-events report
>
> It would be nice to have example reports in this commit message.
>


Okay.

>> +DESCRIPTION
>> +-----------
>> +You can analyze some crucial kvm events and statistics with this
>> +'perf kvm-events' command. Currently, vmexit, mmio and ioport events
>> +are supported.
> First sentence should be written in the 3rd person. eg.,
> This command generates a statistical analysis of KVM events.
>


Okay.

>> +--events=<value>::
>> + events to be analyzed. Possible values: vmexit, mmio, ioport.
>
> Add a comment stating which event type is the default.
>


OK, will fix.

>>
>> +-k::
>> +--key=<value>::
>> + Sorting key. Possible values: sample(default, sort by samples number),
>> +time(sort by average time).
> Space before both of the '('.
>


Yes, will fix.

>> +static const char *get_exit_reason(u64 exit_code, int isa)
>> +{
>> + int table_size = ARRAY_SIZE(svm_exit_reasons);
>> + struct exit_reasons_table *table = svm_exit_reasons;
>> +
>> + if (isa == 1) {
>> + table = vmx_exit_reasons;
>> + table_size = ARRAY_SIZE(vmx_exit_reasons);
>> + }
> Why not use globals that are set once in read_events() after looking up cpu_isa? Then you don't have to state a preference on default init here -- AMD or Intel. And the isa argument will not be needed here.
>


I agree.

>> + #define DEFAULT_VCPU_NUM 32
> Why 32 for the default number of vcpus in a guest? Seems like a lot for the typical VM. Versus something like 4 or 8.
>>


Hmm, since 32 is the default vcpu number in the old kernel (IIRC), but your suggestion
sounds good.

>> + /* Both begin and end events did not get the key. */
>> + if (!event&& key->key == INVALID_KEY)
>> + return;
>> +
> Should not be able to get here with event unset, so the next 2 lines should not be needed. ie., you only want to process events where the begin event was seen in which case event is defined.


In some case, the 'begin event' just records the start timestamp, the actually event
is recognised in the 'end event'.

Take mmio-read for example, in the old kernel, we use kvm-exit as the 'begin event'
and kvm_mmio(KVM_TRACE_MMIO_READ...) is the 'end event'.

>> + "perf kvm events report [<options>]",
> missing '-' between kvm and events
>


...

>> +static const char * const kvm_events_usage[] = {
>> + "perf kvm events [<options>] {record|report}",
> missing '-' between kvm and events


Sorry for my careless, these will be fixed in the next version.

Thanks very much for your review, David! :)

2012-02-21 04:58:37

by David Ahern

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 2/20/12 8:52 PM, Xiao Guangrong wrote:
>>> + /* Both begin and end events did not get the key. */
>>> + if (!event&& key->key == INVALID_KEY)
>>> + return;
>>> +
>> Should not be able to get here with event unset, so the next 2 lines should not be needed. ie., you only want to process events where the begin event was seen in which case event is defined.
>
>
> In some case, the 'begin event' just records the start timestamp, the actually event
> is recognised in the 'end event'.
>
> Take mmio-read for example, in the old kernel, we use kvm-exit as the 'begin event'
> and kvm_mmio(KVM_TRACE_MMIO_READ...) is the 'end event'.

ah, ok. Please add a comment about this path.

David

2012-02-27 04:57:16

by Xiao Guangrong

[permalink] [raw]
Subject: Re: [PATCH 3/3] KVM: perf: kvm events analysis tool

On 02/21/2012 07:47 AM, David Ahern wrote:


>> diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
>> index 70c2c13..c48ebf3 100644
>> --- a/tools/perf/util/thread.h
>> +++ b/tools/perf/util/thread.h
>> @@ -16,6 +16,8 @@ struct thread {
>> bool comm_set;
>> char *comm;
>> int comm_len;
>> +
>> + void *private;
> Arnaldo: Are you ok with this design for now? I can fix this command to whatever API we agree to when it gets committed.


Hi Arnaldo,

What do you think of it? :)