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
