Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
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 qemu-kvm 2542 [001] 20757.662426 0.01 kvm_cr: cr_write 3 = 0x6f3000 qemu-kvm 2542 [001] 20757.662430 0.04 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.662432 0.02 kvm_exit: reason IO_INSTRUCTION rip 0x806d8dbc info b008000b 0 qemu-kvm 2542 [001] 20757.662434 0.02 kvm_emulate_insn: 0:806d8dbc: ed qemu-kvm 2542 [001] 20757.662435 0.01 kvm_pio: pio_read at 0xb008 size 4 count 1 qemu-kvm 2542 [001] 20757.662436 0.01 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.662442 0.06 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.662444 0.02 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.02 kvm_pic_set_irq: chip 1 pin 1 (edge|masked) qemu-kvm 2540 [000] 20757.666482 0.01 kvm_apic_accept_irq: apicid 0 vec 177 (LowPrio|level) qemu-kvm 2540 [000] 20757.666485 0.03 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.01 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666512 0.06 kvm_exit: reason IO_INSTRUCTION rip 0x806d88ca info b009 0 qemu-kvm 2542 [001] 20757.666516 0.04 kvm_emulate_insn: 0:806d88ca: 66 ed qemu-kvm 2542 [001] 20757.666517 0.01 kvm_pio: pio_read at 0xb000 size 2 count 1 qemu-kvm 2542 [001] 20757.666519 0.02 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.666528 0.09 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666531 0.03 kvm_exit: reason IO_INSTRUCTION rip 0x806d88be info afe8 0 qemu-kvm 2542 [001] 20757.666534 0.03 kvm_emulate_insn: 0:806d88be: ec qemu-kvm 2542 [001] 20757.666535 0.01 kvm_pio: pio_read at 0xafe0 size 1 count 1 qemu-kvm 2542 [001] 20757.666537 0.02 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.666544 0.07 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666547 0.03 kvm_exit: reason IO_INSTRUCTION rip 0x806d88be info afe10008 0 qemu-kvm 2542 [001] 20757.666550 0.03 kvm_emulate_insn: 0:806d88be: ec qemu-kvm 2542 [001] 20757.666551 0.01 kvm_pio: pio_read at 0xafe1 size 1 count 1 qemu-kvm 2542 [001] 20757.666552 0.01 kvm_userspace_exit: reason KVM_EXIT_IO (2) qemu-kvm 2542 [001] 20757.666558 0.06 kvm_entry: vcpu 0 qemu-kvm 2542 [001] 20757.666562 0.04 kvm_exit: reason IO_INSTRUCTION rip 0x806d8934 info b001 0
Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
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-EXITSamples Samples% Time%Avg time >> >> APIC_ACCESS 43810744.89% 6.20%17.91us >> EXTERNAL_INTERRUPT 21922622.46% 8.01%46.20us >> IO_INSTRUCTION 12265112.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! -- To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
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 AccessSamples Samples% Time%Avg time >> >> 0xfee00380:W 19658964.95%70.01% 3.83us >> 0xfee00310:W 3535611.68% 6.48% 1.97us >> 0xfee00300:W 3535611.68%16.37% 4.97us >> 0xfee00300:R 3535611.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! -- To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
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-EXITSamples Samples% Time%Avg time > > APIC_ACCESS 43810744.89% 6.20%17.91us > EXTERNAL_INTERRUPT 21922622.46% 8.01%46.20us > IO_INSTRUCTION 12265112.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 AccessSamples Samples% Time%Avg time > > 0xfee00380:W 19658964.95%70.01% 3.83us > 0xfee00310:W 3535611.68% 6.48% 1.97us > 0xfee00300:W 3535611.68%16.37% 4.97us > 0xfee00300:R 3535611.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 AccessSamples Samples% Time%Avg time > > 0xfee00380:W 5804171.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-EXITSamples Samples% Time%Avg time > > HLT 15424 1.58%82.12% 6735.06us > EXTERNAL_INTERRUPT 21922622.46% 8.01%46.20us > APIC_ACCESS 43810744.89% 6.20%17.91us > IO_INSTRUCTION 12265112.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 majord...@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > Please read the FAQ at http://www.tux.org/lkml/ -- To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
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-EXITSamples Samples% Time%Avg time > > APIC_ACCESS 43810744.89% 6.20%17.91us > EXTERNAL_INTERRUPT 21922622.46% 8.01%46.20us > IO_INSTRUCTION 12265112.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 AccessSamples Samples% Time%Avg time > > 0xfee00380:W 19658964.95%70.01% 3.83us > 0xfee00310:W 3535611.68% 6.48% 1.97us > 0xfee00300:W 3535611.68%16.37% 4.97us > 0xfee00300:R 3535611.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 AccessSamples Samples% Time%Avg time > > 0xfee00380:W 5804171.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-EXITSamples Samples% Time%Avg time > > HLT 15424 1.58%82.12% 6735.06us > EXTERNAL_INTERRUPT 21922622.46% 8.01%46.20us > APIC_ACCESS 43810744.89% 6.20%17.91us > IO_INSTRUCTION 12265112.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 -- To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
[RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
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-EXITSamples Samples% Time%Avg time APIC_ACCESS 43810744.89% 6.20%17.91us EXTERNAL_INTERRUPT 21922622.46% 8.01%46.20us IO_INSTRUCTION 12265112.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 AccessSamples Samples% Time%Avg time 0xfee00380:W 19658964.95%70.01% 3.83us 0xfee00310:W 3535611.68% 6.48% 1.97us 0xfee00300:W 3535611.68%16.37% 4.97us 0xfee00300:R 3535611.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 AccessSamples Samples% Time%Avg time 0xfee00380:W 5804171.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-EXITSamples Samples% Time%Avg time HLT 15424 1.58%82.12% 6735.06us EXTERNAL_INTERRUPT 21922622.46% 8.01%46.20us APIC_ACCESS 43810744.89% 6.20%17.91us IO_INSTRUCTION 12265112.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 kvm" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
