All of lore.kernel.org
 help / color / mirror / Atom feed
* Combined traces evaluations
@ 2021-04-16 10:18 Stefano De Venuto
  2021-04-16 13:34 ` Steven Rostedt
  0 siblings, 1 reply; 2+ messages in thread
From: Stefano De Venuto @ 2021-04-16 10:18 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Linux Trace Devel, Dario Faggioli

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

^ permalink raw reply	[flat|nested] 2+ messages in thread
* Re: Combined traces evaluations
  2021-04-16 10:18 Combined traces evaluations Stefano De Venuto
@ 2021-04-16 13:34 ` Steven Rostedt
  0 siblings, 0 replies; 2+ messages in thread
From: Steven Rostedt @ 2021-04-16 13:34 UTC (permalink / raw)
  To: Stefano De Venuto; +Cc: Linux Trace Devel, Dario Faggioli

On Fri, 16 Apr 2021 12:18:11 +0200
Stefano De Venuto <stefano.devenuto99@gmail.com> wrote:

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

We tell the guest to start tracing, and then tell the host to start. This
means that there are going to be missing events on the host when the host
starts tracing. That is,

tell guest to start:

guest starts:

   guest has events

guest switches to host:

<kvm_exit, but not traced>

host starts tracing:

Now we have guest events followed by host events but no kvm_exit, because
it was missed. Perhaps for guest tracing it would be wise to start the host
before the guest :-/

-- Steve

^ permalink raw reply	[flat|nested] 2+ messages in thread
end of thread, other threads:[~2021-04-16 13:34 UTC | newest]

Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-04-16 10:18 Combined traces evaluations Stefano De Venuto
2021-04-16 13:34 ` Steven Rostedt

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.