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
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 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/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 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
