* [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
@ 2012-01-16 9:30 Xiao Guangrong
2012-01-16 9:31 ` [PATCH 1/3] KVM: trace mmio read event properly Xiao Guangrong
` (4 more replies)
0 siblings, 5 replies; 40+ messages in thread
From: Xiao Guangrong @ 2012-01-16 9:30 UTC (permalink / raw)
To: Avi Kivity; +Cc: Marcelo Tosatti, LKML, KVM
This tool is very like xenoprof(if i remember correctly), and traces kvm events
smartly. currently, it supports vmexit/mmio/ioport events.
Usage:
- to trace kvm events:
# ./perf kvm-events record
- show the result
# ./perf kvm-events report
Some output are as follow:
# ./perf kvm-events report
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'
Analyze events for all VCPUs:
VM-EXIT Samples Samples% Time% Avg time
APIC_ACCESS 438107 44.89% 6.20% 17.91us
EXTERNAL_INTERRUPT 219226 22.46% 8.01% 46.20us
IO_INSTRUCTION 122651 12.57% 1.88% 19.44us
EPT_VIOLATION 83110 8.52% 1.36% 20.75us
PENDING_INTERRUPT 37055 3.80% 0.16% 5.38us
CPUID 32718 3.35% 0.08% 3.15us
EXCEPTION_NMI 23601 2.42% 0.17% 8.87us
HLT 15424 1.58% 82.12% 6735.06us
CR_ACCESS 4089 0.42% 0.02% 6.08us
Total Samples:975981, Total events handled time:126502464.88us.
The default event to be analysed is vmexit, we can use --event to specify it,
for example, if we want to trace mmio event:
# ./perf kvm-events report --event mmio
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'
Analyze events for all VCPUs:
MMIO Access Samples Samples% Time% Avg time
0xfee00380:W 196589 64.95% 70.01% 3.83us
0xfee00310:W 35356 11.68% 6.48% 1.97us
0xfee00300:W 35356 11.68% 16.37% 4.97us
0xfee00300:R 35356 11.68% 7.14% 2.17us
Total Samples:302657, Total events handled time:1074746.01us.
We can use --vcpu to specify which vcpu is traced:
root@localhost perf]# ./perf kvm-events report --event mmio --vcpu 1
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'
Analyze events for VCPU 1:
MMIO Access Samples Samples% Time% Avg time
0xfee00380:W 58041 71.20% 74.90% 3.70us
0xfee00310:W 7826 9.60% 5.28% 1.93us
0xfee00300:W 7826 9.60% 13.82% 5.06us
0xfee00300:R 7826 9.60% 6.01% 2.20us
Total Samples:81519, Total events handled time:286577.81us.
And, '--key' is used to sort the result, the possible value sample (default,
the result is sorted by samples number), time(the result is sorted by time%):
# ./perf kvm-events report --key time
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'
Analyze events for all VCPUs:
VM-EXIT Samples Samples% Time% Avg time
HLT 15424 1.58% 82.12% 6735.06us
EXTERNAL_INTERRUPT 219226 22.46% 8.01% 46.20us
APIC_ACCESS 438107 44.89% 6.20% 17.91us
IO_INSTRUCTION 122651 12.57% 1.88% 19.44us
EPT_VIOLATION 83110 8.52% 1.36% 20.75us
EXCEPTION_NMI 23601 2.42% 0.17% 8.87us
PENDING_INTERRUPT 37055 3.80% 0.16% 5.38us
CPUID 32718 3.35% 0.08% 3.15us
CR_ACCESS 4089 0.42% 0.02% 6.08us
Total Samples:975981, Total events handled time:126502464.88us.
I hope guys will like it and any comments are welcome! :)
^ permalink raw reply [flat|nested] 40+ messages in thread* [PATCH 1/3] KVM: trace mmio read event properly 2012-01-16 9:30 [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Xiao Guangrong @ 2012-01-16 9:31 ` Xiao Guangrong 2012-01-16 10:18 ` Avi Kivity 2012-01-16 9:32 ` [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport Xiao Guangrong ` (3 subsequent siblings) 4 siblings, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-01-16 9:31 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM In current code, we use KVM_TRACE_MMIO_READ to trace mmio read event which only can be completed immediately, instead of it, we trace the time when read event occur, then cooperate with then later patch, we can know the time of mmio read emulation Signed-off-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com> --- arch/x86/kvm/x86.c | 6 ++---- 1 files changed, 2 insertions(+), 4 deletions(-) diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c index c95ca2d..0d41cfc 100644 --- a/arch/x86/kvm/x86.c +++ b/arch/x86/kvm/x86.c @@ -3432,7 +3432,6 @@ static int vcpu_mmio_read(struct kvm_vcpu *vcpu, gpa_t addr, int len, void *v) !kvm_iodevice_read(&vcpu->arch.apic->dev, addr, n, v)) && kvm_io_bus_read(vcpu->kvm, KVM_MMIO_BUS, addr, n, v)) break; - trace_kvm_mmio(KVM_TRACE_MMIO_READ, n, addr, *(u64 *)v); handled += n; addr += n; len -= n; @@ -3658,8 +3657,6 @@ static int read_prepare(struct kvm_vcpu *vcpu, void *val, int bytes) { if (vcpu->mmio_read_completed) { memcpy(val, vcpu->mmio_data, bytes); - trace_kvm_mmio(KVM_TRACE_MMIO_READ, bytes, - vcpu->mmio_phys_addr, *(u64 *)val); vcpu->mmio_read_completed = 0; return 1; } @@ -3681,7 +3678,6 @@ static int write_emulate(struct kvm_vcpu *vcpu, gpa_t gpa, static int write_mmio(struct kvm_vcpu *vcpu, gpa_t gpa, int bytes, void *val) { - trace_kvm_mmio(KVM_TRACE_MMIO_WRITE, bytes, gpa, *(u64 *)val); return vcpu_mmio_write(vcpu, gpa, bytes, val); } @@ -3744,6 +3740,8 @@ mmio: /* * Is this MMIO handled locally? */ + trace_kvm_mmio(write ? KVM_TRACE_MMIO_WRITE : KVM_TRACE_MMIO_READ, + bytes, gpa, *(u64 *)val); handled = ops->read_write_mmio(vcpu, gpa, bytes, val); if (handled == bytes) return X86EMUL_CONTINUE; -- 1.7.7.5 ^ permalink raw reply related [flat|nested] 40+ messages in thread
* Re: [PATCH 1/3] KVM: trace mmio read event properly 2012-01-16 9:31 ` [PATCH 1/3] KVM: trace mmio read event properly Xiao Guangrong @ 2012-01-16 10:18 ` Avi Kivity 2012-01-17 2:36 ` Xiao Guangrong 0 siblings, 1 reply; 40+ messages in thread From: Avi Kivity @ 2012-01-16 10:18 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 11:31 AM, Xiao Guangrong wrote: > In current code, we use KVM_TRACE_MMIO_READ to trace mmio read event which > only can be completed immediately, instead of it, we trace the time when > read event occur, then cooperate with then later patch, we can know the time > of mmio read emulation > > @@ -3744,6 +3740,8 @@ mmio: > /* > * Is this MMIO handled locally? > */ > + trace_kvm_mmio(write ? KVM_TRACE_MMIO_WRITE : KVM_TRACE_MMIO_READ, It's better to push the conditional to the trace event itself, so it's only evaluated if tracing is enabled. > + bytes, gpa, *(u64 *)val); We get the wrong value for reads here, no? Can't we leave the code as is, and infer the start of the event from the last kvm_exit trace? > handled = ops->read_write_mmio(vcpu, gpa, bytes, val); > if (handled == bytes) > return X86EMUL_CONTINUE; -- error compiling committee.c: too many arguments to function ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 1/3] KVM: trace mmio read event properly 2012-01-16 10:18 ` Avi Kivity @ 2012-01-17 2:36 ` Xiao Guangrong 0 siblings, 0 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-01-17 2:36 UTC (permalink / raw) To: Avi Kivity; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 06:18 PM, Avi Kivity wrote: > On 01/16/2012 11:31 AM, Xiao Guangrong wrote: >> In current code, we use KVM_TRACE_MMIO_READ to trace mmio read event which >> only can be completed immediately, instead of it, we trace the time when >> read event occur, then cooperate with then later patch, we can know the time >> of mmio read emulation >> >> @@ -3744,6 +3740,8 @@ mmio: >> /* >> * Is this MMIO handled locally? >> */ >> + trace_kvm_mmio(write ? KVM_TRACE_MMIO_WRITE : KVM_TRACE_MMIO_READ, > > It's better to push the conditional to the trace event itself, so it's > only evaluated if tracing is enabled. > Yes. >> + bytes, gpa, *(u64 *)val); > > We get the wrong value for reads here, no? > Yes, the value is meaningless in this point. > Can't we leave the code as is, and infer the start of the event from the > last kvm_exit trace? Yes, we can do it, but the same problems is we need trace vcpu id to get its vmexit, i will do it in the next version if you like this way :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-16 9:30 [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Xiao Guangrong 2012-01-16 9:31 ` [PATCH 1/3] KVM: trace mmio read event properly Xiao Guangrong @ 2012-01-16 9:32 ` Xiao Guangrong 2012-01-16 9:38 ` Avi Kivity 2012-01-16 9:32 ` [PATCH 3/3] KVM: perf: kvm events analysis tool Xiao Guangrong ` (2 subsequent siblings) 4 siblings, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-01-16 9:32 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM - trace vcpu_id for these events - add kvm_mmio_done to trace the time when mmio/ioport emulation is completed Signed-off-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com> --- arch/x86/kvm/trace.h | 33 ++++++++++++++++++++++++++------- arch/x86/kvm/x86.c | 19 +++++++++++++------ include/trace/events/kvm.h | 32 +++++++++++++++++++++++++------- 3 files changed, 64 insertions(+), 20 deletions(-) diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h index 911d264..e556458 100644 --- a/arch/x86/kvm/trace.h +++ b/arch/x86/kvm/trace.h @@ -91,11 +91,12 @@ TRACE_EVENT(kvm_hv_hypercall, * Tracepoint for PIO. */ TRACE_EVENT(kvm_pio, - TP_PROTO(unsigned int rw, unsigned int port, unsigned int size, - unsigned int count), - TP_ARGS(rw, port, size, count), + TP_PROTO(unsigned int vcpu_id, unsigned int rw, unsigned int port, + unsigned int size, unsigned int count), + TP_ARGS(vcpu_id, rw, port, size, count), TP_STRUCT__entry( + __field( unsigned int, vcpu_id ) __field( unsigned int, rw ) __field( unsigned int, port ) __field( unsigned int, size ) @@ -103,17 +104,33 @@ TRACE_EVENT(kvm_pio, ), TP_fast_assign( + __entry->vcpu_id = vcpu_id; __entry->rw = rw; __entry->port = port; __entry->size = size; __entry->count = count; ), - TP_printk("pio_%s at 0x%x size %d count %d", - __entry->rw ? "write" : "read", + TP_printk("vcpu %u pio_%s at 0x%x size %d count %d", + __entry->vcpu_id, __entry->rw ? "write" : "read", __entry->port, __entry->size, __entry->count) ); +TRACE_EVENT(kvm_pio_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) +); + /* * Tracepoint for cpuid. */ @@ -280,6 +297,7 @@ TRACE_EVENT(kvm_exit, TP_ARGS(exit_reason, vcpu, isa), TP_STRUCT__entry( + __field( unsigned int, vcpu_id ) __field( unsigned int, exit_reason ) __field( unsigned long, guest_rip ) __field( u32, isa ) @@ -288,6 +306,7 @@ TRACE_EVENT(kvm_exit, ), TP_fast_assign( + __entry->vcpu_id = vcpu->vcpu_id; __entry->exit_reason = exit_reason; __entry->guest_rip = kvm_rip_read(vcpu); __entry->isa = isa; @@ -295,8 +314,8 @@ TRACE_EVENT(kvm_exit, &__entry->info2); ), - TP_printk("reason %s rip 0x%lx info %llx %llx", - (__entry->isa == KVM_ISA_VMX) ? + TP_printk("vcpu %u reason %s rip 0x%lx info %llx %llx", + __entry->vcpu_id, (__entry->isa == KVM_ISA_VMX) ? __print_symbolic(__entry->exit_reason, VMX_EXIT_REASONS) : __print_symbolic(__entry->exit_reason, SVM_EXIT_REASONS), __entry->guest_rip, __entry->info1, __entry->info2) diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c index 0d41cfc..cf54478 100644 --- a/arch/x86/kvm/x86.c +++ b/arch/x86/kvm/x86.c @@ -3684,7 +3684,8 @@ static int write_mmio(struct kvm_vcpu *vcpu, gpa_t gpa, int bytes, void *val) static int read_exit_mmio(struct kvm_vcpu *vcpu, gpa_t gpa, void *val, int bytes) { - trace_kvm_mmio(KVM_TRACE_MMIO_READ_UNSATISFIED, bytes, gpa, 0); + trace_kvm_mmio(vcpu->vcpu_id, KVM_TRACE_MMIO_READ_UNSATISFIED, + bytes, gpa, 0); return X86EMUL_IO_NEEDED; } @@ -3740,11 +3741,14 @@ mmio: /* * Is this MMIO handled locally? */ - trace_kvm_mmio(write ? KVM_TRACE_MMIO_WRITE : KVM_TRACE_MMIO_READ, - bytes, gpa, *(u64 *)val); + trace_kvm_mmio(vcpu->vcpu_id, + write ? KVM_TRACE_MMIO_WRITE : KVM_TRACE_MMIO_READ, + bytes, gpa, *(u64 *)val); 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; @@ -3902,7 +3906,7 @@ static int emulator_pio_in_out(struct kvm_vcpu *vcpu, int size, unsigned short port, void *val, unsigned int count, bool in) { - trace_kvm_pio(!in, port, size, count); + trace_kvm_pio(vcpu->vcpu_id, !in, port, size, count); vcpu->arch.pio.port = port; vcpu->arch.pio.in = in; @@ -3910,6 +3914,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; } @@ -5399,7 +5404,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); @@ -5407,6 +5412,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..20b9f17 100644 --- a/include/trace/events/kvm.h +++ b/include/trace/events/kvm.h @@ -152,28 +152,46 @@ TRACE_EVENT(kvm_ack_irq, { KVM_TRACE_MMIO_WRITE, "write" } TRACE_EVENT(kvm_mmio, - TP_PROTO(int type, int len, u64 gpa, u64 val), - TP_ARGS(type, len, gpa, val), + TP_PROTO(unsigned int vcpu_id, int type, int len, u64 gpa, u64 val), + TP_ARGS(vcpu_id, type, len, gpa, val), TP_STRUCT__entry( - __field( u32, type ) - __field( u32, len ) - __field( u64, gpa ) - __field( u64, val ) + __field( unsigned int, vcpu_id ) + __field( u32, type ) + __field( u32, len ) + __field( u64, gpa ) + __field( u64, val ) ), TP_fast_assign( + __entry->vcpu_id = vcpu_id; __entry->type = type; __entry->len = len; __entry->gpa = gpa; __entry->val = val; ), - TP_printk("mmio %s len %u gpa 0x%llx val 0x%llx", + TP_printk("vcpu %u mmio %s len %u gpa 0x%llx val 0x%llx", + __entry->vcpu_id, __print_symbolic(__entry->type, kvm_trace_symbol_mmio), __entry->len, __entry->gpa, __entry->val) ); +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.5 ^ permalink raw reply related [flat|nested] 40+ messages in thread
* Re: [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-16 9:32 ` [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport Xiao Guangrong @ 2012-01-16 9:38 ` Avi Kivity 2012-01-17 2:28 ` Xiao Guangrong 0 siblings, 1 reply; 40+ messages in thread From: Avi Kivity @ 2012-01-16 9:38 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 11:32 AM, Xiao Guangrong wrote: > - trace vcpu_id for these events We can infer the vcpu id from the kvm_entry tracepoints, no? > - add kvm_mmio_done to trace the time when mmio/ioport emulation is completed ditto? Relying on the existing tracepoints will make the tool work on older kernels. -- error compiling committee.c: too many arguments to function ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-16 9:38 ` Avi Kivity @ 2012-01-17 2:28 ` Xiao Guangrong 2012-01-17 11:55 ` Marcelo Tosatti 2012-01-24 12:44 ` Avi Kivity 0 siblings, 2 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-01-17 2:28 UTC (permalink / raw) To: Avi Kivity; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 05:38 PM, Avi Kivity wrote: > On 01/16/2012 11:32 AM, Xiao Guangrong wrote: >> - trace vcpu_id for these events > > We can infer the vcpu id from the kvm_entry tracepoints, no? > Thanks for your review, Avi! Hmm. i think it is hard to do since the vcpu thread can be scheduled anytime, one example is as follow: CPU 0 kvm_entry vcpu 0 ...... kvm_entry vcpu 1 ...... event1 occurs ...... event2 occurs It is hard to know the event belong to which kvm_entry? >> - add kvm_mmio_done to trace the time when mmio/ioport emulation is completed > > ditto? > I think is ok to get the event end time by using kvm_entry. > > Relying on the existing tracepoints will make the tool work on older > kernels. > We can drop all new events, but unfortunately, the information of the origin tracepoints is not enough, at least vcpu_id need be traced in theses events to match its events. Yes? ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-17 2:28 ` Xiao Guangrong @ 2012-01-17 11:55 ` Marcelo Tosatti 2012-01-17 17:31 ` David Ahern 2012-01-24 12:44 ` Avi Kivity 1 sibling, 1 reply; 40+ messages in thread From: Marcelo Tosatti @ 2012-01-17 11:55 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Avi Kivity, LKML, KVM On Tue, Jan 17, 2012 at 10:28:11AM +0800, Xiao Guangrong wrote: > On 01/16/2012 05:38 PM, Avi Kivity wrote: > > > On 01/16/2012 11:32 AM, Xiao Guangrong wrote: > >> - trace vcpu_id for these events > > > > We can infer the vcpu id from the kvm_entry tracepoints, no? > > > > > Thanks for your review, Avi! > > Hmm. i think it is hard to do since the vcpu thread can be scheduled > anytime, one example is as follow: > > CPU 0 > > kvm_entry vcpu 0 > ...... > kvm_entry vcpu 1 > ...... > event1 occurs > ...... > event2 occurs > > It is hard to know the event belong to which kvm_entry? > > >> - add kvm_mmio_done to trace the time when mmio/ioport emulation is completed > > > > ditto? > > > > > I think is ok to get the event end time by using kvm_entry. > > > > > Relying on the existing tracepoints will make the tool work on older > > kernels. > > > > > We can drop all new events, but unfortunately, the information of the origin > tracepoints is not enough, at least vcpu_id need be traced in theses events > to match its events. Yes? Yes, and if you don't add completed events, you'll have to use kvm_entry whose collection adds a lot of overhead. ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-17 11:55 ` Marcelo Tosatti @ 2012-01-17 17:31 ` David Ahern 2012-01-18 2:32 ` Xiao Guangrong 0 siblings, 1 reply; 40+ messages in thread From: David Ahern @ 2012-01-17 17:31 UTC (permalink / raw) To: Marcelo Tosatti, Xiao Guangrong; +Cc: Avi Kivity, LKML, KVM On 01/17/2012 04:55 AM, Marcelo Tosatti wrote: > On Tue, Jan 17, 2012 at 10:28:11AM +0800, Xiao Guangrong wrote: >> On 01/16/2012 05:38 PM, Avi Kivity wrote: >> >>> On 01/16/2012 11:32 AM, Xiao Guangrong wrote: >>>> - trace vcpu_id for these events >>> >>> We can infer the vcpu id from the kvm_entry tracepoints, no? >>> >> >> >> Thanks for your review, Avi! >> >> Hmm. i think it is hard to do since the vcpu thread can be scheduled >> anytime, one example is as follow: >> >> CPU 0 >> >> kvm_entry vcpu 0 >> ...... >> kvm_entry vcpu 1 >> ...... >> event1 occurs >> ...... >> event2 occurs >> >> It is hard to know the event belong to which kvm_entry? >> >>>> - add kvm_mmio_done to trace the time when mmio/ioport emulation is completed >>> >>> ditto? >>> >> >> >> I think is ok to get the event end time by using kvm_entry. >> >>> >>> Relying on the existing tracepoints will make the tool work on older >>> kernels. >>> >> >> >> We can drop all new events, but unfortunately, the information of the origin >> tracepoints is not enough, at least vcpu_id need be traced in theses events >> to match its events. Yes? > > Yes, and if you don't add completed events, you'll have to use kvm_entry > whose collection adds a lot of overhead. vcpus run as threads and hence have their own tid which is available in the perf samples. There is an ongoing 'discussion' about modifying existing tracepoints which your proposed patch violates. This is the start of it: https://lkml.org/lkml/2012/1/16/41 David ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-17 17:31 ` David Ahern @ 2012-01-18 2:32 ` Xiao Guangrong 2012-01-18 5:34 ` David Ahern 0 siblings, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-01-18 2:32 UTC (permalink / raw) To: David Ahern; +Cc: Marcelo Tosatti, Avi Kivity, LKML, KVM On 01/18/2012 01:31 AM, David Ahern wrote: >>>> >>>> Relying on the existing tracepoints will make the tool work on older >>>> kernels. >>>> >>> >>> >>> We can drop all new events, but unfortunately, the information of the origin >>> tracepoints is not enough, at least vcpu_id need be traced in theses events >>> to match its events. Yes? >> >> Yes, and if you don't add completed events, you'll have to use kvm_entry >> whose collection adds a lot of overhead. > > > vcpus run as threads and hence have their own tid which is available in > the perf samples. > Nice, thanks for your information, David! > There is an ongoing 'discussion' about modifying existing tracepoints > which your proposed patch violates. This is the start of it: > Hmm, i think we can still add completed tracepoints in the new version kernel, if old version kernel is used, we can fall back to use kvm_entry instead? And there is a exception for mmio read, in current code, the mmio read event is actually used to trace the time when then read emulation is completed, i think we can add a tracepoint like mmio_read_begin to trace the start time of mmio read. So: - for the new kernel, we use mmio_read_begion and kvm_mmio(READ...) to calculate start time and end time. - for the old kernel, we use kvm_exit and kvm_mmio(READ...) to calculate start time and end time. Your idea? ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-18 2:32 ` Xiao Guangrong @ 2012-01-18 5:34 ` David Ahern 0 siblings, 0 replies; 40+ messages in thread From: David Ahern @ 2012-01-18 5:34 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Marcelo Tosatti, Avi Kivity, LKML, KVM On 01/17/2012 07:32 PM, Xiao Guangrong wrote: >> There is an ongoing 'discussion' about modifying existing tracepoints >> which your proposed patch violates. This is the start of it: >> > > > Hmm, i think we can still add completed tracepoints in the new version kernel, > if old version kernel is used, we can fall back to use kvm_entry instead? Yes, new ones are ok. I was referring to the tracepoints like kvm_pio where you added the vcpu_id. And it is not really necessary: with kvm_entry tracepoints it is easy to correlate vcpu to tid and even without you still get thread base samples so events happening on a thread are all the sample vcpu (even if you don't know whether that is vcpu 0, 1, 2, etc). > > And there is a exception for mmio read, in current code, the mmio read event is > actually used to trace the time when then read emulation is completed, i think > we can add a tracepoint like mmio_read_begin to trace the start time of mmio read. > So: > - for the new kernel, we use mmio_read_begion and kvm_mmio(READ...) to calculate > start time and end time. > - for the old kernel, we use kvm_exit and kvm_mmio(READ...) to calculate start time > and end time. > > Your idea? > I did play around with it a bit more today. My concern would be adding more events may make things more precise, but it adds more overhead and I am not sure the precision is worth it. For example on my laptop (Penryn Core 2; a lab server with a xeon E5560 processor is much faster): 0.000002 kvm_exit reason IO_INSTRUCTION rip 0x806d0e30 info 710048 0 0.000003 kvm_emulate_insn 0:806d0e30: e4 71 0.000001 kvm_pio pio_read at 0x71 size 1 count 1 0.000001 kvm_userspace_exit reason KVM_EXIT_IO (2) 0.000003 kvm_set_irq gsi 8 level 0 source 0 0.000001 kvm_pic_set_irq chip 1 pin 0 (edge|masked) 0.000001 kvm_ioapic_set_irq pin 8 dst 1 vec=209 (Fixed|logical|edge) total exit time: 0.000016 The first column is the delta-time between successive events for a vcpu. Most of those events are in the rounded up microsecond range. Moving on to the subsequent kvm_entry shows a total VMENTRY run time of 5 usecs: ie., 16 usecs on a VMEXIT with 7 tracepoints and 5 usecs spent in a VMENTRY. What I am getting at is that the cost of the tracepoints becomes a significant overhead. If it costs 500nsec or 1usec to generate an event and the time in a VMENTRY is only 5 usecs the tracepoint is a large part of the time. David ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport 2012-01-17 2:28 ` Xiao Guangrong 2012-01-17 11:55 ` Marcelo Tosatti @ 2012-01-24 12:44 ` Avi Kivity 1 sibling, 0 replies; 40+ messages in thread From: Avi Kivity @ 2012-01-24 12:44 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Marcelo Tosatti, LKML, KVM On 01/17/2012 04:28 AM, Xiao Guangrong wrote: > On 01/16/2012 05:38 PM, Avi Kivity wrote: > > > On 01/16/2012 11:32 AM, Xiao Guangrong wrote: > >> - trace vcpu_id for these events > > > > We can infer the vcpu id from the kvm_entry tracepoints, no? > > > > > Thanks for your review, Avi! > > Hmm. i think it is hard to do since the vcpu thread can be scheduled > anytime, one example is as follow: > > CPU 0 > > kvm_entry vcpu 0 > ...... > kvm_entry vcpu 1 > ...... > event1 occurs > ...... > event2 occurs > > It is hard to know the event belong to which kvm_entry? > Why is it hard? Correlate the task IDs. -- error compiling committee.c: too many arguments to function ^ permalink raw reply [flat|nested] 40+ messages in thread
* [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-16 9:30 [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Xiao Guangrong 2012-01-16 9:31 ` [PATCH 1/3] KVM: trace mmio read event properly Xiao Guangrong 2012-01-16 9:32 ` [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport Xiao Guangrong @ 2012-01-16 9:32 ` Xiao Guangrong 2012-01-16 10:04 ` Avi Kivity 2012-01-16 10:08 ` Stefan Hajnoczi 2012-01-16 10:11 ` [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Avi Kivity 2012-01-16 22:53 ` David Ahern 4 siblings, 2 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-01-16 9:32 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly Usage: perf kvm-events record perf kvm-events report Signed-off-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com> --- tools/perf/Documentation/perf-kvm-events.txt | 54 ++ tools/perf/Makefile | 1 + tools/perf/builtin-kvm-events.c | 860 ++++++++++++++++++++++++++ tools/perf/builtin.h | 1 + tools/perf/perf.c | 1 + 5 files changed, 917 insertions(+), 0 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..73bcb82 --- /dev/null +++ b/tools/perf/Documentation/perf-kvm-events.txt @@ -0,0 +1,54 @@ +perf-kvm-events(1) +============ + +NAME +---- +perf-kvm-events - Analyze kvm events + +SYNOPSIS +-------- +[verse] +'perf kvm-events' {record|report} + +DESCRIPTION +----------- +You can analyze some crucial events and statistics with this +'perf kvm-events' command. + + 'perf kvm-events record <command>' records kvm 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. + +COMMON OPTIONS +-------------- + +-i:: +--input=<file>:: + Input file name. (default: perf.data unless stdin is a fifo) + +-v:: +--verbose:: + Be more verbose (show symbol address, etc). + +-D:: +--dump-raw-trace:: + Dump raw trace in ASCII. + +REPORT OPTIONS +-------------- +--vcpu=<value>:: + analyze events which occures on this vcpu + +--events=<value>:: + events to be analyzed. Possible values: vmexit, mmio, ioport. +-k:: +--key=<value>:: + Sorting key. Possible values: sample(default, sort by samples number), +time(sort by 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..55dc680 --- /dev/null +++ b/tools/perf/builtin-kvm-events.c @@ -0,0 +1,860 @@ +#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/session.h" +#include "util/tool.h" + +#include <linux/hash.h> + +/* + * Todo: improve the print format of kvm_exit to let it is easier + * parsed by perf, then we can get the exit reason from print + * format directly. + */ +#define EXIT_REASON_EXCEPTION_NMI 0 +#define EXIT_REASON_EXTERNAL_INTERRUPT 1 +#define EXIT_REASON_TRIPLE_FAULT 2 + +#define EXIT_REASON_PENDING_INTERRUPT 7 +#define EXIT_REASON_NMI_WINDOW 8 +#define EXIT_REASON_TASK_SWITCH 9 +#define EXIT_REASON_CPUID 10 +#define EXIT_REASON_HLT 12 +#define EXIT_REASON_INVD 13 +#define EXIT_REASON_INVLPG 14 +#define EXIT_REASON_RDPMC 15 +#define EXIT_REASON_RDTSC 16 +#define EXIT_REASON_VMCALL 18 +#define EXIT_REASON_VMCLEAR 19 +#define EXIT_REASON_VMLAUNCH 20 +#define EXIT_REASON_VMPTRLD 21 +#define EXIT_REASON_VMPTRST 22 +#define EXIT_REASON_VMREAD 23 +#define EXIT_REASON_VMRESUME 24 +#define EXIT_REASON_VMWRITE 25 +#define EXIT_REASON_VMOFF 26 +#define EXIT_REASON_VMON 27 +#define EXIT_REASON_CR_ACCESS 28 +#define EXIT_REASON_DR_ACCESS 29 +#define EXIT_REASON_IO_INSTRUCTION 30 +#define EXIT_REASON_MSR_READ 31 +#define EXIT_REASON_MSR_WRITE 32 +#define EXIT_REASON_INVALID_STATE 33 +#define EXIT_REASON_MWAIT_INSTRUCTION 36 +#define EXIT_REASON_MONITOR_INSTRUCTION 39 +#define EXIT_REASON_PAUSE_INSTRUCTION 40 +#define EXIT_REASON_MCE_DURING_VMENTRY 41 +#define EXIT_REASON_TPR_BELOW_THRESHOLD 43 +#define EXIT_REASON_APIC_ACCESS 44 +#define EXIT_REASON_EPT_VIOLATION 48 +#define EXIT_REASON_EPT_MISCONFIG 49 +#define EXIT_REASON_WBINVD 54 +#define EXIT_REASON_XSETBV 55 + +#define SVM_EXIT_READ_CR0 0x000 +#define SVM_EXIT_READ_CR3 0x003 +#define SVM_EXIT_READ_CR4 0x004 +#define SVM_EXIT_READ_CR8 0x008 +#define SVM_EXIT_WRITE_CR0 0x010 +#define SVM_EXIT_WRITE_CR3 0x013 +#define SVM_EXIT_WRITE_CR4 0x014 +#define SVM_EXIT_WRITE_CR8 0x018 +#define SVM_EXIT_READ_DR0 0x020 +#define SVM_EXIT_READ_DR1 0x021 +#define SVM_EXIT_READ_DR2 0x022 +#define SVM_EXIT_READ_DR3 0x023 +#define SVM_EXIT_READ_DR4 0x024 +#define SVM_EXIT_READ_DR5 0x025 +#define SVM_EXIT_READ_DR6 0x026 +#define SVM_EXIT_READ_DR7 0x027 +#define SVM_EXIT_WRITE_DR0 0x030 +#define SVM_EXIT_WRITE_DR1 0x031 +#define SVM_EXIT_WRITE_DR2 0x032 +#define SVM_EXIT_WRITE_DR3 0x033 +#define SVM_EXIT_WRITE_DR4 0x034 +#define SVM_EXIT_WRITE_DR5 0x035 +#define SVM_EXIT_WRITE_DR6 0x036 +#define SVM_EXIT_WRITE_DR7 0x037 +#define SVM_EXIT_EXCP_BASE 0x040 +#define SVM_EXIT_INTR 0x060 +#define SVM_EXIT_NMI 0x061 +#define SVM_EXIT_SMI 0x062 +#define SVM_EXIT_INIT 0x063 +#define SVM_EXIT_VINTR 0x064 +#define SVM_EXIT_CR0_SEL_WRITE 0x065 +#define SVM_EXIT_IDTR_READ 0x066 +#define SVM_EXIT_GDTR_READ 0x067 +#define SVM_EXIT_LDTR_READ 0x068 +#define SVM_EXIT_TR_READ 0x069 +#define SVM_EXIT_IDTR_WRITE 0x06a +#define SVM_EXIT_GDTR_WRITE 0x06b +#define SVM_EXIT_LDTR_WRITE 0x06c +#define SVM_EXIT_TR_WRITE 0x06d +#define SVM_EXIT_RDTSC 0x06e +#define SVM_EXIT_RDPMC 0x06f +#define SVM_EXIT_PUSHF 0x070 +#define SVM_EXIT_POPF 0x071 +#define SVM_EXIT_CPUID 0x072 +#define SVM_EXIT_RSM 0x073 +#define SVM_EXIT_IRET 0x074 +#define SVM_EXIT_SWINT 0x075 +#define SVM_EXIT_INVD 0x076 +#define SVM_EXIT_PAUSE 0x077 +#define SVM_EXIT_HLT 0x078 +#define SVM_EXIT_INVLPG 0x079 +#define SVM_EXIT_INVLPGA 0x07a +#define SVM_EXIT_IOIO 0x07b +#define SVM_EXIT_MSR 0x07c +#define SVM_EXIT_TASK_SWITCH 0x07d +#define SVM_EXIT_FERR_FREEZE 0x07e +#define SVM_EXIT_SHUTDOWN 0x07f +#define SVM_EXIT_VMRUN 0x080 +#define SVM_EXIT_VMMCALL 0x081 +#define SVM_EXIT_VMLOAD 0x082 +#define SVM_EXIT_VMSAVE 0x083 +#define SVM_EXIT_STGI 0x084 +#define SVM_EXIT_CLGI 0x085 +#define SVM_EXIT_SKINIT 0x086 +#define SVM_EXIT_RDTSCP 0x087 +#define SVM_EXIT_ICEBP 0x088 +#define SVM_EXIT_WBINVD 0x089 +#define SVM_EXIT_MONITOR 0x08a +#define SVM_EXIT_MWAIT 0x08b +#define SVM_EXIT_MWAIT_COND 0x08c +#define SVM_EXIT_XSETBV 0x08d +#define SVM_EXIT_NPF 0x400 + +#define DE_VECTOR 0 +#define DB_VECTOR 1 +#define BP_VECTOR 3 +#define OF_VECTOR 4 +#define BR_VECTOR 5 +#define UD_VECTOR 6 +#define NM_VECTOR 7 +#define DF_VECTOR 8 +#define TS_VECTOR 10 +#define NP_VECTOR 11 +#define SS_VECTOR 12 +#define GP_VECTOR 13 +#define PF_VECTOR 14 +#define MF_VECTOR 16 +#define MC_VECTOR 18 + + +#define VMX_EXIT_REASONS \ + { EXIT_REASON_EXCEPTION_NMI, "EXCEPTION_NMI" }, \ + { EXIT_REASON_EXTERNAL_INTERRUPT, "EXTERNAL_INTERRUPT" }, \ + { EXIT_REASON_TRIPLE_FAULT, "TRIPLE_FAULT" }, \ + { EXIT_REASON_PENDING_INTERRUPT, "PENDING_INTERRUPT" }, \ + { EXIT_REASON_NMI_WINDOW, "NMI_WINDOW" }, \ + { EXIT_REASON_TASK_SWITCH, "TASK_SWITCH" }, \ + { EXIT_REASON_CPUID, "CPUID" }, \ + { EXIT_REASON_HLT, "HLT" }, \ + { EXIT_REASON_INVLPG, "INVLPG" }, \ + { EXIT_REASON_RDPMC, "RDPMC" }, \ + { EXIT_REASON_RDTSC, "RDTSC" }, \ + { EXIT_REASON_VMCALL, "VMCALL" }, \ + { EXIT_REASON_VMCLEAR, "VMCLEAR" }, \ + { EXIT_REASON_VMLAUNCH, "VMLAUNCH" }, \ + { EXIT_REASON_VMPTRLD, "VMPTRLD" }, \ + { EXIT_REASON_VMPTRST, "VMPTRST" }, \ + { EXIT_REASON_VMREAD, "VMREAD" }, \ + { EXIT_REASON_VMRESUME, "VMRESUME" }, \ + { EXIT_REASON_VMWRITE, "VMWRITE" }, \ + { EXIT_REASON_VMOFF, "VMOFF" }, \ + { EXIT_REASON_VMON, "VMON" }, \ + { EXIT_REASON_CR_ACCESS, "CR_ACCESS" }, \ + { EXIT_REASON_DR_ACCESS, "DR_ACCESS" }, \ + { EXIT_REASON_IO_INSTRUCTION, "IO_INSTRUCTION" }, \ + { EXIT_REASON_MSR_READ, "MSR_READ" }, \ + { EXIT_REASON_MSR_WRITE, "MSR_WRITE" }, \ + { EXIT_REASON_MWAIT_INSTRUCTION, "MWAIT_INSTRUCTION" }, \ + { EXIT_REASON_MONITOR_INSTRUCTION, "MONITOR_INSTRUCTION" }, \ + { EXIT_REASON_PAUSE_INSTRUCTION, "PAUSE_INSTRUCTION" }, \ + { EXIT_REASON_MCE_DURING_VMENTRY, "MCE_DURING_VMENTRY" }, \ + { EXIT_REASON_TPR_BELOW_THRESHOLD, "TPR_BELOW_THRESHOLD" },\ + { EXIT_REASON_APIC_ACCESS, "APIC_ACCESS" }, \ + { EXIT_REASON_EPT_VIOLATION, "EPT_VIOLATION" }, \ + { EXIT_REASON_EPT_MISCONFIG, "EPT_MISCONFIG" }, \ + { EXIT_REASON_WBINVD, "WBINVD" } + +#define SVM_EXIT_REASONS \ + { SVM_EXIT_READ_CR0, "read_cr0" }, \ + { SVM_EXIT_READ_CR3, "read_cr3" }, \ + { SVM_EXIT_READ_CR4, "read_cr4" }, \ + { SVM_EXIT_READ_CR8, "read_cr8" }, \ + { SVM_EXIT_WRITE_CR0, "write_cr0" }, \ + { SVM_EXIT_WRITE_CR3, "write_cr3" }, \ + { SVM_EXIT_WRITE_CR4, "write_cr4" }, \ + { SVM_EXIT_WRITE_CR8, "write_cr8" }, \ + { SVM_EXIT_READ_DR0, "read_dr0" }, \ + { SVM_EXIT_READ_DR1, "read_dr1" }, \ + { SVM_EXIT_READ_DR2, "read_dr2" }, \ + { SVM_EXIT_READ_DR3, "read_dr3" }, \ + { SVM_EXIT_WRITE_DR0, "write_dr0" }, \ + { SVM_EXIT_WRITE_DR1, "write_dr1" }, \ + { SVM_EXIT_WRITE_DR2, "write_dr2" }, \ + { SVM_EXIT_WRITE_DR3, "write_dr3" }, \ + { SVM_EXIT_WRITE_DR5, "write_dr5" }, \ + { SVM_EXIT_WRITE_DR7, "write_dr7" }, \ + { SVM_EXIT_EXCP_BASE + DB_VECTOR, "DB excp" }, \ + { SVM_EXIT_EXCP_BASE + BP_VECTOR, "BP excp" }, \ + { SVM_EXIT_EXCP_BASE + UD_VECTOR, "UD excp" }, \ + { SVM_EXIT_EXCP_BASE + PF_VECTOR, "PF excp" }, \ + { SVM_EXIT_EXCP_BASE + NM_VECTOR, "NM excp" }, \ + { SVM_EXIT_EXCP_BASE + MC_VECTOR, "MC excp" }, \ + { SVM_EXIT_INTR, "interrupt" }, \ + { SVM_EXIT_NMI, "nmi" }, \ + { SVM_EXIT_SMI, "smi" }, \ + { SVM_EXIT_INIT, "init" }, \ + { SVM_EXIT_VINTR, "vintr" }, \ + { SVM_EXIT_CPUID, "cpuid" }, \ + { SVM_EXIT_INVD, "invd" }, \ + { SVM_EXIT_HLT, "hlt" }, \ + { SVM_EXIT_INVLPG, "invlpg" }, \ + { SVM_EXIT_INVLPGA, "invlpga" }, \ + { SVM_EXIT_IOIO, "io" }, \ + { SVM_EXIT_MSR, "msr" }, \ + { SVM_EXIT_TASK_SWITCH, "task_switch" }, \ + { SVM_EXIT_SHUTDOWN, "shutdown" }, \ + { SVM_EXIT_VMRUN, "vmrun" }, \ + { SVM_EXIT_VMMCALL, "hypercall" }, \ + { SVM_EXIT_VMLOAD, "vmload" }, \ + { SVM_EXIT_VMSAVE, "vmsave" }, \ + { SVM_EXIT_STGI, "stgi" }, \ + { SVM_EXIT_CLGI, "clgi" }, \ + { SVM_EXIT_SKINIT, "skinit" }, \ + { SVM_EXIT_WBINVD, "wbinvd" }, \ + { SVM_EXIT_MONITOR, "monitor" }, \ + { SVM_EXIT_MWAIT, "mwait" }, \ + { SVM_EXIT_XSETBV, "xsetbv" }, \ + { SVM_EXIT_NPF, "npf" } + +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(long isa, u64 exit_code) +{ + 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("unkonw kvm exit code:%ld on %s\n", exit_code, isa == 1 ? + "VMX" : "SVM"); +} + +struct event_key { + u64 key; + int info; +}; + +struct kvm_events_ops { + bool (*is_begain_event)(struct event *event, void *data); + bool (*is_end_event)(struct event *event); + struct event_key (*get_key)(struct event *event, void *data); + void (*decode_key)(struct event_key *key, char decode[20]); + const char *name; +}; + +static bool exit_event_begain(struct event *event, void *data __unused) +{ + return !strcmp(event->name, "kvm_exit"); +} + +static bool exit_event_end(struct event *event) +{ + return !strcmp(event->name, "kvm_entry"); +} + +static struct event_key exit_event_get_key(struct event *event, void *data) +{ + struct event_key key; + + key.key = raw_field_value(event, "exit_reason", data); + key.info = raw_field_value(event, "isa", data); + return key; +} + +static void exit_event_decode_key(struct event_key *key, char decode[20]) +{ + const char *exit_reason = get_exit_reason(key->info, key->key); + + memset(decode, 0, 20); + strncpy(decode, exit_reason, 20); +} + +static struct kvm_events_ops exit_events = { + .is_begain_event = exit_event_begain, + .is_end_event = exit_event_end, + .get_key = exit_event_get_key, + .decode_key = exit_event_decode_key, + .name = "VM-EXIT" +}; + +#define KVM_TRACE_MMIO_READ_UNSATISFIED 0 +#define KVM_TRACE_MMIO_READ 1 +#define KVM_TRACE_MMIO_WRITE 2 +static bool mmio_event_begain(struct event *event, void *data) +{ + if (!strcmp(event->name, "kvm_mmio")) { + long type = raw_field_value(event, "type", data); + + if (type != KVM_TRACE_MMIO_READ_UNSATISFIED) + return true; + }; + + return false; +} + +static bool mmio_event_end(struct event *event) +{ + return !strcmp(event->name, "kvm_mmio_done"); +} + +static struct event_key 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); + + return key; +} + +static void mmio_event_decode_key(struct event_key *key, char decode[20]) +{ + memset(decode, 0, 20); + sprintf(decode, "%#lx:%s", key->key, + key->info == KVM_TRACE_MMIO_READ ? "R" : "W"); +} + +static struct kvm_events_ops mmio_events = { + .is_begain_event = mmio_event_begain, + .is_end_event = mmio_event_end, + .get_key = mmio_event_get_key, + .decode_key = mmio_event_decode_key, + .name = "MMIO Access" +}; + +static bool ioport_event_begain(struct event *event, void *data __unused) +{ + return !strcmp(event->name, "kvm_pio"); +} + +static struct event_key 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); + + return key; +} + +static void ioport_event_decode_key(struct event_key *key, char decode[20]) +{ + memset(decode, 0, 20); + sprintf(decode, "%#lx:%s", key->key, key->info ? "POUT" : "PIN"); +} + +static struct kvm_events_ops ioport_events = { + .is_begain_event = ioport_event_begain, + .is_end_event = mmio_event_end, + .get_key = ioport_event_get_key, + .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); +} + +#define KVM_MAX_VCPUS 254 + +struct kvm_event { + struct list_head hash_entry; + struct rb_node rb; + + u64 count; + u64 time; + struct { + u64 count; + u64 time; + } vcpu[KVM_MAX_VCPUS]; + + struct event_key key; +}; + +struct { + u64 start_time; + struct kvm_event *last_event; +} vcpu_event_record[KVM_MAX_VCPUS] ; + +#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 < KVM_MAX_VCPUS; i++) + vcpu_event_record[i].last_event = NULL; + + 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 hash_long((unsigned long)key, EVENTS_BITS); +} + +static void kvm_event_init(struct kvm_event *event, struct event_key *key) +{ + event->key = *key; +} + +static struct kvm_event *find_create_kvm_event(struct event_key *key) +{ + struct kvm_event *event; + struct list_head *head; + + 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 = zalloc(sizeof(*event)); + if (!event) + die("Not enough memory\n"); + + kvm_event_init(event, key); + list_add(&event->hash_entry, head); + return event; +} + +static void handle_begain_event(struct event_key *key, int vcpu_id, + u64 timestamp) +{ + struct kvm_event *event = find_create_kvm_event(key); + + vcpu_event_record[vcpu_id].last_event = event; + vcpu_event_record[vcpu_id].start_time = timestamp; +} + +static void update_kvm_event(struct kvm_event *event, int vcpu_id, + u64 time_diff) +{ + event->count++; + event->time += time_diff; + event->vcpu[vcpu_id].count++; + event->vcpu[vcpu_id].time += time_diff; +} + +static void handle_end_event(int vcpu_id, u64 timestamp) +{ + u64 time_begain, time_diff; + struct kvm_event *event; + + event = vcpu_event_record[vcpu_id].last_event; + if (!event) + return; + + time_begain = vcpu_event_record[vcpu_id].start_time; + + vcpu_event_record[vcpu_id].last_event = NULL; + vcpu_event_record[vcpu_id].start_time = 0; + + BUG_ON(!time_begain || timestamp < time_begain); + + time_diff = timestamp - time_begain; + update_kvm_event(event, vcpu_id, time_diff); +} + +static int get_vcpu_id(struct event *event, void *data) +{ + return raw_field_value(event, "vcpu_id", data); +} + +static void handle_kvm_event(struct event *event, void *data, u64 timestamp) +{ + int vcpu_id; + + if (events_ops->is_begain_event(event, data)) { + struct event_key key = events_ops->get_key(event, data); + + vcpu_id = get_vcpu_id(event, data); + return handle_begain_event(&key, vcpu_id, timestamp); + } + + if (events_ops->is_end_event(event)) { + vcpu_id = get_vcpu_id(event, data); + return handle_end_event(vcpu_id, 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 COMPARE_EVENT_KEY(member) \ +static u64 get_event_ ##member(struct kvm_event *event, int vcpu) \ +{ \ + if (vcpu == -1) \ + return event->member; \ + \ + return event->vcpu[vcpu].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);\ +} + +COMPARE_EVENT_KEY(count); +COMPARE_EVENT_KEY(time); + +#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, time), + { 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("%13s ", "Samples%"); + + pr_info("%13s ", "Time%"); + pr_info("%15s ", "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("%12.2f%% ", (double)ecount / total_count * 100); + pr_info("%12.2f%%", (double)etime / total_time * 100); + pr_info("%13.2fus ", (double)etime / ecount/1e3); + 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(void *data, int __unused cpu, u64 timestamp, + struct thread *thread __unused) +{ + struct event *event; + int type; + + type = trace_parse_common_type(data); + event = trace_find_event(type); + + return handle_kvm_event(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(sample->raw_data, sample->cpu, sample->time, thread); + + 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 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; + + return perf_session__process_events(session, &eops); +} + +static void verify_vcpu(int vcpu) +{ + if (vcpu != -1 && (vcpu > KVM_MAX_VCPUS || vcpu < 0)) + die("Unknow vcpu:%d.\n", vcpu); + +} + +static int kvm_events_report(int vcpu) +{ + verify_vcpu(vcpu); + select_key(); + register_kvm_events_ops(); + init_kvm_event_record(); + 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_mmio_done", + "-e", "kvm:kvm_pio" +}; + +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_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 = 1; j < (unsigned int)argc; j++, i++) + rec_argv[i] = argv[j]; + + BUG_ON(i != rec_argc); + + 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 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_INCR('v', "verbose", &verbose, + "be more verbose (show symbol address, etc)"), + 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], "report", 6)) { + 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/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 }, }; -- 1.7.7.5 ^ permalink raw reply related [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-16 9:32 ` [PATCH 3/3] KVM: perf: kvm events analysis tool Xiao Guangrong @ 2012-01-16 10:04 ` Avi Kivity 2012-01-17 2:30 ` Xiao Guangrong 2012-01-16 10:08 ` Stefan Hajnoczi 1 sibling, 1 reply; 40+ messages in thread From: Avi Kivity @ 2012-01-16 10:04 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 11:32 AM, Xiao Guangrong wrote: > Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly > > Usage: > perf kvm-events record Why not 'perf record -e kvm'? > perf kvm-events report > +static const char *get_exit_reason(long isa, u64 exit_code) > +{ > + 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[exit_code] ... > + table++; > + } > + > + die("unkonw kvm exit code:%ld on %s\n", exit_code, isa == 1 ? > + "VMX" : "SVM"); "unknown" > + > +struct kvm_events_ops { > + bool (*is_begain_event)(struct event *event, void *data); begin > + bool (*is_end_event)(struct event *event); > + struct event_key (*get_key)(struct event *event, void *data); > + void (*decode_key)(struct event_key *key, char decode[20]); > + const char *name; > +}; > + > + > +static struct event_key exit_event_get_key(struct event *event, void *data) > +{ > + struct event_key key; > + > + key.key = raw_field_value(event, "exit_reason", data); > + key.info = raw_field_value(event, "isa", data); "isa" is not available on all kernel versions; need to fall back to /proc/cpuid detection. > + return key; > +} > -- error compiling committee.c: too many arguments to function ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-16 10:04 ` Avi Kivity @ 2012-01-17 2:30 ` Xiao Guangrong 2012-01-24 12:49 ` Avi Kivity 0 siblings, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-01-17 2:30 UTC (permalink / raw) To: Avi Kivity; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 06:04 PM, Avi Kivity wrote: > On 01/16/2012 11:32 AM, Xiao Guangrong wrote: >> Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly >> >> Usage: >> perf kvm-events record > > Why not 'perf record -e kvm'? It works, many perf tools have this style, like: perf lock record, perf sched record, perf kmem record, I think the reason is that only enable the tracepoints we need to avoid unnecessary overload so that the result is more exacter. > >> perf kvm-events report > > > >> +static const char *get_exit_reason(long isa, u64 exit_code) >> +{ >> + 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[exit_code] ... > Actually, this array is not indexed by exit_code, it means: table[exit_code].exit_code != exit_code. >> + table++; >> + } >> + >> + die("unkonw kvm exit code:%ld on %s\n", exit_code, isa == 1 ? >> + "VMX" : "SVM"); > > "unknown" > ...... >> + >> +struct kvm_events_ops { >> + bool (*is_begain_event)(struct event *event, void *data); > > begin > Sorry for my careless. >> + bool (*is_end_event)(struct event *event); >> + struct event_key (*get_key)(struct event *event, void *data); >> + void (*decode_key)(struct event_key *key, char decode[20]); >> + const char *name; >> +}; >> + >> + >> +static struct event_key exit_event_get_key(struct event *event, void *data) >> +{ >> + struct event_key key; >> + >> + key.key = raw_field_value(event, "exit_reason", data); >> + key.info = raw_field_value(event, "isa", data); > > "isa" is not available on all kernel versions; need to fall back to > /proc/cpuid detection. > Got it, will do it in the next version. Thanks Avi! ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-17 2:30 ` Xiao Guangrong @ 2012-01-24 12:49 ` Avi Kivity 0 siblings, 0 replies; 40+ messages in thread From: Avi Kivity @ 2012-01-24 12:49 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Marcelo Tosatti, LKML, KVM On 01/17/2012 04:30 AM, Xiao Guangrong wrote: > On 01/16/2012 06:04 PM, Avi Kivity wrote: > > > On 01/16/2012 11:32 AM, Xiao Guangrong wrote: > >> Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly > >> > >> Usage: > >> perf kvm-events record > > > > Why not 'perf record -e kvm'? > > > It works, many perf tools have this style, like: > perf lock record, > perf sched record, > perf kmem record, > > I think the reason is that only enable the tracepoints we need to avoid > unnecessary overload so that the result is more exacter. Maybe a virtual event list: perf record -e kvm-pio This allows us to combine the event list with other events: perf record -e kvm-pio -e timer > >> + > >> + while (table_size--) { > >> + if (table->exit_code == exit_code) > >> + return table->reason; > > > > ... table[exit_code] ... > > > > > Actually, this array is not indexed by exit_code, it means: > table[exit_code].exit_code != exit_code. So make it indexed by exit code. -- error compiling committee.c: too many arguments to function ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-16 9:32 ` [PATCH 3/3] KVM: perf: kvm events analysis tool Xiao Guangrong 2012-01-16 10:04 ` Avi Kivity @ 2012-01-16 10:08 ` Stefan Hajnoczi 2012-01-17 2:37 ` Xiao Guangrong 2012-01-17 11:59 ` Marcelo Tosatti 1 sibling, 2 replies; 40+ messages in thread From: Stefan Hajnoczi @ 2012-01-16 10:08 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM On Mon, Jan 16, 2012 at 9:32 AM, Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com> wrote: > +DESCRIPTION > +----------- > +You can analyze some crucial events and statistics with this > +'perf kvm-events' command. This line is very general and does not explain which events/statistics can be collected or how you can use that information. I suggest making this description more specific. Explain that this subcommand observers kvm.ko tracepoints and annotates/decodes them with additional information (this is why I would use this command and not raw perf record -e kvm:\*). > + { SVM_EXIT_MONITOR, "monitor" }, \ > + { SVM_EXIT_MWAIT, "mwait" }, \ > + { SVM_EXIT_XSETBV, "xsetbv" }, \ > + { SVM_EXIT_NPF, "npf" } All this copy-paste could be avoided by sharing this stuff with the arch/x86/kvm/ code. > +static void exit_event_decode_key(struct event_key *key, char decode[20]) > +{ > + const char *exit_reason = get_exit_reason(key->info, key->key); > + > + memset(decode, 0, 20); > + strncpy(decode, exit_reason, 20); This is a bad pattern to follow when using strncpy(3) because if there was a strlen(exit_reason) == 20 string then decode[] would not be NUL-terminated. Right now it's safe but it's better to just use strlcpy() and drop the memset(3). > +} > + > +static struct kvm_events_ops exit_events = { > + .is_begain_event = exit_event_begain, > + .is_end_event = exit_event_end, > + .get_key = exit_event_get_key, > + .decode_key = exit_event_decode_key, > + .name = "VM-EXIT" > +}; > + > +#define KVM_TRACE_MMIO_READ_UNSATISFIED 0 > +#define KVM_TRACE_MMIO_READ 1 > +#define KVM_TRACE_MMIO_WRITE 2 > +static bool mmio_event_begain(struct event *event, void *data) > +{ > + if (!strcmp(event->name, "kvm_mmio")) { > + long type = raw_field_value(event, "type", data); > + > + if (type != KVM_TRACE_MMIO_READ_UNSATISFIED) > + return true; > + }; > + > + return false; > +} > + > +static bool mmio_event_end(struct event *event) > +{ > + return !strcmp(event->name, "kvm_mmio_done"); > +} > + > +static struct event_key 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); > + > + return key; > +} > + > +static void mmio_event_decode_key(struct event_key *key, char decode[20]) > +{ > + memset(decode, 0, 20); > + sprintf(decode, "%#lx:%s", key->key, > + key->info == KVM_TRACE_MMIO_READ ? "R" : "W"); Please drop the memset and use snprintf(3) instead of sprintf(3). It places the NUL-terminator and ensures you don't exceed the buffer size. Same pattern below. ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-16 10:08 ` Stefan Hajnoczi @ 2012-01-17 2:37 ` Xiao Guangrong 2012-01-17 11:59 ` Marcelo Tosatti 1 sibling, 0 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-01-17 2:37 UTC (permalink / raw) To: Stefan Hajnoczi; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM On 01/16/2012 06:08 PM, Stefan Hajnoczi wrote: > On Mon, Jan 16, 2012 at 9:32 AM, Xiao Guangrong > <xiaoguangrong@linux.vnet.ibm.com> wrote: >> +DESCRIPTION >> +----------- >> +You can analyze some crucial events and statistics with this >> +'perf kvm-events' command. > > This line is very general and does not explain which events/statistics > can be collected or how you can use that information. I suggest > making this description more specific. Explain that this subcommand > observers kvm.ko tracepoints and annotates/decodes them with > additional information (this is why I would use this command and not > raw perf record -e kvm:\*). > Okay. >> + � � � { SVM_EXIT_MONITOR, � � � � � � � � � � "monitor" }, \ >> + � � � { SVM_EXIT_MWAIT, � � � � � � � � � � � "mwait" }, \ >> + � � � { SVM_EXIT_XSETBV, � � � � � � � � � � �"xsetbv" }, \ >> + � � � { SVM_EXIT_NPF, � � � � � � � � � � � � "npf" } > > All this copy-paste could be avoided by sharing this stuff with the > arch/x86/kvm/ code. > I will try to combine them in the next version. >> +static void exit_event_decode_key(struct event_key *key, char decode[20]) >> +{ >> + � � � const char *exit_reason = get_exit_reason(key->info, key->key); >> + >> + � � � memset(decode, 0, 20); >> + � � � strncpy(decode, exit_reason, 20); > > This is a bad pattern to follow when using strncpy(3) because if there > was a strlen(exit_reason) == 20 string then decode[] would not be > NUL-terminated. Right now it's safe but it's better to just use > strlcpy() and drop the memset(3). > Good point. >> +static void mmio_event_decode_key(struct event_key *key, char decode[20]) >> +{ >> + � � � memset(decode, 0, 20); >> + � � � sprintf(decode, "%#lx:%s", key->key, >> + � � � � � � � key->info == KVM_TRACE_MMIO_READ ? "R" : "W"); > > Please drop the memset and use snprintf(3) instead of sprintf(3). It > places the NUL-terminator and ensures you don't exceed the buffer > size. > > Same pattern below. > Will do, thanks Stefan! :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-16 10:08 ` Stefan Hajnoczi 2012-01-17 2:37 ` Xiao Guangrong @ 2012-01-17 11:59 ` Marcelo Tosatti 2012-01-24 12:51 ` Avi Kivity 1 sibling, 1 reply; 40+ messages in thread From: Marcelo Tosatti @ 2012-01-17 11:59 UTC (permalink / raw) To: Stefan Hajnoczi; +Cc: Xiao Guangrong, Avi Kivity, LKML, KVM On Mon, Jan 16, 2012 at 10:08:40AM +0000, Stefan Hajnoczi wrote: > On Mon, Jan 16, 2012 at 9:32 AM, Xiao Guangrong > <xiaoguangrong@linux.vnet.ibm.com> wrote: > > +DESCRIPTION > > +----------- > > +You can analyze some crucial events and statistics with this > > +'perf kvm-events' command. > > This line is very general and does not explain which events/statistics > can be collected or how you can use that information. I suggest > making this description more specific. Explain that this subcommand > observers kvm.ko tracepoints and annotates/decodes them with > additional information (this is why I would use this command and not > raw perf record -e kvm:\*). > > > + { SVM_EXIT_MONITOR, "monitor" }, \ > > + { SVM_EXIT_MWAIT, "mwait" }, \ > > + { SVM_EXIT_XSETBV, "xsetbv" }, \ > > + { SVM_EXIT_NPF, "npf" } > > All this copy-paste could be avoided by sharing this stuff with the > arch/x86/kvm/ code. Yes, same for KVM_MAX_VCPUS. ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-01-17 11:59 ` Marcelo Tosatti @ 2012-01-24 12:51 ` Avi Kivity 0 siblings, 0 replies; 40+ messages in thread From: Avi Kivity @ 2012-01-24 12:51 UTC (permalink / raw) To: Marcelo Tosatti; +Cc: Stefan Hajnoczi, Xiao Guangrong, LKML, KVM On 01/17/2012 01:59 PM, Marcelo Tosatti wrote: > > > > All this copy-paste could be avoided by sharing this stuff with the > > arch/x86/kvm/ code. > > Yes, same for KVM_MAX_VCPUS. > > This is an internal define. perf kvm should work with different kernel versions, so it needs to query the value dynamically. -- error compiling committee.c: too many arguments to function ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events 2012-01-16 9:30 [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Xiao Guangrong ` (2 preceding siblings ...) 2012-01-16 9:32 ` [PATCH 3/3] KVM: perf: kvm events analysis tool Xiao Guangrong @ 2012-01-16 10:11 ` Avi Kivity 2012-01-17 2:30 ` Xiao Guangrong 2012-01-16 22:53 ` David Ahern 4 siblings, 1 reply; 40+ messages in thread From: Avi Kivity @ 2012-01-16 10:11 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 11:30 AM, Xiao Guangrong wrote: > This tool is very like xenoprof(if i remember correctly), and traces kvm events > smartly. currently, it supports vmexit/mmio/ioport events. > > Usage: > - to trace kvm events: > # ./perf kvm-events record > > - show the result > # ./perf kvm-events report > > Some output are as follow: > # ./perf kvm-events report > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' > > > Analyze events for all VCPUs: > > VM-EXIT Samples Samples% Time% Avg time > > APIC_ACCESS 438107 44.89% 6.20% 17.91us > EXTERNAL_INTERRUPT 219226 22.46% 8.01% 46.20us > IO_INSTRUCTION 122651 12.57% 1.88% 19.44us > EPT_VIOLATION 83110 8.52% 1.36% 20.75us > PENDING_INTERRUPT 37055 3.80% 0.16% 5.38us > CPUID 32718 3.35% 0.08% 3.15us > EXCEPTION_NMI 23601 2.42% 0.17% 8.87us > HLT 15424 1.58% 82.12% 6735.06us > CR_ACCESS 4089 0.42% 0.02% 6.08us > > Total Samples:975981, Total events handled time:126502464.88us. Nice! If we can have a live version as well, this can replace kvm_stat. The average numbers are really high. Like a factor of 3x-4x off. Would be good to print the standard deviation and see why. Maybe it's due to the tracing overhead. > The default event to be analysed is vmexit, we can use --event to specify it, > for example, if we want to trace mmio event: > # ./perf kvm-events report --event mmio > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' > > > Analyze events for all VCPUs: > > MMIO Access Samples Samples% Time% Avg time > > 0xfee00380:W 196589 64.95% 70.01% 3.83us > 0xfee00310:W 35356 11.68% 6.48% 1.97us > 0xfee00300:W 35356 11.68% 16.37% 4.97us > 0xfee00300:R 35356 11.68% 7.14% 2.17us These are more reasonable (though still high - 5us for an ICR write?) > > Total Samples:302657, Total events handled time:1074746.01us. > > We can use --vcpu to specify which vcpu is traced: > root@localhost perf]# ./perf kvm-events report --event mmio --vcpu 1 > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' > > > Analyze events for VCPU 1: > > MMIO Access Samples Samples% Time% Avg time > > 0xfee00380:W 58041 71.20% 74.90% 3.70us > 0xfee00310:W 7826 9.60% 5.28% 1.93us > 0xfee00300:W 7826 9.60% 13.82% 5.06us > 0xfee00300:R 7826 9.60% 6.01% 2.20us > > Total Samples:81519, Total events handled time:286577.81us. > > And, '--key' is used to sort the result, the possible value sample (default, > the result is sorted by samples number), time(the result is sorted by time%): > # ./perf kvm-events report --key time > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' > > > Analyze events for all VCPUs: > > VM-EXIT Samples Samples% Time% Avg time > > HLT 15424 1.58% 82.12% 6735.06us > EXTERNAL_INTERRUPT 219226 22.46% 8.01% 46.20us > APIC_ACCESS 438107 44.89% 6.20% 17.91us > IO_INSTRUCTION 122651 12.57% 1.88% 19.44us > EPT_VIOLATION 83110 8.52% 1.36% 20.75us > EXCEPTION_NMI 23601 2.42% 0.17% 8.87us > PENDING_INTERRUPT 37055 3.80% 0.16% 5.38us > CPUID 32718 3.35% 0.08% 3.15us > CR_ACCESS 4089 0.42% 0.02% 6.08us > > Total Samples:975981, Total events handled time:126502464.88us. > > I hope guys will like it and any comments are welcome! :) I think it's great! A live version would be a nice addition too. Please copy the perf userspace maintainers to get more detailed review in the next version. -- error compiling committee.c: too many arguments to function ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events 2012-01-16 10:11 ` [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Avi Kivity @ 2012-01-17 2:30 ` Xiao Guangrong 0 siblings, 0 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-01-17 2:30 UTC (permalink / raw) To: Avi Kivity; +Cc: Marcelo Tosatti, LKML, KVM On 01/16/2012 06:11 PM, Avi Kivity wrote: >> Total Samples:975981, Total events handled time:126502464.88us. > > Nice! If we can have a live version as well, this can replace kvm_stat. > > The average numbers are really high. Like a factor of 3x-4x off. Would > be good to print the standard deviation and see why. Maybe it's due to > the tracing overhead. > It is a good suggestion, i will print stddev in the next version. >> The default event to be analysed is vmexit, we can use --event to specify it, >> for example, if we want to trace mmio event: >> # ./perf kvm-events report --event mmio >> Warning: Error: expected type 5 but read 4 >> Warning: Error: expected type 5 but read 0 >> Warning: unknown op '}' >> >> >> Analyze events for all VCPUs: >> >> MMIO Access Samples Samples% Time% Avg time >> >> 0xfee00380:W 196589 64.95% 70.01% 3.83us >> 0xfee00310:W 35356 11.68% 6.48% 1.97us >> 0xfee00300:W 35356 11.68% 16.37% 4.97us >> 0xfee00300:R 35356 11.68% 7.14% 2.17us > > These are more reasonable (though still high - 5us for an ICR write?) > Hmm, maybe i need look into it... >> Total Samples:975981, Total events handled time:126502464.88us. >> >> I hope guys will like it and any comments are welcome! :) > > I think it's great! A live version would be a nice addition too. > > Please copy the perf userspace maintainers to get more detailed review > in the next version. > Okay, Thanks! ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events 2012-01-16 9:30 [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Xiao Guangrong ` (3 preceding siblings ...) 2012-01-16 10:11 ` [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Avi Kivity @ 2012-01-16 22:53 ` David Ahern 2012-01-17 2:41 ` Xiao Guangrong 4 siblings, 1 reply; 40+ messages in thread From: David Ahern @ 2012-01-16 22:53 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM On 01/16/2012 02:30 AM, Xiao Guangrong wrote: > This tool is very like xenoprof(if i remember correctly), and traces kvm events > smartly. currently, it supports vmexit/mmio/ioport events. > > Usage: > - to trace kvm events: > # ./perf kvm-events record > > - show the result > # ./perf kvm-events report > > Some output are as follow: > # ./perf kvm-events report > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' Integrating the trace-cmd plugins into perf will remedy the above errors: https://lkml.org/lkml/2011/8/16/352 Unfortunately, that effort is stalled at the moment. > > > Analyze events for all VCPUs: > > VM-EXIT Samples Samples% Time% Avg time > > APIC_ACCESS 438107 44.89% 6.20% 17.91us > EXTERNAL_INTERRUPT 219226 22.46% 8.01% 46.20us > IO_INSTRUCTION 122651 12.57% 1.88% 19.44us > EPT_VIOLATION 83110 8.52% 1.36% 20.75us > PENDING_INTERRUPT 37055 3.80% 0.16% 5.38us > CPUID 32718 3.35% 0.08% 3.15us > EXCEPTION_NMI 23601 2.42% 0.17% 8.87us > HLT 15424 1.58% 82.12% 6735.06us > CR_ACCESS 4089 0.42% 0.02% 6.08us > > Total Samples:975981, Total events handled time:126502464.88us. Have you thought about dumping a time history -- something similar to what perf-script can do with dumping events but adding in kvm-specific analysis like what you are doing in these examples? David > > The default event to be analysed is vmexit, we can use --event to specify it, > for example, if we want to trace mmio event: > # ./perf kvm-events report --event mmio > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' > > > Analyze events for all VCPUs: > > MMIO Access Samples Samples% Time% Avg time > > 0xfee00380:W 196589 64.95% 70.01% 3.83us > 0xfee00310:W 35356 11.68% 6.48% 1.97us > 0xfee00300:W 35356 11.68% 16.37% 4.97us > 0xfee00300:R 35356 11.68% 7.14% 2.17us > > Total Samples:302657, Total events handled time:1074746.01us. > > We can use --vcpu to specify which vcpu is traced: > root@localhost perf]# ./perf kvm-events report --event mmio --vcpu 1 > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' > > > Analyze events for VCPU 1: > > MMIO Access Samples Samples% Time% Avg time > > 0xfee00380:W 58041 71.20% 74.90% 3.70us > 0xfee00310:W 7826 9.60% 5.28% 1.93us > 0xfee00300:W 7826 9.60% 13.82% 5.06us > 0xfee00300:R 7826 9.60% 6.01% 2.20us > > Total Samples:81519, Total events handled time:286577.81us. > > And, '--key' is used to sort the result, the possible value sample (default, > the result is sorted by samples number), time(the result is sorted by time%): > # ./perf kvm-events report --key time > Warning: Error: expected type 5 but read 4 > Warning: Error: expected type 5 but read 0 > Warning: unknown op '}' > > > Analyze events for all VCPUs: > > VM-EXIT Samples Samples% Time% Avg time > > HLT 15424 1.58% 82.12% 6735.06us > EXTERNAL_INTERRUPT 219226 22.46% 8.01% 46.20us > APIC_ACCESS 438107 44.89% 6.20% 17.91us > IO_INSTRUCTION 122651 12.57% 1.88% 19.44us > EPT_VIOLATION 83110 8.52% 1.36% 20.75us > EXCEPTION_NMI 23601 2.42% 0.17% 8.87us > PENDING_INTERRUPT 37055 3.80% 0.16% 5.38us > CPUID 32718 3.35% 0.08% 3.15us > CR_ACCESS 4089 0.42% 0.02% 6.08us > > Total Samples:975981, Total events handled time:126502464.88us. > > I hope guys will like it and any comments are welcome! :) > > -- > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > Please read the FAQ at http://www.tux.org/lkml/ ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events 2012-01-16 22:53 ` David Ahern @ 2012-01-17 2:41 ` Xiao Guangrong 2012-01-17 4:49 ` David Ahern 0 siblings, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-01-17 2:41 UTC (permalink / raw) To: David Ahern; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM On 01/17/2012 06:53 AM, David Ahern wrote: > > > On 01/16/2012 02:30 AM, Xiao Guangrong wrote: >> This tool is very like xenoprof(if i remember correctly), and traces kvm events >> smartly. currently, it supports vmexit/mmio/ioport events. >> >> Usage: >> - to trace kvm events: >> # ./perf kvm-events record >> >> - show the result >> # ./perf kvm-events report >> >> Some output are as follow: >> # ./perf kvm-events report >> Warning: Error: expected type 5 but read 4 >> Warning: Error: expected type 5 but read 0 >> Warning: unknown op '}' > > Integrating the trace-cmd plugins into perf will remedy the above errors: > https://lkml.org/lkml/2011/8/16/352 > Yes, it is great! > Unfortunately, that effort is stalled at the moment. > >> >> >> Analyze events for all VCPUs: >> >> VM-EXIT Samples Samples% Time% Avg time >> >> APIC_ACCESS 438107 44.89% 6.20% 17.91us >> EXTERNAL_INTERRUPT 219226 22.46% 8.01% 46.20us >> IO_INSTRUCTION 122651 12.57% 1.88% 19.44us >> EPT_VIOLATION 83110 8.52% 1.36% 20.75us >> PENDING_INTERRUPT 37055 3.80% 0.16% 5.38us >> CPUID 32718 3.35% 0.08% 3.15us >> EXCEPTION_NMI 23601 2.42% 0.17% 8.87us >> HLT 15424 1.58% 82.12% 6735.06us >> CR_ACCESS 4089 0.42% 0.02% 6.08us >> >> Total Samples:975981, Total events handled time:126502464.88us. > > Have you thought about dumping a time history -- something similar to > what perf-script can do with dumping events but adding in kvm-specific > analysis like what you are doing in these examples? > I will look into it and put it to my todo list if it is possible. Thanks, David! ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events 2012-01-17 2:41 ` Xiao Guangrong @ 2012-01-17 4:49 ` David Ahern 0 siblings, 0 replies; 40+ messages in thread From: David Ahern @ 2012-01-17 4:49 UTC (permalink / raw) To: Xiao Guangrong; +Cc: Avi Kivity, Marcelo Tosatti, LKML, KVM [-- Attachment #1: Type: text/plain, Size: 1037 bytes --] On 01/16/2012 07:41 PM, Xiao Guangrong wrote: >> Have you thought about dumping a time history -- something similar to >> what perf-script can do with dumping events but adding in kvm-specific >> analysis like what you are doing in these examples? >> > > > I will look into it and put it to my todo list if it is possible. > Thanks, David! > I've played around with ways to do it as time (and motivation) allowed. Attached is one example using perf with the trace-cmd plugin plus a patch on perf-script to dump time between events: perf record -e kvm:* -fo /tmp/perf.data -p 2540 -- sleep 1 perf script -i /tmp/perf.data The output of perf-script is in the attached file. The 5th column is the dt between successive events which is mainly a convenience. A perf-kvm-events type command would allow more customization in the output -- like correlating specific events and computing total time between exit and entry accounting for HLT reasons -- as well as various statistical dumps (average, stddev, max/min, histograms). David [-- Attachment #2: kvm-trace-example.txt --] [-- Type: text/plain, Size: 2525 bytes --] qemu-kvm 2542 [001] 20757.662426 0.000001 kvm_cr: cr_write 3 = 0x6f3000 qemu-kvm 2542 [001] 20757.662430 0.000004 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.662432 0.000002 kvm_exit: reason IO_INSTRUCTION rip 0x806d8dbc info b008000b 0 qemu-kvm 2542 [001] 20757.662434 0.000002 kvm_emulate_insn: 0:806d8dbc: ed qemu-kvm 2542 [001] 20757.662435 0.000001 kvm_pio: pio_read at 0xb008 size 4 count 1 qemu-kvm 2542 [001] 20757.662436 0.000001 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.662442 0.000006 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.662444 0.000002 kvm_exit: reason HLT rip 0xf770fd3d info 0 0 qemu-kvm 2540 [000] 20757.666479 0.004287 kvm_set_irq: gsi 9 level 1 source 0 qemu-kvm 2540 [000] 20757.666481 0.000002 kvm_pic_set_irq: chip 1 pin 1 (edge|masked) qemu-kvm 2540 [000] 20757.666482 0.000001 kvm_apic_accept_irq: apicid 0 vec 177 (LowPrio|level) qemu-kvm 2540 [000] 20757.666485 0.000003 kvm_ioapic_set_irq: pin 9 dst 1 vec=177 (LowPrio|logical|level) qemu-kvm 2542 [001] 20757.666505 0.004061 kvm_inj_virq: irq 177 qemu-kvm 2542 [001] 20757.666506 0.000001 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666512 0.000006 kvm_exit: reason IO_INSTRUCTION rip 0x806d88ca info b0000009 0 qemu-kvm 2542 [001] 20757.666516 0.000004 kvm_emulate_insn: 0:806d88ca: 66 ed qemu-kvm 2542 [001] 20757.666517 0.000001 kvm_pio: pio_read at 0xb000 size 2 count 1 qemu-kvm 2542 [001] 20757.666519 0.000002 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.666528 0.000009 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666531 0.000003 kvm_exit: reason IO_INSTRUCTION rip 0x806d88be info afe00008 0 qemu-kvm 2542 [001] 20757.666534 0.000003 kvm_emulate_insn: 0:806d88be: ec qemu-kvm 2542 [001] 20757.666535 0.000001 kvm_pio: pio_read at 0xafe0 size 1 count 1 qemu-kvm 2542 [001] 20757.666537 0.000002 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.666544 0.000007 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666547 0.000003 kvm_exit: reason IO_INSTRUCTION rip 0x806d88be info afe10008 0 qemu-kvm 2542 [001] 20757.666550 0.000003 kvm_emulate_insn: 0:806d88be: ec qemu-kvm 2542 [001] 20757.666551 0.000001 kvm_pio: pio_read at 0xafe1 size 1 count 1 qemu-kvm 2542 [001] 20757.666552 0.000001 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.666558 0.000006 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666562 0.000004 kvm_exit: reason IO_INSTRUCTION rip 0x806d8934 info b0000001 0 ^ permalink raw reply [flat|nested] 40+ messages in thread
* [PATCH v4 0/3] KVM: perf: kvm events analysis tool
@ 2012-02-09 9:06 Xiao Guangrong
2012-02-09 9:09 ` [PATCH 3/3] " Xiao Guangrong
0 siblings, 1 reply; 40+ messages in thread
From: Xiao Guangrong @ 2012-02-09 9:06 UTC (permalink / raw)
To: Avi Kivity
Cc: Marcelo Tosatti, Ingo Molnar, Arnaldo Carvalho de Melo,
David Ahern, LKML, KVM
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.
^ permalink raw reply [flat|nested] 40+ messages in thread* [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-09 9:06 [PATCH v4 0/3] KVM: perf: kvm events analysis tool Xiao Guangrong @ 2012-02-09 9:09 ` Xiao Guangrong 2012-02-13 3:04 ` David Ahern 2012-02-20 23:47 ` David Ahern 0 siblings, 2 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-02-09 9:09 UTC (permalink / raw) To: Xiao Guangrong Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, Arnaldo Carvalho de Melo, David Ahern, LKML, KVM 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 <xiaoguangrong@linux.vnet.ibm.com> --- 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; ^ permalink raw reply related [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-09 9:09 ` [PATCH 3/3] " Xiao Guangrong @ 2012-02-13 3:04 ` David Ahern 2012-02-13 5:00 ` Xiao Guangrong 2012-02-20 23:47 ` David Ahern 1 sibling, 1 reply; 40+ messages in thread From: David Ahern @ 2012-02-13 3:04 UTC (permalink / raw) To: Xiao Guangrong Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, Arnaldo Carvalho de Melo, LKML, KVM 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 <xiaoguangrong@linux.vnet.ibm.com> > --- > 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; > ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-13 3:04 ` David Ahern @ 2012-02-13 5:00 ` Xiao Guangrong 0 siblings, 0 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-02-13 5:00 UTC (permalink / raw) To: David Ahern Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, Arnaldo Carvalho de Melo, LKML, KVM 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! :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-09 9:09 ` [PATCH 3/3] " Xiao Guangrong 2012-02-13 3:04 ` David Ahern @ 2012-02-20 23:47 ` David Ahern 2012-02-21 3:52 ` Xiao Guangrong 2012-02-27 4:57 ` Xiao Guangrong 1 sibling, 2 replies; 40+ messages in thread From: David Ahern @ 2012-02-20 23:47 UTC (permalink / raw) To: Xiao Guangrong, Arnaldo Carvalho de Melo Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, LKML, KVM 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<xiaoguangrong@linux.vnet.ibm.com> > --- > 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 majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-20 23:47 ` David Ahern @ 2012-02-21 3:52 ` Xiao Guangrong 2012-02-21 4:58 ` David Ahern 2012-02-27 4:57 ` Xiao Guangrong 1 sibling, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-02-21 3:52 UTC (permalink / raw) To: David Ahern Cc: Arnaldo Carvalho de Melo, Avi Kivity, Marcelo Tosatti, Ingo Molnar, LKML, KVM 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! :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-21 3:52 ` Xiao Guangrong @ 2012-02-21 4:58 ` David Ahern 0 siblings, 0 replies; 40+ messages in thread From: David Ahern @ 2012-02-21 4:58 UTC (permalink / raw) To: Xiao Guangrong Cc: Arnaldo Carvalho de Melo, Avi Kivity, Marcelo Tosatti, Ingo Molnar, LKML, KVM 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 ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-20 23:47 ` David Ahern 2012-02-21 3:52 ` Xiao Guangrong @ 2012-02-27 4:57 ` Xiao Guangrong 1 sibling, 0 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-02-27 4:57 UTC (permalink / raw) To: David Ahern Cc: Arnaldo Carvalho de Melo, Avi Kivity, Marcelo Tosatti, Ingo Molnar, LKML, KVM 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? :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool
@ 2012-02-13 5:32 David Ahern
2012-02-13 10:06 ` Xiao Guangrong
0 siblings, 1 reply; 40+ messages in thread
From: David Ahern @ 2012-02-13 5:32 UTC (permalink / raw)
To: Xiao Guangrong
Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar,
Arnaldo Carvalho de Melo, LKML, KVM
[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset=utf-8, Size: 2863 bytes --]
[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 <xiaoguangrong@linux.vnet.ibm.com> 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Ç+‰·Ÿ®‰†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a¢f£¢·hšïêÿ‘êçz_è®\x03(階ŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨èÚ&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥
^ permalink raw reply [flat|nested] 40+ messages in thread* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-13 5:32 David Ahern @ 2012-02-13 10:06 ` Xiao Guangrong 2012-02-13 15:52 ` David Ahern 0 siblings, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-02-13 10:06 UTC (permalink / raw) To: David Ahern Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, Arnaldo Carvalho de Melo, LKML, KVM 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. :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-13 10:06 ` Xiao Guangrong @ 2012-02-13 15:52 ` David Ahern 2012-02-16 4:59 ` Xiao Guangrong 0 siblings, 1 reply; 40+ messages in thread From: David Ahern @ 2012-02-13 15:52 UTC (permalink / raw) To: Xiao Guangrong Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, Arnaldo Carvalho de Melo, LKML, KVM 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 ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-13 15:52 ` David Ahern @ 2012-02-16 4:59 ` Xiao Guangrong 2012-02-16 5:05 ` David Ahern 0 siblings, 1 reply; 40+ messages in thread From: Xiao Guangrong @ 2012-02-16 4:59 UTC (permalink / raw) To: David Ahern Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, Arnaldo Carvalho de Melo, LKML, KVM 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! :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-16 4:59 ` Xiao Guangrong @ 2012-02-16 5:05 ` David Ahern 2012-02-16 5:33 ` Xiao Guangrong 2012-02-16 16:35 ` Arnaldo Carvalho de Melo 0 siblings, 2 replies; 40+ messages in thread From: David Ahern @ 2012-02-16 5:05 UTC (permalink / raw) To: Xiao Guangrong, Arnaldo Carvalho de Melo Cc: Avi Kivity, Marcelo Tosatti, Ingo Molnar, LKML, KVM 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 ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-16 5:05 ` David Ahern @ 2012-02-16 5:33 ` Xiao Guangrong 2012-02-16 16:35 ` Arnaldo Carvalho de Melo 1 sibling, 0 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-02-16 5:33 UTC (permalink / raw) To: David Ahern Cc: Arnaldo Carvalho de Melo, Avi Kivity, Marcelo Tosatti, Ingo Molnar, LKML, KVM 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. :) ^ permalink raw reply [flat|nested] 40+ messages in thread
* Re: [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-02-16 5:05 ` David Ahern 2012-02-16 5:33 ` Xiao Guangrong @ 2012-02-16 16:35 ` Arnaldo Carvalho de Melo 1 sibling, 0 replies; 40+ messages in thread From: Arnaldo Carvalho de Melo @ 2012-02-16 16:35 UTC (permalink / raw) To: David Ahern Cc: Xiao Guangrong, Avi Kivity, Marcelo Tosatti, Ingo Molnar, LKML, KVM 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 ^ permalink raw reply [flat|nested] 40+ messages in thread
* [PATCH v5 0/3] KVM: perf: kvm events analysis tool
@ 2012-03-06 8:55 Xiao Guangrong
2012-03-06 8:58 ` [PATCH 3/3] " Xiao Guangrong
0 siblings, 1 reply; 40+ messages in thread
From: Xiao Guangrong @ 2012-03-06 8:55 UTC (permalink / raw)
To: Avi Kivity, Arnaldo Carvalho de Melo
Cc: Marcelo Tosatti, Ingo Molnar, David Ahern, LKML, KVM
Changlong:
Thanks to David's review, there are some changes:
- add kvm-events compile-depend files to tools/perf/MANIFEST
- fix some typos and little clean up
- rebase it on -tip tree
The output example is following:
#./perf kvm-events report --event mmio --vcpu 3
Analyze events for VCPU 3:
MMIO Access Samples Samples% Time% Avg time
0xfee00380:W 29688 61.16% 64.52% 3.37us ( +- 0.86% )
0xfee00300:W 6285 12.95% 20.06% 4.95us ( +- 2.34% )
0xfee00300:R 6285 12.95% 8.08% 1.99us ( +- 0.59% )
0xfee00310:W 6285 12.95% 7.34% 1.81us ( +- 6.76% )
Total Samples:48543, Total events handled time:155156.31us.
^ permalink raw reply [flat|nested] 40+ messages in thread* [PATCH 3/3] KVM: perf: kvm events analysis tool 2012-03-06 8:55 [PATCH v5 0/3] " Xiao Guangrong @ 2012-03-06 8:58 ` Xiao Guangrong 0 siblings, 0 replies; 40+ messages in thread From: Xiao Guangrong @ 2012-03-06 8:58 UTC (permalink / raw) To: Xiao Guangrong Cc: Avi Kivity, Arnaldo Carvalho de Melo, Marcelo Tosatti, Ingo Molnar, David Ahern, LKML, KVM 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 The output example is following: #./perf kvm-events report --event mmio --vcpu 3 Analyze events for VCPU 3: MMIO Access Samples Samples% Time% Avg time 0xfee00380:W 29688 61.16% 64.52% 3.37us ( +- 0.86% ) 0xfee00300:W 6285 12.95% 20.06% 4.95us ( +- 2.34% ) 0xfee00300:R 6285 12.95% 8.08% 1.99us ( +- 0.59% ) 0xfee00310:W 6285 12.95% 7.34% 1.81us ( +- 6.76% ) Total Samples:48543, Total events handled time:155156.31us. Signed-off-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com> --- tools/perf/MANIFEST | 3 + tools/perf/Makefile | 1 + tools/perf/builtin-kvm-events.c | 855 +++++++++++++++++++++++++++++++++++++++ tools/perf/builtin.h | 1 + tools/perf/command-list.txt | 1 + tools/perf/perf.c | 1 + tools/perf/util/header.c | 55 +++- tools/perf/util/header.h | 1 + tools/perf/util/thread.h | 2 + 9 files changed, 919 insertions(+), 1 deletions(-) create mode 100644 tools/perf/builtin-kvm-events.c diff --git a/tools/perf/MANIFEST b/tools/perf/MANIFEST index 5476bc0..e01ec73 100644 --- a/tools/perf/MANIFEST +++ b/tools/perf/MANIFEST @@ -13,3 +13,6 @@ arch/*/lib/memset*.S include/linux/poison.h include/linux/magic.h include/linux/hw_breakpoint.h +arch/x86/include/asm/svm.h +arch/x86/include/asm/vmx.h +arch/x86/include/asm/kvm_host.h diff --git a/tools/perf/Makefile b/tools/perf/Makefile index fa04340..d8d7f67 100644 --- a/tools/perf/Makefile +++ b/tools/perf/Makefile @@ -400,6 +400,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..6857047 --- /dev/null +++ b/tools/perf/builtin-kvm-events.c @@ -0,0 +1,855 @@ +#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 "../../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 void exit_event_get_key(struct event *event, void *data, + struct event_key *key) +{ + key->info = 0; + 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 int cpu_isa; + +static const char *get_exit_reason(u64 exit_code) +{ + int table_size = ARRAY_SIZE(svm_exit_reasons); + struct exit_reasons_table *table = svm_exit_reasons; + + if (cpu_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, + cpu_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); + + 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 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; + + /* + * In some case, the 'begin event' only records the start timestamp, + * the actual event is recognized in the 'end event' (e.g. mmio-event + * in the old kernel). + */ + + /* 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, "report 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..e767431 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 9f867d9..3de6b22 100644 --- a/tools/perf/util/header.c +++ b/tools/perf/util/header.c @@ -1483,9 +1483,15 @@ static int process_build_id(struct perf_file_section *section, return 0; } +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); int (*process)(struct perf_file_section *section, struct perf_header *h, int feat, int fd); const char *name; @@ -1500,6 +1506,9 @@ struct feature_ops { #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 @@ -1514,7 +1523,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), @@ -1567,6 +1576,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 e68f617..58dd315 100644 --- a/tools/perf/util/header.h +++ b/tools/perf/util/header.h @@ -93,6 +93,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; ^ permalink raw reply related [flat|nested] 40+ messages in thread
end of thread, other threads:[~2012-03-06 8:59 UTC | newest] Thread overview: 40+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2012-01-16 9:30 [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Xiao Guangrong 2012-01-16 9:31 ` [PATCH 1/3] KVM: trace mmio read event properly Xiao Guangrong 2012-01-16 10:18 ` Avi Kivity 2012-01-17 2:36 ` Xiao Guangrong 2012-01-16 9:32 ` [PATCH 2/3] KVM: improve trace events of vmexit/mmio/ioport Xiao Guangrong 2012-01-16 9:38 ` Avi Kivity 2012-01-17 2:28 ` Xiao Guangrong 2012-01-17 11:55 ` Marcelo Tosatti 2012-01-17 17:31 ` David Ahern 2012-01-18 2:32 ` Xiao Guangrong 2012-01-18 5:34 ` David Ahern 2012-01-24 12:44 ` Avi Kivity 2012-01-16 9:32 ` [PATCH 3/3] KVM: perf: kvm events analysis tool Xiao Guangrong 2012-01-16 10:04 ` Avi Kivity 2012-01-17 2:30 ` Xiao Guangrong 2012-01-24 12:49 ` Avi Kivity 2012-01-16 10:08 ` Stefan Hajnoczi 2012-01-17 2:37 ` Xiao Guangrong 2012-01-17 11:59 ` Marcelo Tosatti 2012-01-24 12:51 ` Avi Kivity 2012-01-16 10:11 ` [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events Avi Kivity 2012-01-17 2:30 ` Xiao Guangrong 2012-01-16 22:53 ` David Ahern 2012-01-17 2:41 ` Xiao Guangrong 2012-01-17 4:49 ` David Ahern 2012-02-09 9:06 [PATCH v4 0/3] KVM: perf: kvm events analysis tool Xiao Guangrong 2012-02-09 9:09 ` [PATCH 3/3] " Xiao Guangrong 2012-02-13 3:04 ` David Ahern 2012-02-13 5:00 ` Xiao Guangrong 2012-02-20 23:47 ` David Ahern 2012-02-21 3:52 ` Xiao Guangrong 2012-02-21 4:58 ` David Ahern 2012-02-27 4:57 ` Xiao Guangrong 2012-02-13 5:32 David Ahern 2012-02-13 10:06 ` Xiao Guangrong 2012-02-13 15:52 ` David Ahern 2012-02-16 4:59 ` Xiao Guangrong 2012-02-16 5:05 ` David Ahern 2012-02-16 5:33 ` Xiao Guangrong 2012-02-16 16:35 ` Arnaldo Carvalho de Melo 2012-03-06 8:55 [PATCH v5 0/3] " Xiao Guangrong 2012-03-06 8:58 ` [PATCH 3/3] " Xiao Guangrong
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).