Hello,
I'm making some evaluation on tracing events with `trace-cmd agent` and
I noticed that sometimes a match with a kvm_exit event, regarding the
first guest events, doesn't happen.
For example, here the kvm_exit is visible:
trace.dat: cpus=4
trace-tumbleweed.dat: cpus=1
trace-tumbleweed.dat: <...>-29155 [000]16777013679205: sched_stat_runtime: comm=trace-cmd pid=29155 runtime=140813 [ns] vruntime=7024475924876 [ns]
trace-tumbleweed.dat: <...>-29155 [000]16777013692308: sched_switch: prev_comm=trace-cmd prev_pid=29155 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=29157 next_prio=120
trace-tumbleweed.dat: <...>-29155 [000]16777013696353: write_msr: c0000100, value 7f515878d740
trace-tumbleweed.dat: <...>-29157 [000]16777014284180: sched_stat_runtime: comm=trace-cmd pid=29157 runtime=155889 [ns] vruntime=7024477939951 [ns]
trace-tumbleweed.dat: <...>-29157 [000]16777014290771: sched_switch: prev_comm=trace-cmd prev_pid=29157 prev_prio=120 prev_state=S ==> next_comm=yes next_pid=29085 next_prio=120
trace-tumbleweed.dat: <...>-29157 [000]16777014296815: write_msr: c0000100, value 7f861456f5c0
trace.dat: sleep-7618 [003]16777016549098: sched_process_exec: filename=/usr/bin/sleep pid=7618 old_pid=7618
trace.dat: sleep-7618 [003]16777017486508: write_msr: c0000100, value 7fd73591f5c0
trace.dat: kworker/u8:8-2663 [001]16777017700288: timer_init: timer=0xffff8a8c84b41098
trace.dat: kworker/u8:8-2663 [001]16777017759026: timer_init: timer=0xffff8a8c84b41398
trace.dat: kworker/u8:8-2663 [001]16777017790176: timer_init: timer=0xffff8a8c84b41698
trace.dat: kworker/u8:8-2663 [001]16777017833578: timer_init: timer=0xffff8a8c84b40198
trace.dat: kworker/u8:8-2663 [001]16777017864351: timer_init: timer=0xffff8a8c84b43198
trace.dat: kworker/u8:8-2663 [001]16777017898496: timer_init: timer=0xffff8a8c84b43498
trace.dat: kworker/u8:8-2663 [001]16777017925106: sched_stat_runtime: comm=kworker/u8:8 pid=2663 runtime=1553944 [ns] vruntime=857719474182 [ns]
trace.dat: kworker/u8:8-2663 [001]16777017952596: sched_switch: prev_comm=kworker/u8:8 prev_pid=2663 prev_prio=120 prev_state=I ==> next_comm=kworker/u8:7 next_pid=2311 next_prio=120
trace.dat: kworker/u8:7-2311 [001]16777017968341: sched_stat_runtime: comm=kworker/u8:7 pid=2311 runtime=11960 [ns] vruntime=857717851510 [ns]
trace.dat: kworker/u8:7-2311 [001]16777017979368: sched_switch: prev_comm=kworker/u8:7 prev_pid=2311 prev_prio=120 prev_state=I ==> next_comm=vhost-1557 next_pid=1608 next_prio=120
trace.dat: vhost-1557-1608 [001]16777018016393: sched_waking: comm=trace-cmd pid=7617 prio=120 target_cpu=001
trace.dat: vhost-1557-1608 [001]16777018040762: sched_wakeup: comm=trace-cmd pid=7617 prio=120 target_cpu=001
trace.dat: vhost-1557-1608 [001]16777018057028: kvm_msi_set_irq: dst 0 vec 59 (Fixed|physical|edge)
trace.dat: vhost-1557-1608 [001]16777018064868: kvm_apic_accept_irq: apicid 0 vec 59 (Fixed|edge)
trace.dat: vhost-1557-1608 [001]16777018073306: sched_stat_runtime: comm=vhost-1557 pid=1608 runtime=15868 [ns] vruntime=8759414247 [ns]
trace.dat: CPU 0/KVM-1605 [000]16777018080743: write_msr: c0011020, value 40000000000000
trace.dat: vhost-1557-1608 [001]16777018081984: sched_switch: prev_comm=vhost-1557 prev_pid=1608 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=7617 next_prio=120
trace.dat: vhost-1557-1608 [001]16777018089488: write_msr: c0000100, value 7fd41c495740
trace.dat: trace-cmd-7617 [001]16777018094601: timer_cancel: timer=0xffffb253c346bda8
trace.dat: CPU 0/KVM-1605 [000]16777018095244: kvm_exit: vcpu 0 reason interrupt rip 0xffffffffa4000010 info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
.
.
.
But, in this case, this is not:
trace.dat: cpus=4
trace-tumbleweed.dat: cpus=1
trace-tumbleweed.dat: <...>-2029 [000]14320154450824: sched_stat_runtime: comm=trace-cmd pid=2029 runtime=83257 [ns] vruntime=424042595783 [ns]
trace-tumbleweed.dat: <...>-2029 [000]14320154459784: sched_switch: prev_comm=trace-cmd prev_pid=2029 prev_prio=120 prev_state=S ==> next_comm=kworker/0:5 next_pid=642 next_prio=120
trace-tumbleweed.dat: <...>-642 [000]14320154609674: sched_stat_runtime: comm=kworker/0:5 pid=642 runtime=41065 [ns] vruntime=424037656636 [ns]
trace-tumbleweed.dat: <...>-642 [000]14320154612824: sched_switch: prev_comm=kworker/0:5 prev_pid=642 prev_prio=120 prev_state=I ==> next_comm=trace-cmd next_pid=2031 next_prio=120
trace-tumbleweed.dat: <...>-642 [000]14320154618668: write_msr: c0000100, value 7ff922cd5740
trace-tumbleweed.dat: <...>-2031 [000]14320154927909: sched_stat_runtime: comm=trace-cmd pid=2031 runtime=81803 [ns] vruntime=424042450209 [ns]
trace-tumbleweed.dat: <...>-2031 [000]14320154935362: sched_switch: prev_comm=trace-cmd prev_pid=2031 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
trace-tumbleweed.dat: <idle>-0 [000]14320155379843: sched_waking: comm=kworker/0:5 pid=642 prio=120 target_cpu=000
.
.
.
trace-tumbleweed.dat: <...>-13 [000]14320159278816: write_msr: c0000100, value 7ff922cd5740
trace-tumbleweed.dat: <...>-2031 [000]14320159394095: sched_stat_runtime: comm=trace-cmd pid=2031 runtime=30715 [ns] vruntime=424042602229 [ns]
trace-tumbleweed.dat: <...>-2031 [000]14320159397210: sched_switch: prev_comm=trace-cmd prev_pid=2031 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
trace.dat: sleep-6029 [003]14320160638822: timer_init: timer=0xffff907c44d60798
trace.dat: sleep-6029 [003]14320160690679: timer_start: timer=0xffff907c44a9ac60 function=delayed_work_timer_fn expires=4295807198 [timeout=1] cpu=3 idx=31 flags=D|P|I
trace.dat: sleep-6029 [003]14320160700125: sched_stat_runtime: comm=trace-cmd pid=6029 runtime=593243 [ns] vruntime=257043002407 [ns]
trace.dat: sleep-6029 [003]14320160720438: sched_switch: prev_comm=trace-cmd prev_pid=6029 prev_prio=120 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120
trace.dat: <idle>-0 [002]14320164537024: hrtimer_cancel: hrtimer=0xffff907d76d21a00
trace.dat: <idle>-0 [003]14320164537068: hrtimer_cancel: hrtimer=0xffff907d76da1a00
.
.
.
trace.dat: CPU 0/KVM-1567 [001]14320175237271: kvm_inj_virq: irq 236
trace.dat: CPU 0/KVM-1567 [001]14320175249459: kvm_entry: vcpu 0, rip 0xffffffff8545200e
trace.dat: CPU 0/KVM-1567 [001]14320175253942: write_msr: c0011020, value 0
trace-tumbleweed.dat: <idle>-0 [000]14320175283462: hrtimer_cancel: hrtimer=0xffff9002fdc21a00
In these examples the guest has only one vCPU, so, in the second trace,
a kvm_entry is done before a kvm_exit.
Is there something that I'm missing? What can be the cause of this
mismatch since it only happens at the beginning of the trace?
If necessary, I can provide more info about my setup, or do more tests.
Thanks and Regards,
Stefano
|