Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation

[Steven Rostedt <rostedt@goodmis.org>]

On Fri, 16 Apr 2021 22:48:38 +0200
Stefano De Venuto <stefano.devenuto99@gmail.com> wrote:

> On 4/16/21 7:47 PM, Dario Faggioli wrote:
> > On Fri, 2021-04-16 at 18:46 +0200, Stefano De Venuto wrote:  
> >> Add a tool in examples/ that scans a merged host + guest trace and
> >> search for host events that are inside a vmentry/vmexit block (and
> >> vice-versa for guest events ouside the block) and report the found
> >> ones.
> >>
> >> It can be useful as a starting point for identifying issues of for
> >> checking the effectiveness of host/guest traces synchronization, or
> >> even for improving the placing of the tracepoints in the kernel.
> >>
> >> Signed-off-by: Stefano De Venuto <stefano.devenuto99@gmail.com>
> >>  
> > Just as an example, by using this tool we noticed that there are a
> > bunch of host events that, despite happening before a VMEnter (and
> > after a VMExit) were shown in the trace inside of a kvm_enter -
> > kvm_exit "block".
> > 
> > Stefano, do you still have an example of how the trace looks like? Can
> > you paste it here?
> >   
> 
> Yes. An example of those events is visible in this trace:
> 
> 	   trace.dat:        CPU 0/KVM-1567  [001]14320175367012: kvm_entry:            vcpu 0, rip 0xffffffff84a792b6
> 	   trace.dat:        CPU 0/KVM-1567  [001]14320175253942: write_msr:            c0011020, value 0
> trace-tumbleweed.dat:           <idle>-0     [000]14320175283462: hrtimer_cancel:       hrtimer=0xffff9002fdc21a00
> trace-tumbleweed.dat:           <idle>-0     [000]14320175291336: hrtimer_expire_entry: hrtimer=0xffff9002fdc21a00 function=tick_sched_timer now=3601121397289
> trace-tumbleweed.dat:           <idle>-0     [000]14320175317345: hrtimer_expire_exit:  hrtimer=0xffff9002fdc21a00
> trace-tumbleweed.dat:           <idle>-0     [000]14320175319329: hrtimer_start:        hrtimer=0xffff9002fdc21a00 function=tick_sched_timer expires=3601125253926 softexpires=3601125253926 mode=0x0
>            trace.dat:        CPU 0/KVM-1567  [001]14320175331517: write_msr:            c0011020, value 40000000000000
>            trace.dat:        CPU 0/KVM-1567  [001]14320175338548: kvm_wait_lapic_expire: vcpu 0: delta 534432 (late)
>            trace.dat:        CPU 0/KVM-1567  [001]14320175341750: kvm_eoi:              apicid 0 vector 236
>            trace.dat:        CPU 0/KVM-1567  [001]14320175343465: kvm_pv_eoi:           apicid 0 vector 236
>            trace.dat:        CPU 0/KVM-1567  [001]14320175345704: kvm_exit:             vcpu 0 reason msr rip 0xffffffff84a792b4 info1 0x0000000000000001 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000

Is the above with the time negotiations working fine?

We do not yet support the guest shift, as we found that it was broken (I
believe you reported that) and we do not have a machine available to that
has that feature :-/

-- Steve


> 
> > Stefano has also already developed the attached kernel patch. Which we
> > plan to submit upstream as soon as we've tested properly on Intel
> > hardware as well. But that's another story (although, feel free to
> > provide any feedback already, if interested).
> > 
> > Thanks and Regards
> >