Re: [RFC][PATCH] KVM: perf: a smart tool to analyse kvm events

[David Ahern <dsahern@gmail.com>]

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