[PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE

[PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

Chaning kvmtrace code to use timestamp and add powerpc support.

This is the revised series including the feedback from the earlier submission
this week. I now also added the userspace changes which completes the series.

The series contains nine patches (4 generic / 5 powerpc code):

Subject: [PATCH 1/9] kvmtrace: Remove use of bit fields in kvm trace structure v3
	Introducing a endian save way to store the flags event,tcs, num_data 
Subject: [PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday
	use a cross host comparable timestamp source and make it 32/64 bit save
Subject: [PATCH 3/9] kvmtrace: rename cycles to timestamp
	it is no more tracking cycles, so rename variables and change comments
Subject: [PATCH 3/9] kvmppc: kvmtrace: enable KVM_TRACE building for powerpc
	enable KVM_TRACE for powerpc in Kconfig/Makefile
Subject: [PATCH 4/9] kvmppc: kvmtrace: adds trace points for ppc tlb activity v2
	use KVM_TRACE to track tlb/shadow tlb activity on embedded powerpc
Subject: [PATCH 5/9] kvmppc: kvmtrace: trace powerpc instruction emulation
	use KVM_TRACE to track instruction emulation overhead
Subject: [PATCH 7/9] kvm-userspace: kvmtrace_format: add ppc instruction emulation
	extension to kvmtrace_format to handle complex event types e.g. ppc
	instructon emulation
Subject: [PATCH 8/9] kvm-userspace: kvmtrace_format: add statistic section
	adding statistic creation/prsentation to the kvmtrace data processing
Subject: [PATCH 9/9] kvm-userspace: kvmtrace: rename cycles to timestamp
	it is no more tracking cycles, so rename variables and change comments

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 arch/powerpc/kvm/emulate.c   |    2
 b/arch/powerpc/kvm/44x_tlb.c |   15 ++
 b/arch/powerpc/kvm/Kconfig   |   11 +
 b/arch/powerpc/kvm/Makefile  |    6
 b/arch/powerpc/kvm/emulate.c |    4
 b/include/linux/kvm.h        |   17 ++
 b/user/formats               |   16 --
 b/user/kvmtrace_format       |  276 ++++++++++++++++++++++++++++++++++++++++---
 b/virt/kvm/kvm_trace.c       |   19 +-
 include/linux/kvm.h          |   10 +
 user/formats                 |   50 +++----
 user/kvmtrace_format         |  114 +++++++++++++----
 virt/kvm/kvm_trace.c         |   29 ++--
 13 files changed, 461 insertions(+), 108 deletions(-)

[PATCH 1/9] kvmtrace: Remove use of bit fields in kvm trace structure v3

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
From: Jerone Young <jyoung5@us.ibm.com>

This patch fixes kvmtrace use on big endian systems. When using bit fields the
compiler will lay data out in the wrong order expected when laid down into a
file.
This fixes it by using one variable instead of using bit fields.

Updates in v3:
	- fixed macro definition bug in v2
	- ensured in macro operator order
	- fixed whitespace/indent issues
	- removed superfluous initialization

Signed-off-by: Jerone Young <jyoung5@us.ibm.com>
Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 include/linux/kvm.h  |   17 ++++++++++++++---
 virt/kvm/kvm_trace.c |   19 ++++++++++---------
 2 files changed, 24 insertions(+), 12 deletions(-)

[diff]

diff --git a/include/linux/kvm.h b/include/linux/kvm.h
--- a/include/linux/kvm.h
+++ b/include/linux/kvm.h
@@ -311,9 +311,13 @@
 
 /* This structure represents a single trace buffer record. */
 struct kvm_trace_rec {
-	__u32 event:28;
-	__u32 extra_u32:3;
-	__u32 cycle_in:1;
+	/* variable rec_val
+	 * is split into:
+	 * bits 0 - 27  -> event id
+	 * bits 28 -30  -> number of extra data args of size u32
+	 * bits 31      -> binary indicator for if tsc is in record
+	 */
+	__u32 rec_val;
 	__u32 pid;
 	__u32 vcpu_id;
 	union {
@@ -326,6 +330,13 @@
 		} nocycle;
 	} u;
 } __attribute__((packed));
+
+#define TRACE_REC_EVENT_ID(val) \
+		(0x0fffffff & (val))
+#define TRACE_REC_NUM_DATA_ARGS(val) \
+		(0x70000000 & ((val) << 28))
+#define TRACE_REC_TCS(val) \
+		(0x80000000 & ((val) << 31))
 
 #define KVMIO 0xAE
 
diff --git a/virt/kvm/kvm_trace.c b/virt/kvm/kvm_trace.c
--- a/virt/kvm/kvm_trace.c
+++ b/virt/kvm/kvm_trace.c
@@ -54,12 +54,13 @@
 	struct kvm_trace *kt = kvm_trace;
 	struct kvm_trace_rec rec;
 	struct kvm_vcpu *vcpu;
-	int    i, extra, size;
+	int    i, size;
+	u32    extra;
 
 	if (unlikely(kt->trace_state != KVM_TRACE_STATE_RUNNING))
 		return;
 
-	rec.event	= va_arg(*args, u32);
+	rec.rec_val	= TRACE_REC_EVENT_ID(va_arg(*args, u32));
 	vcpu		= va_arg(*args, struct kvm_vcpu *);
 	rec.pid		= current->tgid;
 	rec.vcpu_id	= vcpu->vcpu_id;
@@ -67,21 +68,21 @@
 	extra   	= va_arg(*args, u32);
 	WARN_ON(!(extra <= KVM_TRC_EXTRA_MAX));
 	extra 		= min_t(u32, extra, KVM_TRC_EXTRA_MAX);
-	rec.extra_u32   = extra;
 
-	rec.cycle_in 	= p->cycle_in;
-
-	if (rec.cycle_in) {
+	rec.rec_val |= TRACE_REC_TCS(p->cycle_in)
+			| TRACE_REC_NUM_DATA_ARGS(extra);
+	
+	if (p->cycle_in) {
 		rec.u.cycle.cycle_u64 = get_cycles();
 
-		for (i = 0; i < rec.extra_u32; i++)
+		for (i = 0; i < extra; i++)
 			rec.u.cycle.extra_u32[i] = va_arg(*args, u32);
 	} else {
-		for (i = 0; i < rec.extra_u32; i++)
+		for (i = 0; i < extra; i++)
 			rec.u.nocycle.extra_u32[i] = va_arg(*args, u32);
 	}
 
-	size = calc_rec_size(rec.cycle_in, rec.extra_u32 * sizeof(u32));
+	size = calc_rec_size(p->cycle_in, extra * sizeof(u32));
 	relay_write(kt->rchan, &rec, size);
 }
 

[PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

The current kvmtrace code uses get_cycles() while the interpretation would be
easier using using nanoseconds. Getnstimeofday should give the same accuracy
as get_cycles on all architectures but at a better unit (e.g. comparable
between two hosts with different frequencies.

The implementation of kvmtrace uses a 64 bit cycle variable while get_cycles
only provided a unsigned long which is != 64 bit on 32 bit architectures.
Since this patch introduced getnstimeofday we can addtionally merge the
tv_sec portion of the struct timespec returned to use the full 64 bit
of the trace interface and therefor avoid some wraparounds. This merge
is done always if the two values of a struct timespec fit into the u64.

An alternative might be ktime_t instead of u64 and using as Sheng Yang
suggested and ktime_get(), I had no time to test&compare that yet.
Any comments or requirements from others what to prefer here ?

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 kvm_trace.c |    9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

[diff]

diff --git a/virt/kvm/kvm_trace.c b/virt/kvm/kvm_trace.c
--- a/virt/kvm/kvm_trace.c
+++ b/virt/kvm/kvm_trace.c
@@ -56,6 +56,7 @@
 	struct kvm_vcpu *vcpu;
 	int    i, size;
 	u32    extra;
+	struct timespec tv;
 
 	if (unlikely(kt->trace_state != KVM_TRACE_STATE_RUNNING))
 		return;
@@ -73,7 +74,13 @@
 			| TRACE_REC_NUM_DATA_ARGS(extra);
 	
 	if (p->cycle_in) {
-		rec.u.cycle.cycle_u64 = get_cycles();
+		getnstimeofday(&tv);
+		/* compress both struct tv values into u64 on 32 bit archs */
+		if (sizeof(tv) == sizeof(u64))
+			rec.u.cycle.cycle_u64 = 
+				(((u64)tv.tv_sec) << 32) | tv.tv_nsec;
+		else
+			rec.u.cycle.cycle_u64 = tv.tv_nsec;
 
 		for (i = 0; i < extra; i++)
 			rec.u.cycle.extra_u32[i] = va_arg(*args, u32);

[PATCH 3/9] kvmtrace: rename cycles to timestamp

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

Due to the fact that the cycle counter is now completely replaced by the more
generic time based code (getnstimeofday) this patch renames all occurances of
the old cycle code to make it clear that this is now a timestamp.

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 include/linux/kvm.h  |    6 +++---
 virt/kvm/kvm_trace.c |   20 ++++++++++----------
 2 files changed, 13 insertions(+), 13 deletions(-)

[diff]

diff --git a/include/linux/kvm.h b/include/linux/kvm.h
--- a/include/linux/kvm.h
+++ b/include/linux/kvm.h
@@ -322,12 +322,12 @@
 	__u32 vcpu_id;
 	union {
 		struct {
-			__u64 cycle_u64;
+			__u64 timestamp_u64;
 			__u32 extra_u32[KVM_TRC_EXTRA_MAX];
-		} cycle;
+		} timestamp;
 		struct {
 			__u32 extra_u32[KVM_TRC_EXTRA_MAX];
-		} nocycle;
+		} notimestamp;
 	} u;
 } __attribute__((packed));
 
diff --git a/virt/kvm/kvm_trace.c b/virt/kvm/kvm_trace.c
--- a/virt/kvm/kvm_trace.c
+++ b/virt/kvm/kvm_trace.c
@@ -35,16 +35,16 @@
 struct kvm_trace_probe {
 	const char *name;
 	const char *format;
-	u32 cycle_in;
+	u32 timestamp_in;
 	marker_probe_func *probe_func;
 };
 
-static inline int calc_rec_size(int cycle, int extra)
+static inline int calc_rec_size(int timestamp, int extra)
 {
 	int rec_size = KVM_TRC_HEAD_SIZE;
 
 	rec_size += extra;
-	return cycle ? rec_size += KVM_TRC_CYCLE_SIZE : rec_size;
+	return timestamp ? rec_size += KVM_TRC_CYCLE_SIZE : rec_size;
 }
 
 static void kvm_add_trace(void *probe_private, void *call_data,
@@ -70,26 +70,26 @@
 	WARN_ON(!(extra <= KVM_TRC_EXTRA_MAX));
 	extra 		= min_t(u32, extra, KVM_TRC_EXTRA_MAX);
 
-	rec.rec_val |= TRACE_REC_TCS(p->cycle_in)
+	rec.rec_val |= TRACE_REC_TCS(p->timestamp_in)
 			| TRACE_REC_NUM_DATA_ARGS(extra);
 	
-	if (p->cycle_in) {
+	if (p->timestamp_in) {
 		getnstimeofday(&tv);
 		/* compress both struct tv values into u64 on 32 bit archs */
 		if (sizeof(tv) == sizeof(u64))
-			rec.u.cycle.cycle_u64 = 
+			rec.u.timestamp.timestamp_u64 = 
 				(((u64)tv.tv_sec) << 32) | tv.tv_nsec;
 		else
-			rec.u.cycle.cycle_u64 = tv.tv_nsec;
+			rec.u.timestamp.timestamp_u64 = tv.tv_nsec;
 
 		for (i = 0; i < extra; i++)
-			rec.u.cycle.extra_u32[i] = va_arg(*args, u32);
+			rec.u.timestamp.extra_u32[i] = va_arg(*args, u32);
 	} else {
 		for (i = 0; i < extra; i++)
-			rec.u.nocycle.extra_u32[i] = va_arg(*args, u32);
+			rec.u.notimestamp.extra_u32[i] = va_arg(*args, u32);
 	}
 
-	size = calc_rec_size(p->cycle_in, extra * sizeof(u32));
+	size = calc_rec_size(p->timestamp_in, extra * sizeof(u32));
 	relay_write(kt->rchan, &rec, size);
 }
 

[PATCH 3/9] kvmppc: kvmtrace: enable KVM_TRACE building for powerpc

[ehrhardt]

From: Jerone Young <jyoung5@us.ibm.com>

This patch enables KVM_TRACE to build for PowerPC arch. This means just
adding sections to Kconfig and Makefile.

Signed-off-by: Jerone Young <jyoung5@us.ibm.com>
Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 Kconfig  |   11 +++++++++++
 Makefile |    6 ++++--
 2 files changed, 15 insertions(+), 2 deletions(-)

[diff]
diff --git a/arch/powerpc/kvm/Kconfig b/arch/powerpc/kvm/Kconfig
--- a/arch/powerpc/kvm/Kconfig
+++ b/arch/powerpc/kvm/Kconfig
@@ -37,6 +37,17 @@ config KVM_BOOKE_HOST
 	  Provides host support for KVM on Book E PowerPC processors. Currently
 	  this works on 440 processors only.
 
+config KVM_TRACE
+	bool "KVM trace support"
+	depends on KVM && MARKERS && SYSFS
+	select RELAY
+	select DEBUG_FS
+	default n
+	---help---
+	  This option allows reading a trace of kvm-related events through
+	  relayfs.  Note the ABI is not considered stable and will be
+	  modified in future updates.
+
 source drivers/virtio/Kconfig
 
 endif # VIRTUALIZATION
diff --git a/arch/powerpc/kvm/Makefile b/arch/powerpc/kvm/Makefile
--- a/arch/powerpc/kvm/Makefile
+++ b/arch/powerpc/kvm/Makefile
@@ -4,9 +4,11 @@
 
 EXTRA_CFLAGS += -Ivirt/kvm -Iarch/powerpc/kvm
 
-common-objs = $(addprefix ../../../virt/kvm/, kvm_main.o coalesced_mmio.o)
+common-objs-y = $(addprefix ../../../virt/kvm/, kvm_main.o coalesced_mmio.o)
 
-kvm-objs := $(common-objs) powerpc.o emulate.o booke_guest.o
+common-objs-$(CONFIG_KVM_TRACE)  += $(addprefix ../../../virt/kvm/, kvm_trace.o)
+
+kvm-objs := $(common-objs-y) powerpc.o emulate.o booke_guest.o
 obj-$(CONFIG_KVM) += kvm.o
 
 AFLAGS_booke_interrupts.o := -I$(obj)

[PATCH 4/9] kvmppc: kvmtrace: adds trace points for ppc tlb activity v2

[ehrhardt]

From: Jerone Young <jyoung5@us.ibm.com>
From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

This patch adds trace points to track powerpc TLB activities using the
KVM_TRACE infrastructure.
Update to v1:
	- fixed wrong indents reported by checkpatch

Signed-off-by: Jerone Young <jyoung5@us.ibm.com>
Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 arch/powerpc/kvm/44x_tlb.c |   15 ++++++++++++++-
 arch/powerpc/kvm/emulate.c |    4 ++++
 include/linux/kvm.h        |    3 +++
 3 files changed, 21 insertions(+), 1 deletion(-)

[diff]

diff --git a/arch/powerpc/kvm/44x_tlb.c b/arch/powerpc/kvm/44x_tlb.c
--- a/arch/powerpc/kvm/44x_tlb.c
+++ b/arch/powerpc/kvm/44x_tlb.c
@@ -19,6 +19,7 @@
 
 #include <linux/types.h>
 #include <linux/string.h>
+#include <linux/kvm.h>
 #include <linux/kvm_host.h>
 #include <linux/highmem.h>
 #include <asm/mmu-44x.h>
@@ -175,6 +176,10 @@
 	stlbe->word1 = (hpaddr & 0xfffffc00) | ((hpaddr >> 32) & 0xf);
 	stlbe->word2 = kvmppc_44x_tlb_shadow_attrib(flags,
 	                                            vcpu->arch.msr & MSR_PR);
+
+	KVMTRACE_5D(STLB_WRITE, vcpu, victim,
+			stlbe->tid, stlbe->word0, stlbe->word1, stlbe->word2,
+			handler);
 }
 
 void kvmppc_mmu_invalidate(struct kvm_vcpu *vcpu, u64 eaddr, u64 asid)
@@ -203,6 +208,9 @@
 
 		kvmppc_44x_shadow_release(vcpu, i);
 		stlbe->word0 = 0;
+		KVMTRACE_5D(STLB_INVAL, vcpu, i,
+				stlbe->tid, stlbe->word0, stlbe->word1,
+				stlbe->word2, handler);
 	}
 	up_write(&current->mm->mmap_sem);
 }
@@ -216,8 +224,13 @@
 	/* XXX Replace loop with fancy data structures. */
 	down_write(&current->mm->mmap_sem);
 	for (i = 0; i <= tlb_44x_hwater; i++) {
+		struct tlbe *stlbe = &vcpu->arch.shadow_tlb[i];
+
 		kvmppc_44x_shadow_release(vcpu, i);
-		vcpu->arch.shadow_tlb[i].word0 = 0;
+		stlbe->word0 = 0;
+		KVMTRACE_5D(STLB_INVAL, vcpu, i,
+				stlbe->tid, stlbe->word0, stlbe->word1,
+				stlbe->word2, handler);
 	}
 	up_write(&current->mm->mmap_sem);
 }
diff --git a/arch/powerpc/kvm/emulate.c b/arch/powerpc/kvm/emulate.c
--- a/arch/powerpc/kvm/emulate.c
+++ b/arch/powerpc/kvm/emulate.c
@@ -169,6 +169,10 @@
 		 * are mapped on the fly. */
 		kvmppc_mmu_map(vcpu, eaddr, raddr >> PAGE_SHIFT, asid, flags);
 	}
+
+	KVMTRACE_5D(GTLB_WRITE, vcpu, index,
+			tlbe->tid, tlbe->word0, tlbe->word1, tlbe->word2,
+			handler);
 
 	return EMULATE_DONE;
 }
diff --git a/include/linux/kvm.h b/include/linux/kvm.h
--- a/include/linux/kvm.h
+++ b/include/linux/kvm.h
@@ -470,5 +470,8 @@
 #define KVM_TRC_LMSW             (KVM_TRC_HANDLER + 0x13)
 #define KVM_TRC_APIC_ACCESS      (KVM_TRC_HANDLER + 0x14)
 #define KVM_TRC_TDP_FAULT        (KVM_TRC_HANDLER + 0x15)
+#define KVM_TRC_GTLB_WRITE       (KVM_TRC_HANDLER + 0x16)
+#define KVM_TRC_STLB_WRITE       (KVM_TRC_HANDLER + 0x17)
+#define KVM_TRC_STLB_INVAL       (KVM_TRC_HANDLER + 0x18)
 
 #endif

[PATCH 5/9] kvmppc: kvmtrace: trace powerpc instruction emulation

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

This patch adds a trace point for the instruction emulation on embedded powerpc
utilizing the KVM_TRACE interface.

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 arch/powerpc/kvm/emulate.c |    2 ++
 include/linux/kvm.h        |    1 +
 2 files changed, 3 insertions(+)

[diff]

diff --git a/arch/powerpc/kvm/emulate.c b/arch/powerpc/kvm/emulate.c
--- a/arch/powerpc/kvm/emulate.c
+++ b/arch/powerpc/kvm/emulate.c
@@ -769,6 +769,8 @@
 		break;
 	}
 
+	KVMTRACE_3D(PPC_INSTR, vcpu, inst, vcpu->arch.pc, emulated, entryexit);
+
 	if (advance)
 		vcpu->arch.pc += 4; /* Advance past emulated instruction. */
 
diff --git a/include/linux/kvm.h b/include/linux/kvm.h
--- a/include/linux/kvm.h
+++ b/include/linux/kvm.h
@@ -473,5 +473,6 @@
 #define KVM_TRC_GTLB_WRITE       (KVM_TRC_HANDLER + 0x16)
 #define KVM_TRC_STLB_WRITE       (KVM_TRC_HANDLER + 0x17)
 #define KVM_TRC_STLB_INVAL       (KVM_TRC_HANDLER + 0x18)
+#define KVM_TRC_PPC_INSTR        (KVM_TRC_HANDLER + 0x19)
 
 #endif

[PATCH 7/9] kvm-userspace: kvmtrace_format: add ppc instruction emulation

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

This patch adds the handling of the ppc instruction emulation trace records.
Due to the fact that those are more complex than the classic "formats" file
way this patch adds a check of the event id and maps to the internal handler
function if needed (other complex trace records that might appear in future
can hook up there too).
Additionally this fixes the ppc tlb trace record definitions in the formats
file now that the revised kernel patch series is submitted.

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 formats         |   16 +--
 kvmtrace_format |  276 +++++++++++++++++++++++++++++++++++++++++++++++++++++---
 2 files changed, 268 insertions(+), 24 deletions(-)

[diff]

diff --git a/user/formats b/user/formats
--- a/user/formats
+++ b/user/formats
@@ -23,13 +23,9 @@
 0x00020013  %(tsc)d (+%(reltsc)8d)  LMSW          vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ value = 0x%(1)08x ]
 0x00020014  %(tsc)d (+%(reltsc)8d)  APIC_ACCESS   vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ offset = 0x%(1)08x ]
 0x00020015  %(tsc)d (+%(reltsc)8d)  TDP_FAULT     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
-# ppc: context switch
-0x00020016  %(tsc)d (+%(reltsc)8d)  CONT_SWITCH   vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
-# ppc: tlb write
-0x00020017  %(tsc)d (+%(reltsc)8d)  TLB_WRITE    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
-# ppc: tlb invalidate
-0x00020018  %(tsc)d (+%(reltsc)8d)  TLB_INVAL     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
-# ppc: guest TLB write
-0x00020019  %(tsc)d (+%(reltsc)8d)  GTLB_WRITE    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
-# ppc: shadow TLB write
-0x00020020  %(tsc)d (+%(reltsc)8d)  STLB_WRITE   vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
+# ppc: tlb traces
+0x00020016  GTLB_WRITE    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
+0x00020017  STLB_WRITE    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
+0x00020018  STLB_INVAL    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
+# ppc: instruction emulation - this type is handled more complex in kvmtrace_format, but listed to show the eventid and transported data
+#0x00020019  %(tsc)d (+%(reltsc)8d)  PPC_INSTR     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ instr = 0x%(1)08x, pc = 0x%(2)08x, emul = 0x%(3)08x, nsec = %(4)08d ]
diff --git a/user/kvmtrace_format b/user/kvmtrace_format
--- a/user/kvmtrace_format
+++ b/user/kvmtrace_format
@@ -58,6 +58,250 @@
 def sighand(x,y):
     global interrupted
     interrupted = 1
+
+# ppc instruction decoding for event type 0x00020019 (PPC_INSTR)
+def get_op(instr):
+        return (instr >> 26);
+
+def get_xop(instr):
+        return (instr >> 1) & 0x3ff;
+
+def get_sprn(instr):
+	return ((instr >> 16) & 0x1f) | ((instr >> 6) & 0x3e0)
+
+def get_dcrn(instr):
+	return ((instr >> 16) & 0x1f) | ((instr >> 6) & 0x3e0);
+
+def get_tlbwe_type(instr):
+	ws = (instr >> 11) & 0x1f;
+	if ws == 0:
+		return "PAGEID"
+	elif ws == 1:
+		return "XLAT"
+	elif ws == 2:
+		return "ATTRIB"
+	else:
+		return "UNKNOWN"
+
+def get_name(instr):
+	if get_op(instr)==3:
+		return "trap"
+	elif get_op(instr)==19:
+		if get_xop(instr) == 50:
+			return "rfi"
+		else:
+			return "unknown"
+	elif get_op(instr)==31:
+		if get_xop(instr) == 83:
+			return "mfmsr"
+
+		elif get_xop(instr) == 87:
+			return "lbzx"
+
+		elif get_xop(instr) == 131:
+			return "wrtee"
+
+		elif get_xop(instr) == 146:
+			return "mtmsr"
+
+		elif get_xop(instr) == 163:
+			return "wrteei"
+
+		elif get_xop(instr) == 215:
+			return "stbx"
+
+		elif get_xop(instr) == 247:
+			return "stbux"
+
+		elif get_xop(instr) == 279:
+			return "lhzx"
+
+		elif get_xop(instr) == 311:
+			return "lhzux"
+
+		elif get_xop(instr) == 323:
+			return "mfdcr"
+
+		elif get_xop(instr) == 339:
+			return "mfspr"
+
+		elif get_xop(instr) == 407:
+			return "sthx"
+
+		elif get_xop(instr) == 439:
+			return "sthux"
+
+		elif get_xop(instr) == 451:
+			return "mtdcr"
+
+		elif get_xop(instr) == 467:
+			return "mtspr"
+
+		elif get_xop(instr) == 470:
+			return "dcbi"
+
+		elif get_xop(instr) == 534:
+			return "lwbrx"
+
+		elif get_xop(instr) == 566:
+			return "tlbsync"
+
+		elif get_xop(instr) == 662:
+			return "stwbrx"
+
+		elif get_xop(instr) == 978:
+			return "tlbwe"
+
+		elif get_xop(instr) == 914:
+			return "tlbsx"
+
+		elif get_xop(instr) == 790:
+			return "lhbrx"
+
+		elif get_xop(instr) == 918:
+			return "sthbrx"
+
+		elif get_xop(instr) == 966:
+			return "iccci"
+
+		else:
+			return "unknown"
+
+	elif get_op(instr) == 32:
+		return "lwz"
+
+	elif get_op(instr) == 33:
+		return "lwzu"
+
+	elif get_op(instr) == 34:
+		return "lbz"
+
+	elif get_op(instr) == 35:
+		return "lbzu"
+
+	elif get_op(instr) == 36:
+		return "stw"
+
+	elif get_op(instr) == 37:
+		return "stwu"
+
+	elif get_op(instr) == 38:
+		return "stb"
+
+	elif get_op(instr) == 39:
+		return "stbu"
+
+	elif get_op(instr) == 40:
+		return "lhz"
+
+	elif get_op(instr) == 41:
+		return "lhzu"
+
+	elif get_op(instr) == 44:
+		return "sth"
+
+	elif get_op(instr) == 45:
+		return "sthu"
+
+	else:
+		return "unknown"
+
+def get_sprn_name(sprn):
+		if sprn == 0x01a:
+			return "SRR0"
+		elif sprn == 0x01b:
+			return "SRR1"
+		elif sprn == 0x3b2:
+			return "MMUCR"
+		elif sprn == 0x030:
+			return "PID"
+		elif sprn == 0x03f:
+			return "IVPR"
+		elif sprn == 0x3b3:
+			return "CCR0"
+		elif sprn == 0x378:
+			return "CCR1"
+		elif sprn == 0x11f:
+			return "PVR"
+		elif sprn == 0x03d:
+			return "DEAR"
+		elif sprn == 0x03e:
+			return "ESR"
+		elif sprn == 0x134:
+			return "DBCR0"
+		elif sprn == 0x135:
+			return "DBCR1"
+		elif sprn == 0x11c:
+			return "TBWL"
+		elif sprn == 0x11d:
+			return "TBWU"
+		elif sprn == 0x016:
+			return "DEC"
+		elif sprn == 0x150:
+			return "TSR"
+		elif sprn == 0x154:
+			return "TCR"
+		elif sprn == 0x110:
+			return "SPRG0"
+		elif sprn == 0x111:
+			return "SPRG1"
+		elif sprn == 0x112:
+			return "SPRG2"
+		elif sprn == 0x113:
+			return "SPRG3"
+		elif sprn == 0x114:
+			return "SPRG4"
+		elif sprn == 0x115:
+			return "SPRG5"
+		elif sprn == 0x116:
+			return "SPRG6"
+		elif sprn == 0x117:
+			return "SPRG7"
+		elif sprn == 0x190:
+			return "IVOR0"
+		elif sprn == 0x191:
+			return "IVOR1"
+		elif sprn == 0x192:
+			return "IVOR2"
+		elif sprn == 0x193:
+			return "IVOR3"
+		elif sprn == 0x194:
+			return "IVOR4"
+		elif sprn == 0x195:
+			return "IVOR5"
+		elif sprn == 0x196:
+			return "IVOR6"
+		elif sprn == 0x197:
+			return "IVOR7"
+		elif sprn == 0x198:
+			return "IVOR8"
+		elif sprn == 0x199:
+			return "IVOR9"
+		elif sprn == 0x19a:
+			return "IVOR10"
+		elif sprn == 0x19b:
+			return "IVOR11"
+		elif sprn == 0x19c:
+			return "IVOR12"
+		elif sprn == 0x19d:
+			return "IVOR13"
+		elif sprn == 0x19e:
+			return "IVOR14"
+		elif sprn == 0x19f:
+			return "IVOR15"
+		else:
+			return "UNKNOWN"
+
+def get_special(instr):
+	if get_op(instr) == 31:
+		if (get_xop(instr) == 339) or (get_xop(instr) == 467):
+			sprn = get_sprn(instr);
+			return ("- sprn 0x%03x %8s" % (sprn, get_sprn_name(sprn)))
+		elif (get_xop(instr) == 323 ) or (get_xop(instr) == 451):
+			return ("- dcrn 0x%03x" % get_dcrn(instr))
+		elif (get_xop(instr) == 978 ) or (get_xop(instr) == 451):
+			return ("- ws -> %8s" % get_tlbwe_type(instr))
+	return ""
 
 ##### Main code
 
@@ -206,20 +450,24 @@
                 '4'     : d4,
                 '5'     : d5    }
 
-        try:
-
-            if defs.has_key(str(event)):
-                print defs[str(event)] % args
-            else:
-                if defs.has_key(str(0)): print defs[str(0)] % args
-        except TypeError:
-            if defs.has_key(str(event)):
-                print defs[str(event)]
-                print args
-            else:
-                if defs.has_key(str(0)):
-                    print defs[str(0)]
+        # some event types need more than just formats mapping they are if/elif
+        # chained here and the last default else is the mapping via formats
+        if event == 0x00020019:
+            pdata = (tsc, reltsc, vcpu_id, pid, d1, d2, d3, get_name(d1), get_special(d1))
+            print "%d (+%12d)  PPC_INSTR vcpu = 0x%08x  pid = 0x%08x [ instr = 0x%08x, pc = 0x%08x, emul = %01d, mnemonic = %8s %s" % pdata
+        else:
+            try:
+                if defs.has_key(str(event)):
+                    print defs[str(event)] % args
+                else:
+                    if defs.has_key(str(0)): print defs[str(0)] % args
+            except TypeError:
+                if defs.has_key(str(event)):
+                    print defs[str(event)]
                     print args
-
+                else:
+                    if defs.has_key(str(0)):
+                        print defs[str(0)]
+                        print args
 
     except IOError, struct.error: sys.exit()

[PATCH 8/9] kvm-userspace: kvmtrace_format: add statistic section

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

Usually people don't want to read thousands of trace log lines to interpret
the data, a condensed statistic about the traced events is usually better
to read.
This patch adds a new command line switch -s that tells kvmtrace_format to
generate statistics while processing the trace records. Those statistics are
then printed at the end of the output.
This patch contains a statistic function for the ppc instruction emulation.
An example output might look like that:

      mnemonic +      count
---------------+-----------
        wrteei |       1260
         mfmsr |        977
         mtspr |        895
         wrtee |        742
         mfspr |        534
           rfi |        179
         mtmsr |         90
           lbz |         53
           stb |         28
           sum =       4758
[...] more detailed statistics about spr, dcr and tlb usage

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 kvmtrace_format |   73 +++++++++++++++++++++++++++++++++++++++++++++++++++-----
 1 file changed, 67 insertions(+), 6 deletions(-)

[diff]
diff --git a/user/kvmtrace_format b/user/kvmtrace_format
--- a/user/kvmtrace_format
+++ b/user/kvmtrace_format
@@ -4,7 +4,7 @@
 
 # Program for reformatting trace buffer output according to user-supplied rules
 
-import re, sys, string, signal, struct, os, getopt
+import re, sys, string, signal, struct, os, getopt, operator
 
 def usage():
     print >> sys.stderr, \
@@ -29,6 +29,12 @@
           this script may not be able to keep up with the output of kvmtrace
           if it is piped directly.  In these circumstances you should have
           kvmtrace output to a file for processing off-line.
+
+          kvmtrace_format has the following additional switches
+          -c mhz - specifies the mhz of the traced machine used to convert
+                   cycle data in trace records into time
+          -s     - if this switch is set additional trace statistics are
+                   created and printed at the end of the output
           """
     sys.exit(1)
 
@@ -60,6 +66,33 @@
     interrupted = 1
 
 # ppc instruction decoding for event type 0x00020019 (PPC_INSTR)
+# some globals for statistic summaries
+stat_ppc_instr_mnemonic = {};
+stat_ppc_instr_spr = {};
+stat_ppc_instr_dcr = {};
+stat_ppc_instr_tlb = {};
+
+def ppc_instr_print_summary(sortedlist, colname):
+	print "\n\n%14s + %10s" % (colname, "count")
+	print "%s" % (15*"-"+"+"+11*"-")
+	sum = 0
+	for value, key in sortedlist:
+		sum += key
+		print "%14s | %10d" % (value, key)
+	print "%14s = %10d" % ("sum", sum)
+
+
+def ppc_instr_summary():
+	# don't print empty statistics
+        if stat_ppc_instr_mnemonic:
+		ppc_instr_print_summary(sorted(stat_ppc_instr_mnemonic.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic")
+        if stat_ppc_instr_spr:
+		ppc_instr_print_summary(sorted(stat_ppc_instr_spr.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic-spr")
+        if stat_ppc_instr_dcr:
+		ppc_instr_print_summary(sorted(stat_ppc_instr_dcr.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic-dcr")
+        if stat_ppc_instr_tlb:
+		ppc_instr_print_summary(sorted(stat_ppc_instr_tlb.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic-tlb")
+
 def get_op(instr):
         return (instr >> 26);
 
@@ -293,28 +326,53 @@
 			return "UNKNOWN"
 
 def get_special(instr):
+	name = get_name(instr);
+	if stat_ppc_instr_mnemonic.has_key(name):
+		stat_ppc_instr_mnemonic[name] += 1
+	else:
+		stat_ppc_instr_mnemonic[name] = 1
+
 	if get_op(instr) == 31:
 		if (get_xop(instr) == 339) or (get_xop(instr) == 467):
 			sprn = get_sprn(instr);
-			return ("- sprn 0x%03x %8s" % (sprn, get_sprn_name(sprn)))
+			sprn_name = get_sprn_name(sprn);
+			stat_idx = name+"-"+sprn_name
+			if stat_ppc_instr_spr.has_key(stat_idx):
+				stat_ppc_instr_spr[stat_idx] += 1
+			else:
+				stat_ppc_instr_spr[stat_idx] = 1
+			return ("- sprn 0x%03x %8s" % (sprn, sprn_name))
 		elif (get_xop(instr) == 323 ) or (get_xop(instr) == 451):
-			return ("- dcrn 0x%03x" % get_dcrn(instr))
+			dcrn = get_dcrn(instr);
+			stat_idx = name+"-"+("%04X"%dcrn)
+			if stat_ppc_instr_dcr.has_key(stat_idx):
+				stat_ppc_instr_dcr[stat_idx] += 1
+			else:
+				stat_ppc_instr_dcr[stat_idx] = 1
+			return ("- dcrn 0x%03x" % dcrn)
 		elif (get_xop(instr) == 978 ) or (get_xop(instr) == 451):
-			return ("- ws -> %8s" % get_tlbwe_type(instr))
+			tlbwe_type = get_tlbwe_type(instr)
+			stat_idx = name+"-"+tlbwe_type
+			if stat_ppc_instr_tlb.has_key(stat_idx):
+				stat_ppc_instr_tlb[stat_idx] += 1
+			else:
+				stat_ppc_instr_tlb[stat_idx] = 1
+			return ("- ws -> %8s" % tlbwe_type)
 	return ""
 
 ##### Main code
 
 mhz = 0
+summary = False
 
 if len(sys.argv) < 2:
     usage()
 
 try:
-    opts, arg = getopt.getopt(sys.argv[1:], "c:" )
-
+    opts, arg = getopt.getopt(sys.argv[1:], "sc:" )
     for opt in opts:
         if opt[0] == '-c' : mhz = int(opt[1])
+        if opt[0] == '-s' : summary = True
 
 except getopt.GetoptError:
     usage()
@@ -471,3 +529,6 @@
                         print args
 
     except IOError, struct.error: sys.exit()
+
+if summary:
+	ppc_instr_summary()

[PATCH 9/9] kvm-userspace: kvmtrace: rename cycles to timestamp

[ehrhardt]

From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>

Due to the fact that the cycle counter is now completely replaced by the more
generic time based code (getnstimeofday) this patch renames all occurances of
the old cycle code to make it clear that this is now a timestamp.
Due to some values now growing a big larger (relts) the patch also
increases the print width of those values.

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
 formats         |   50 +++++++++++++++++++++++++-------------------------
 kvmtrace_format |   41 +++++++++++++++++------------------------
 2 files changed, 42 insertions(+), 49 deletions(-)

[diff]

diff --git a/user/formats b/user/formats
--- a/user/formats
+++ b/user/formats
@@ -1,31 +1,31 @@
-0x00000000  %(tsc)d (+%(reltsc)8d)  unknown (0x%(event)016x) vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x ]
+0x00000000  %(ts)d (+%(relts)12d)  unknown (0x%(event)016x) vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x ]
 
-0x00010001  %(tsc)d (+%(reltsc)8d)  VMENTRY       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
-0x00010002  %(tsc)d (+%(reltsc)8d)  VMEXIT        vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ exitcode = 0x%(1)08x, rip = 0x%(3)08x %(2)08x ]
-0x00020001  %(tsc)d (+%(reltsc)8d)  PAGE_FAULT    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
-0x00020002  %(tsc)d (+%(reltsc)8d)  INJ_VIRQ      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x00020003  %(tsc)d (+%(reltsc)8d)  REDELIVER_EVT vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x00020004  %(tsc)d (+%(reltsc)8d)  PEND_INTR     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x00020005  %(tsc)d (+%(reltsc)8d)  IO_READ       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
-0x00020006  %(tsc)d (+%(reltsc)8d)  IO_WRITE      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
-0x00020007  %(tsc)d (+%(reltsc)8d)  CR_READ       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
-0x00020008  %(tsc)d (+%(reltsc)8d)  CR_WRITE      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
-0x00020009  %(tsc)d (+%(reltsc)8d)  DR_READ       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
-0x0002000A  %(tsc)d (+%(reltsc)8d)  DR_WRITE      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
-0x0002000B  %(tsc)d (+%(reltsc)8d)  MSR_READ      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
-0x0002000C  %(tsc)d (+%(reltsc)8d)  MSR_WRITE     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
-0x0002000D  %(tsc)d (+%(reltsc)8d)  CPUID         vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ func = 0x%(1)08x, eax = 0x%(2)08x, ebx = 0x%(3)08x, ecx = 0x%(4)08x edx = 0x%(5)08x]
-0x0002000E  %(tsc)d (+%(reltsc)8d)  INTR          vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x0002000F  %(tsc)d (+%(reltsc)8d)  NMI           vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
-0x00020010  %(tsc)d (+%(reltsc)8d)  VMMCALL       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ func = 0x%(1)08x ]
-0x00020011  %(tsc)d (+%(reltsc)8d)  HLT           vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
-0x00020012  %(tsc)d (+%(reltsc)8d)  CLTS          vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
-0x00020013  %(tsc)d (+%(reltsc)8d)  LMSW          vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ value = 0x%(1)08x ]
-0x00020014  %(tsc)d (+%(reltsc)8d)  APIC_ACCESS   vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ offset = 0x%(1)08x ]
-0x00020015  %(tsc)d (+%(reltsc)8d)  TDP_FAULT     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
+0x00010001  %(ts)d (+%(relts)12d)  VMENTRY       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
+0x00010002  %(ts)d (+%(relts)12d)  VMEXIT        vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ exitcode = 0x%(1)08x, rip = 0x%(3)08x %(2)08x ]
+0x00020001  %(ts)d (+%(relts)12d)  PAGE_FAULT    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
+0x00020002  %(ts)d (+%(relts)12d)  INJ_VIRQ      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x00020003  %(ts)d (+%(relts)12d)  REDELIVER_EVT vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x00020004  %(ts)d (+%(relts)12d)  PEND_INTR     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x00020005  %(ts)d (+%(relts)12d)  IO_READ       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
+0x00020006  %(ts)d (+%(relts)12d)  IO_WRITE      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
+0x00020007  %(ts)d (+%(relts)12d)  CR_READ       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
+0x00020008  %(ts)d (+%(relts)12d)  CR_WRITE      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
+0x00020009  %(ts)d (+%(relts)12d)  DR_READ       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
+0x0002000A  %(ts)d (+%(relts)12d)  DR_WRITE      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
+0x0002000B  %(ts)d (+%(relts)12d)  MSR_READ      vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
+0x0002000C  %(ts)d (+%(relts)12d)  MSR_WRITE     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
+0x0002000D  %(ts)d (+%(relts)12d)  CPUID         vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ func = 0x%(1)08x, eax = 0x%(2)08x, ebx = 0x%(3)08x, ecx = 0x%(4)08x edx = 0x%(5)08x]
+0x0002000E  %(ts)d (+%(relts)12d)  INTR          vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x0002000F  %(ts)d (+%(relts)12d)  NMI           vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
+0x00020010  %(ts)d (+%(relts)12d)  VMMCALL       vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ func = 0x%(1)08x ]
+0x00020011  %(ts)d (+%(relts)12d)  HLT           vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
+0x00020012  %(ts)d (+%(relts)12d)  CLTS          vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x
+0x00020013  %(ts)d (+%(relts)12d)  LMSW          vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ value = 0x%(1)08x ]
+0x00020014  %(ts)d (+%(relts)12d)  APIC_ACCESS   vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ offset = 0x%(1)08x ]
+0x00020015  %(ts)d (+%(relts)12d)  TDP_FAULT     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
 # ppc: tlb traces
 0x00020016  GTLB_WRITE    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
 0x00020017  STLB_WRITE    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
 0x00020018  STLB_INVAL    vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
 # ppc: instruction emulation - this type is handled more complex in kvmtrace_format, but listed to show the eventid and transported data
-#0x00020019  %(tsc)d (+%(reltsc)8d)  PPC_INSTR     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ instr = 0x%(1)08x, pc = 0x%(2)08x, emul = 0x%(3)08x, nsec = %(4)08d ]
+#0x00020019  %(ts)d (+%(relts)12d)  PPC_INSTR     vcpu = 0x%(vcpu)08x  pid = 0x%(pid)08x [ instr = 0x%(1)08x, pc = 0x%(2)08x, emul = 0x%(3)08x, nsec = %(4)08d ]
diff --git a/user/kvmtrace_format b/user/kvmtrace_format
--- a/user/kvmtrace_format
+++ b/user/kvmtrace_format
@@ -17,7 +17,7 @@
           {event_id}{whitespace}{text format string}
 
           The textual format string may include format specifiers, such as:
-            %(tsc)d, %(event)d, %(pid)d %(vcpu)d %(1)d, %(2)d,
+            %(ts)d, %(event)d, %(pid)d %(vcpu)d %(1)d, %(2)d,
 	    %(3)d, %(4)d, %(5)d
           [ the 'd' format specifier outputs in decimal, alternatively 'x'
             will output in hexadecimal and 'o' will output in octal ]
@@ -31,8 +31,6 @@
           kvmtrace output to a file for processing off-line.
 
           kvmtrace_format has the following additional switches
-          -c mhz - specifies the mhz of the traced machine used to convert
-                   cycle data in trace records into time
           -s     - if this switch is set additional trace statistics are
                    created and printed at the end of the output
           """
@@ -362,7 +360,6 @@
 
 ##### Main code
 
-mhz = 0
 summary = False
 
 if len(sys.argv) < 2:
@@ -371,7 +368,6 @@
 try:
     opts, arg = getopt.getopt(sys.argv[1:], "sc:" )
     for opt in opts:
-        if opt[0] == '-c' : mhz = int(opt[1])
         if opt[0] == '-s' : summary = True
 
 except getopt.GetoptError:
@@ -388,12 +384,12 @@
 # structure of trace record (as output by kvmtrace):
 # HDR(I) {TSC(Q)} D1(I) D2(I) D3(I) D4(I) D5(I)
 #
-# HDR consists of EVENT:28:, n_data:3:, tsc_in:1:
+# HDR consists of EVENT:28:, n_data:3:, ts_in:1:
 # pid:32, vcpu_id:32
 # EVENT means Event ID
 # n_data means number of data (like D1, D2, ...)
-# tsc_in means TSC data exists(1) or not(0).
-# if tsc_in == 0, TSC(Q) does not exists.
+# ts_in means Timestamp data exists(1) or not(0).
+# if ts_in == 0, TSC(Q) does not exists.
 #
 HDRREC = "<III"
 TSCREC = "<Q"
@@ -404,7 +400,7 @@
 D5REC  = "<IIIII"
 KMAGIC  = "<I"
 
-last_tsc = 0
+last_ts = 0
 
 i=0
 
@@ -441,7 +437,7 @@
 	(event, pid, vcpu_id) = struct.unpack(HDRREC, line)
 
         n_data = event >> 28 & 0x7
-        tsc_in = event >> 31
+        ts_in = event >> 31
 
         d1 = 0
         d2 = 0
@@ -449,13 +445,13 @@
         d4 = 0
         d5 = 0
 
-        tsc = 0
+        ts = 0
 
-        if tsc_in == 1:
+        if ts_in == 1:
             line = sys.stdin.read(struct.calcsize(TSCREC))
             if not line:
                 break
-            tsc = struct.unpack(TSCREC, line)[0]
+            ts = struct.unpack(TSCREC, line)[0]
         if n_data == 1:
             line = sys.stdin.read(struct.calcsize(D1REC))
             if not line:
@@ -486,20 +482,17 @@
 
         # provide relative TSC
 
-        if last_tsc > 0 and tsc_in == 1:
-            reltsc = tsc - last_tsc
+        if last_ts > 0 and ts_in == 1:
+            relts = ts - last_ts
         else:
-            reltsc = 0
+            relts = 0
 
-        if tsc_in == 1:
-            last_tsc = tsc
+        if ts_in == 1:
+            last_ts = ts
 
-        if mhz:
-            tsc = tsc / (mhz*1000000.0)
-
-        args = {'tsc'   : tsc,
+        args = {'ts'   : ts,
                 'event' : event,
-                'reltsc': reltsc,
+                'relts': relts,
 		'pid'   : pid,
 		'vcpu'  : vcpu_id,
                 '1'     : d1,
@@ -511,7 +504,7 @@
         # some event types need more than just formats mapping they are if/elif
         # chained here and the last default else is the mapping via formats
         if event == 0x00020019:
-            pdata = (tsc, reltsc, vcpu_id, pid, d1, d2, d3, get_name(d1), get_special(d1))
+            pdata = (ts, relts, vcpu_id, pid, d1, d2, d3, get_name(d1), get_special(d1))
             print "%d (+%12d)  PPC_INSTR vcpu = 0x%08x  pid = 0x%08x [ instr = 0x%08x, pc = 0x%08x, emul = %01d, mnemonic = %8s %s" % pdata
         else:
             try:

Re: [PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday

[Avi Kivity]

ehrhardt@linux.vnet.ibm.com wrote:
> From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
>
> The current kvmtrace code uses get_cycles() while the interpretation would be
> easier using using nanoseconds. Getnstimeofday should give the same accuracy
> as get_cycles on all architectures but at a better unit (e.g. comparable
> between two hosts with different frequencies.
>
> The implementation of kvmtrace uses a 64 bit cycle variable while get_cycles
> only provided a unsigned long which is != 64 bit on 32 bit architectures.
> Since this patch introduced getnstimeofday we can addtionally merge the
> tv_sec portion of the struct timespec returned to use the full 64 bit
> of the trace interface and therefor avoid some wraparounds. This merge
> is done always if the two values of a struct timespec fit into the u64.
>
> An alternative might be ktime_t instead of u64 and using as Sheng Yang
> suggested and ktime_get(), I had no time to test&compare that yet.
> Any comments or requirements from others what to prefer here ?
>
> Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
> ---
>
> [diffstat]
>  kvm_trace.c |    9 ++++++++-
>  1 file changed, 8 insertions(+), 1 deletion(-)
>
> [diff]
>
> diff --git a/virt/kvm/kvm_trace.c b/virt/kvm/kvm_trace.c
> --- a/virt/kvm/kvm_trace.c
> +++ b/virt/kvm/kvm_trace.c
> @@ -56,6 +56,7 @@
>  	struct kvm_vcpu *vcpu;
>  	int    i, size;
>  	u32    extra;
> +	struct timespec tv;
>  
>  	if (unlikely(kt->trace_state != KVM_TRACE_STATE_RUNNING))
>  		return;
> @@ -73,7 +74,13 @@
>  			| TRACE_REC_NUM_DATA_ARGS(extra);
>  	
>  	if (p->cycle_in) {
> -		rec.u.cycle.cycle_u64 = get_cycles();
> +		getnstimeofday(&tv);
> +		/* compress both struct tv values into u64 on 32 bit archs */
> +		if (sizeof(tv) == sizeof(u64))
> +			rec.u.cycle.cycle_u64 = 
> +				(((u64)tv.tv_sec) << 32) | tv.tv_nsec;
> +		else
> +			rec.u.cycle.cycle_u64 = tv.tv_nsec;
>  (*args, u32);
>   

Surely, different results on 32-bit and 64-bit aren't what's wanted.  I 
guess ktime_get() is better.

-- 
error compiling committee.c: too many arguments to function