Re: Tracing kvm: kvm_entry and kvm_exit

Re: Tracing kvm: kvm_entry and kvm_exit

[Stefan Hajnoczi]

On Fri, Feb 22, 2013 at 11:34:27AM -0500, Mohamad Gebai wrote:
> I am tracing kvm using perf and I am analyzing the sequences of kvm_entry and
> kvm_exit tracepoints.
> I noticed that during the boot process of a VM, there are a lot more (2 to 3 as
> many times) kvm_entry event than there are kvm_exit. I tried looking around but
> didn't find anything that explains this. Is this missing instrumentation? Or
> what other path does kvm take that doesn't generate a kvm_exit event?

Gleb Natapov noticed something similar when playing with the perf script
I posted here:

http://permalink.gmane.org/gmane.comp.emulators.kvm.devel/104181

Perhaps there is a code path that is missing trace_kvm_exit().

We didn't investigate why it happens but the unexplained kvm_entry
events only appeared at the beginning of the trace, so the theory was
that events are not activated atomically by perf(1).

CCing perf mailing list.

It would be interesting if someone knows the answer.

Stefan

Re: Tracing kvm: kvm_entry and kvm_exit

[Mohamad Gebai]

I did the same experience using LTTng where the events and counters are
activated before launching kvm. So the problem doesn't seem to be with the
activation time but rather with tracepoint instrumentation within kvm. I will
investigate on it but if anyone has any kind of explanation it would be
appreciated.

Selon Stefan Hajnoczi <stefanha@gmail.com>:

> On Fri, Feb 22, 2013 at 11:34:27AM -0500, Mohamad Gebai wrote:
> > I am tracing kvm using perf and I am analyzing the sequences of kvm_entry
> and
> > kvm_exit tracepoints.
> > I noticed that during the boot process of a VM, there are a lot more (2 to
> 3 as
> > many times) kvm_entry event than there are kvm_exit. I tried looking around
> but
> > didn't find anything that explains this. Is this missing instrumentation?
> Or
> > what other path does kvm take that doesn't generate a kvm_exit event?
>
> Gleb Natapov noticed something similar when playing with the perf script
> I posted here:
>
> http://permalink.gmane.org/gmane.comp.emulators.kvm.devel/104181
>
> Perhaps there is a code path that is missing trace_kvm_exit().
>
> We didn't investigate why it happens but the unexplained kvm_entry
> events only appeared at the beginning of the trace, so the theory was
> that events are not activated atomically by perf(1).
>
> CCing perf mailing list.
>
> It would be interesting if someone knows the answer.
>
> Stefan
>

Re: Tracing kvm: kvm_entry and kvm_exit

[Gleb Natapov]

On Mon, Feb 25, 2013 at 11:18:04AM +0100, Stefan Hajnoczi wrote:
> On Fri, Feb 22, 2013 at 11:34:27AM -0500, Mohamad Gebai wrote:
> > I am tracing kvm using perf and I am analyzing the sequences of kvm_entry and
> > kvm_exit tracepoints.
> > I noticed that during the boot process of a VM, there are a lot more (2 to 3 as
> > many times) kvm_entry event than there are kvm_exit. I tried looking around but
> > didn't find anything that explains this. Is this missing instrumentation? Or
> > what other path does kvm take that doesn't generate a kvm_exit event?
> 
> Gleb Natapov noticed something similar when playing with the perf script
> I posted here:
> 
> http://permalink.gmane.org/gmane.comp.emulators.kvm.devel/104181
> 
> Perhaps there is a code path that is missing trace_kvm_exit().
> 
During guest boot there is such path. If instruction is emulated entry
is reported but exit is not. What we saw with perf was different though,
It was during normal run, not boot, so emulation cannot explain it.

> We didn't investigate why it happens but the unexplained kvm_entry
> events only appeared at the beginning of the trace, so the theory was
> that events are not activated atomically by perf(1).
> 
> CCing perf mailing list.
> 
> It would be interesting if someone knows the answer.
> 
> Stefan
> --
> To unsubscribe from this list: send the line "unsubscribe kvm" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

--
			Gleb.

Re: Tracing kvm: kvm_entry and kvm_exit

[David Ahern]

On 2/25/13 3:18 AM, Stefan Hajnoczi wrote:
> On Fri, Feb 22, 2013 at 11:34:27AM -0500, Mohamad Gebai wrote:
>> I am tracing kvm using perf and I am analyzing the sequences of kvm_entry and
>> kvm_exit tracepoints.
>> I noticed that during the boot process of a VM, there are a lot more (2 to 3 as
>> many times) kvm_entry event than there are kvm_exit. I tried looking around but
>> didn't find anything that explains this. Is this missing instrumentation? Or
>> what other path does kvm take that doesn't generate a kvm_exit event?
>
> Gleb Natapov noticed something similar when playing with the perf script
> I posted here:
>
> http://permalink.gmane.org/gmane.comp.emulators.kvm.devel/104181

Have you tried using perf kvm stat? It is really easy to add a 
flag/option to dump individual analysis points with the stats summary at 
the end - or only dump data points greater than some threshold.

Latest version for the 'live mode' can be found here:
   https://github.com/dsahern/linux/tree/perf-kvm-live-3.8

>
> Perhaps there is a code path that is missing trace_kvm_exit().

I have been playing with the live mode a bit lately. I'll add a debug to 
note 2 consecutive entry events without an exit -- see if it sheds some 
light on it.

David

Re: Tracing kvm: kvm_entry and kvm_exit

[David Ahern]

On 2/27/13 9:39 AM, David Ahern wrote:
> I have been playing with the live mode a bit lately. I'll add a debug to
> note 2 consecutive entry events without an exit -- see if it sheds some
> light on it.

If you feel game take this for a spin:
   https://github.com/dsahern/linux/commits/perf-kvm-live-3.8

I pushed a few more commits that add debugs to show consecutive events 
(2 entries or 2 exits), max and min times for various exit reasons and 
an option to dump events that take longer than some threshold. If you 
dump the output to a file or run screen with logging you should be able 
to find when the 'long' event happens and which VMEXIT reason was the cause.

Example screen dump:

21:47:37.935302

Analyze events for all VMs, all VCPUs:

              VM-EXIT    Samples  Samples%     Time%   Min Time   Max 
Time         Avg time

          APIC_ACCESS        978    61.51%     0.02%        1us 
113us      7.81us ( +-   3.67% )
       IO_INSTRUCTION        212    13.33%     0.00%        2us 
85us      9.20us ( +-   7.57% )
            CR_ACCESS         93     5.85%     0.00%        2us 
66us      3.49us ( +-  19.73% )
   EXTERNAL_INTERRUPT         53     3.33%     0.01%        3us 
135us     57.02us ( +-   6.59% )
        EXCEPTION_NMI         26     1.64%     0.00%        2us 
3us      2.57us ( +-   1.74% )
    PENDING_INTERRUPT          3     0.19%     0.00%        1us 
1us      1.85us ( +-   4.18% )

Total Samples:1590, Total events handled time:39942741.62us.

295170818723592 VM 11854, vcpu 3: APIC_ACCESS event took 113usec
295170819686668 VM 11854, vcpu 0: EXTERNAL_INTERRUPT event took 112usec
295172155051688 VM 11854, vcpu 0: EXTERNAL_INTERRUPT event took 119usec
295172841724899 VM 11854, vcpu 0: APIC_ACCESS event took 129usec
295172999633325 VM 11854, vcpu 0: EXTERNAL_INTERRUPT event took 111usec

David

Re: Tracing kvm: kvm_entry and kvm_exit

[Stefan Hajnoczi]

On Thu, Feb 28, 2013 at 5:49 AM, David Ahern <dsahern@gmail.com> wrote:
> On 2/27/13 9:39 AM, David Ahern wrote:
>>
>> I have been playing with the live mode a bit lately. I'll add a debug to
>> note 2 consecutive entry events without an exit -- see if it sheds some
>> light on it.
>
>
> If you feel game take this for a spin:
>   https://github.com/dsahern/linux/commits/perf-kvm-live-3.8

This is very cool, thanks for sharing.

Next time I'm profiling vmexit latencies I'll give it a try.

Stefan

Re: Tracing kvm: kvm_entry and kvm_exit

[Mohamad Gebai]

Selon David Ahern <dsahern@gmail.com>:

> On 2/27/13 9:39 AM, David Ahern wrote:
> > I have been playing with the live mode a bit lately. I'll add a debug to
> > note 2 consecutive entry events without an exit -- see if it sheds some
> > light on it.
>
> If you feel game take this for a spin:
>    https://github.com/dsahern/linux/commits/perf-kvm-live-3.8

Thank you for this, I have been testing it for the last couple of days, I can
see that perf kvm is getting more stable. Though I just realized that if you
launch perf kvm as soon as you start a VM, the VM fails to boot. Any idea why
this happens?

Re: Tracing kvm: kvm_entry and kvm_exit

[David Ahern]

On 3/3/13 10:36 PM, Mohamad Gebai wrote:
> Thank you for this, I have been testing it for the last couple of days, I can
> see that perf kvm is getting more stable. Though I just realized that if you
> launch perf kvm as soon as you start a VM, the VM fails to boot. Any idea why
> this happens?
>

no, but tell me more and I'll see if I can reproduce.

host kernel version?
guest kernel?
qemu-kvm command line? (leave out the disk and network arguments -- just 
the rest)

sequence of events? launching qemu-kvm in one window and at the "same 
time" launching perf-kvm? Or is perf-kvm started a few seconds prior to 
qemu-kvm or vice-versa?

Re: Tracing kvm: kvm_entry and kvm_exit

[Mohamad Gebai]

> On 3/3/13 10:36 PM, Mohamad Gebai wrote:
> > Thank you for this, I have been testing it for the last couple of days, I
> can
> > see that perf kvm is getting more stable. Though I just realized that if
> you
> > launch perf kvm as soon as you start a VM, the VM fails to boot. Any idea
> why
> > this happens?
> >
>
> no, but tell me more and I'll see if I can reproduce.
>
Sure thing:

> host kernel version?
3.8 compiled from perf-kvm-live-3.8
> guest kernel?
3.8.1
> qemu-kvm command line? (leave out the disk and network arguments -- just
> the rest)
Actually using virt-manager for this but here's the most relevant part of the
qemu-kvm command line:
/usr/bin/qemu-kvm -name debian_test -S -M pc-1.2 -enable-kvm -m 1024 -smp
1,sockets=1,cores=1,threads=1

> sequence of events? launching qemu-kvm in one window and at the "same
> time" launching perf-kvm? Or is perf-kvm started a few seconds prior to
> qemu-kvm or vice-versa?
>

Actually qemu-kvm is launched first, then perf kvm is launched right after,
before the bootloader of the VM using this command line:
perf kvm stat -p <vm-pid> -e kvmmmu:*

Re: Tracing kvm: kvm_entry and kvm_exit

[David Ahern]

On 3/3/13 11:15 PM, Mohamad Gebai wrote:
>> host kernel version?
> 3.8 compiled from perf-kvm-live-3.8

I made no changes to the kernel side so essentially you are running v3.8 
unmodified.

>> guest kernel?
> 3.8.1
>> qemu-kvm command line? (leave out the disk and network arguments -- just
>> the rest)
> Actually using virt-manager for this but here's the most relevant part of the
> qemu-kvm command line:
> /usr/bin/qemu-kvm -name debian_test -S -M pc-1.2 -enable-kvm -m 1024 -smp
> 1,sockets=1,cores=1,threads=1

ok, I take that to mean qemu-kvm 1.2.

> Actually qemu-kvm is launched first, then perf kvm is launched right after,
> before the bootloader of the VM using this command line:
> perf kvm stat -p <vm-pid> -e kvmmmu:*

I have not been able to reproduce it. Host kernel is v3.8, guest kernel 
is 3.8.1-201.fc18.x86_64 (Fedora 18, latest kernel). Host CPU: Intel(R) 
Xeon(R) CPU E5540  @ 2.53GHz.

qemu-kvm version is 1.2. Relevant command line (launched manually)

/usr/local/qemu-kvm/1.2/bin/qemu-system-x86_64 -m 4096 -smp 
1,sockets=1,cores=1,threads=1  -S -M pc-1.2

That starts the VM with paused vcpus. Then launch perf-kvm-stat:

perf kvm stat -p $(vm-status -b f18) -e kvmmmu:*

VM boots just fine.

When I get some time I can try qemu versions 1.3 and 1.4 to see if it 
makes a difference. Any output from the VM or host dmesg? What if you 
start qemu manually?

David