* [PATCH 1/9] kvmtrace: Remove use of bit fields in kvm trace structure v3
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 10:54 ` [PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday ehrhardt
` (7 subsequent siblings)
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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);
}
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
2008-07-10 10:54 ` [PATCH 1/9] kvmtrace: Remove use of bit fields in kvm trace structure v3 ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 15:15 ` Avi Kivity
2008-07-10 10:54 ` [PATCH 3/9] kvmtrace: rename cycles to timestamp ehrhardt
` (6 subsequent siblings)
8 siblings, 1 reply; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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);
^ permalink raw reply [flat|nested] 11+ messages in thread* Re: [PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday
2008-07-10 10:54 ` [PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday ehrhardt
@ 2008-07-10 15:15 ` Avi Kivity
0 siblings, 0 replies; 11+ messages in thread
From: Avi Kivity @ 2008-07-10 15:15 UTC (permalink / raw)
To: ehrhardt; +Cc: kvm, hollisb, kvm-ppc
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* [PATCH 3/9] kvmtrace: rename cycles to timestamp
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
2008-07-10 10:54 ` [PATCH 1/9] kvmtrace: Remove use of bit fields in kvm trace structure v3 ehrhardt
2008-07-10 10:54 ` [PATCH 2/9] kvmtrace: replace get_cycles with getnstimeofday ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 10:54 ` [PATCH 3/9] kvmppc: kvmtrace: enable KVM_TRACE building for powerpc ehrhardt
` (5 subsequent siblings)
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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);
}
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 3/9] kvmppc: kvmtrace: enable KVM_TRACE building for powerpc
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
` (2 preceding siblings ...)
2008-07-10 10:54 ` [PATCH 3/9] kvmtrace: rename cycles to timestamp ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 10:54 ` [PATCH 4/9] kvmppc: kvmtrace: adds trace points for ppc tlb activity v2 ehrhardt
` (4 subsequent siblings)
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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)
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 4/9] kvmppc: kvmtrace: adds trace points for ppc tlb activity v2
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
` (3 preceding siblings ...)
2008-07-10 10:54 ` [PATCH 3/9] kvmppc: kvmtrace: enable KVM_TRACE building for powerpc ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 10:54 ` [PATCH 5/9] kvmppc: kvmtrace: trace powerpc instruction emulation ehrhardt
` (3 subsequent siblings)
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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(¤t->mm->mmap_sem);
}
@@ -216,8 +224,13 @@
/* XXX Replace loop with fancy data structures. */
down_write(¤t->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(¤t->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
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 5/9] kvmppc: kvmtrace: trace powerpc instruction emulation
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
` (4 preceding siblings ...)
2008-07-10 10:54 ` [PATCH 4/9] kvmppc: kvmtrace: adds trace points for ppc tlb activity v2 ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 10:54 ` [PATCH 7/9] kvm-userspace: kvmtrace_format: add ppc " ehrhardt
` (2 subsequent siblings)
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 7/9] kvm-userspace: kvmtrace_format: add ppc instruction emulation
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
` (5 preceding siblings ...)
2008-07-10 10:54 ` [PATCH 5/9] kvmppc: kvmtrace: trace powerpc instruction emulation ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 10:54 ` [PATCH 8/9] kvm-userspace: kvmtrace_format: add statistic section ehrhardt
2008-07-10 10:54 ` [PATCH 9/9] kvm-userspace: kvmtrace: rename cycles to timestamp ehrhardt
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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()
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 8/9] kvm-userspace: kvmtrace_format: add statistic section
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
` (6 preceding siblings ...)
2008-07-10 10:54 ` [PATCH 7/9] kvm-userspace: kvmtrace_format: add ppc " ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
2008-07-10 10:54 ` [PATCH 9/9] kvm-userspace: kvmtrace: rename cycles to timestamp ehrhardt
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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()
^ permalink raw reply [flat|nested] 11+ messages in thread* [PATCH 9/9] kvm-userspace: kvmtrace: rename cycles to timestamp
2008-07-10 10:54 [PATCH 0/5] kvmtrace: powerpc support and timestamps for KVM_TRACE ehrhardt
` (7 preceding siblings ...)
2008-07-10 10:54 ` [PATCH 8/9] kvm-userspace: kvmtrace_format: add statistic section ehrhardt
@ 2008-07-10 10:54 ` ehrhardt
8 siblings, 0 replies; 11+ messages in thread
From: ehrhardt @ 2008-07-10 10:54 UTC (permalink / raw)
To: kvm; +Cc: hollisb, avi, kvm-ppc, 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:
^ permalink raw reply [flat|nested] 11+ messages in thread