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

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

[ehrhardt]

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

Changing kvmtrace code to use timestamps and add powerpc support.

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

Updated in v3:
	patch 2/8 now uses ktime_get() for all architectures as discussed

The series contains eight patches (3 generic / 5 powerpc code):

Subject: [PATCH 1/8] 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/8] kvmtrace: replace get_cycles with getnstimeofday
	use a new timestamp source (ktime_get) which makes it 32/64 bit save,
	comparable and does not need an arch hook
Subject: [PATCH 3/8] kvmppc: kvmtrace: enable KVM_TRACE building for powerpc
	enable KVM_TRACE for powerpc in Kconfig/Makefile
Subject: [PATCH 4/8] 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/8] kvmppc: kvmtrace: trace powerpc instruction emulation
	use KVM_TRACE to track instruction emulation overhead
Subject: [PATCH 6/8] kvm-userspace: kvmtrace_format: add ppc instruction emulation
	extension to kvmtrace_format to handle complex event types e.g. ppc
	instructon emulation
Subject: [PATCH 7/8] kvm-userspace: kvmtrace_format: add statistic section
	adding statistic creation/prsentation to the kvmtrace data processing
Subject: [PATCH 8/8] 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         |   18 +-
 13 files changed, 452 insertions(+), 106 deletions(-)

[PATCH 1/8] 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/8] kvmtrace: replace get_cycles with ktime_get v3

[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. ktime_get() should give at least the same
accuracy as get_cycles on all architectures (even better on 32bit archs) but
at a better unit (e.g. comparable between hosts with different frequencies.

V3 of this patch now uses the ktime_get() as discussed on the mailing list.
This ensures that the granularity is always 64 bit on all architetcures and
in the background getnstimeofday is used giving us ns granularity.
Additionally this gives us only one generic implementation without need for
an arch hook.

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

[diffstat]
 include/linux/kvm.h  |    6 +++---
 virt/kvm/kvm_trace.c |   18 +++++++++---------
 2 files changed, 12 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
@@ -322,12 +322,12 @@
 	__u32 vcpu_id;
 	union {
 		struct {
-			__u64 cycle_u64;
+			ktime_t timestamp;
 			__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,
@@ -69,20 +69,20 @@
 	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) {
-		rec.u.cycle.cycle_u64 = get_cycles();
+	if (p->timestamp_in) {
+		rec.u.timestamp.timestamp = ktime_get();
 
 		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/8] 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/8] 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/8] 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 6/8] 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 7/8] 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 8/8] kvm-userspace: kvmtrace: cycles are now ktime_t timestamps

[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 0/8] kvmtrace: powerpc support and timestamps for KVM_TRACE v3

[Avi Kivity]

ehrhardt@linux.vnet.ibm.com wrote:
> From: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
>
> Changing kvmtrace code to use timestamps and add powerpc support.
>
> This is the revised series including the feedback from the earlier submission
> last week. I now also added the userspace changes which complete the series.
>
>   

All applied, thanks.

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