Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events
From: David Ahern
Date: Mon Jan 16 2012 - 23:49:47 EST
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.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