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

[Stefano De Venuto <stefano.devenuto99@gmail.com>]

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

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