Trouble adding kvm clock trace to qemu-kvm

Trouble adding kvm clock trace to qemu-kvm

[Chris Thompson]

I'm trying to add a trace to qemu-kvm that will log the value of the 
vcpu's clock when a specific interrupt gets pushed. I'm working with 
qemu-kvm-0.14.0 on the 2.6.32-31 kernel. I've added the following to 
kvm_arch_try_push_interrupts in qemu-kvm-x86.c:

if (irq == 41) {
     // Get the VCPU's TSC
     struct kvm_clock_data clock;
     kvm_vcpu_ioctl(env, KVM_GET_CLOCK, &clock);
     uint64_t ticks = clock.clock;
     trace_kvm_clock_at_injection(ticks);
}

And here's the trace event I added:

kvm_clock_at_injection(uint64_t ticks) "interrupt 41 at clock %"PRIu64""

I have that trace and the virtio_blk_req_complete trace enabled. An 
excerpt from the resulting trace output from simpletrace.py:

virtio_blk_req_complete 288390365546367 30461.681 req=46972352 status=0
kvm_clock_at_injection 288390365546578 0.211 ticks=46972352
virtio_blk_req_complete 288390394870065 29323.487 req=46972352 status=0
kvm_clock_at_injection 288390394870276 0.211 ticks=46972352

Am I getting the guest's clock incorrectly? And even if so, why is it 
the same as the request pointer that virtio_blk_req_complete reports?

Any ideas are appreciated.

Thanks,

Chris

Re: Trouble adding kvm clock trace to qemu-kvm

[Avi Kivity]

On 04/30/2011 08:00 PM, Chris Thompson wrote:
> I'm trying to add a trace to qemu-kvm that will log the value of the 
> vcpu's clock when a specific interrupt gets pushed. I'm working with 
> qemu-kvm-0.14.0 on the 2.6.32-31 kernel. I've added the following to 
> kvm_arch_try_push_interrupts in qemu-kvm-x86.c:
>
> if (irq == 41) {
>     // Get the VCPU's TSC
>     struct kvm_clock_data clock;
>     kvm_vcpu_ioctl(env, KVM_GET_CLOCK, &clock);
>     uint64_t ticks = clock.clock;
>     trace_kvm_clock_at_injection(ticks);
> }
>

This mechanism is only active with -no-kvm-irqchip; otherwise interrupt 
injection happens in the kernel.

> And here's the trace event I added:
>
> kvm_clock_at_injection(uint64_t ticks) "interrupt 41 at clock %"PRIu64""
>
> I have that trace and the virtio_blk_req_complete trace enabled. An 
> excerpt from the resulting trace output from simpletrace.py:
>
> virtio_blk_req_complete 288390365546367 30461.681 req=46972352 status=0
> kvm_clock_at_injection 288390365546578 0.211 ticks=46972352
> virtio_blk_req_complete 288390394870065 29323.487 req=46972352 status=0
> kvm_clock_at_injection 288390394870276 0.211 ticks=46972352
>
> Am I getting the guest's clock incorrectly? And even if so, why is it 
> the same as the request pointer that virtio_blk_req_complete reports?
>
> Any ideas are appreciated.

What is the 'ticks' field?

-- 
I have a truly marvellous patch that fixes the bug which this
signature is too narrow to contain.

Re: Trouble adding kvm clock trace to qemu-kvm

[Stefan Hajnoczi]

On Sat, Apr 30, 2011 at 6:00 PM, Chris Thompson <cthomp@cs.umn.edu> wrote:
> I'm trying to add a trace to qemu-kvm that will log the value of the vcpu's
> clock when a specific interrupt gets pushed. I'm working with
> qemu-kvm-0.14.0 on the 2.6.32-31 kernel. I've added the following to
> kvm_arch_try_push_interrupts in qemu-kvm-x86.c:
>
> if (irq == 41) {
>    // Get the VCPU's TSC
>    struct kvm_clock_data clock;
>    kvm_vcpu_ioctl(env, KVM_GET_CLOCK, &clock);
>    uint64_t ticks = clock.clock;
>    trace_kvm_clock_at_injection(ticks);
> }
>
> And here's the trace event I added:
>
> kvm_clock_at_injection(uint64_t ticks) "interrupt 41 at clock %"PRIu64""
>
> I have that trace and the virtio_blk_req_complete trace enabled. An excerpt
> from the resulting trace output from simpletrace.py:
>
> virtio_blk_req_complete 288390365546367 30461.681 req=46972352 status=0
> kvm_clock_at_injection 288390365546578 0.211 ticks=46972352
> virtio_blk_req_complete 288390394870065 29323.487 req=46972352 status=0
> kvm_clock_at_injection 288390394870276 0.211 ticks=46972352

Did you modify simpletrace.py?  The 288390365546367 field is should
not be there.  The output format should be:
<trace-event-name> <delta-microseconds> [<arg0>=<val0>...]

It looks like your simpletrace.py may be pretty-printing trace records
incorrectly.

If you have a public git tree you can link to I'd be happy to check
that simpletrace.py is working.

Stefan