From mboxrd@z Thu Jan  1 00:00:00 1970
From: Chris Thompson <cthomp@cs.umn.edu>
Subject: Trouble adding kvm clock trace to qemu-kvm
Date: Sat, 30 Apr 2011 12:00:30 -0500
Message-ID: <4DBC402E.1080103@cs.umn.edu>
Mime-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
To: kvm@vger.kernel.org
Return-path: <kvm-owner@vger.kernel.org>
Received: from mta-a3.tc.umn.edu ([134.84.119.232]:54859 "EHLO
	mta-a3.tc.umn.edu" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1751349Ab1D3RPm (ORCPT <rfc822;kvm@vger.kernel.org>);
	Sat, 30 Apr 2011 13:15:42 -0400
Received: from [192.168.1.107] (c-174-53-162-57.hsd1.mn.comcast.net [174.53.162.57])
	by mta-a3.tc.umn.edu (UMN smtpd) with ESMTP
	for <kvm@vger.kernel.org>; Sat, 30 Apr 2011 12:00:41 -0500 (CDT)
Sender: kvm-owner@vger.kernel.org
List-ID: <kvm.vger.kernel.org>

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