Skip to contentSkip to conversation

kvm: powerpc: add exit timing statistics

PATCH In review Ehrhardt Christian 2 participants 3 messages Nov 4, 2008 – Nov 7, 2008

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

PATCH 1/1 kvm: powerpc: add exit timing statistics

From: Christian Ehrhardt <[email protected]>

Other existing kvm stats are either just counters (kvm_stat) reported for kvm generally or trace based aproaches like kvm_trace.
For kvm on powerpc we had the need to track the timings of the different exit types. While this could be achieved parsing data created with a kvm_trace extension this adds too muhc overhead (at least on embedded powerpc) slowing down the workloads we wanted to measure.

Therefore this patch adds a in kernel exit timing statistic to the powerpc kvm code. These statistic is available per vm&vcpu under the kvm debugfs directory. As this statistic is low, but still some overhead it can be enabled via a .config entry and should be off by default.

Since this patch touched all powerpc kvm_stat code anyway this code is now merged and simpliefied together with the exit timing statistic code (still working with exit timing disabled in .config).

Here is a sample output (after postprocessing with the awk script I'll post in reply to this patch) how the results look like. sum of time 27504898

        MMIO: count        824 min         51 max        555 sum                75825 sum_quad              9232871 avg          92.0206 stddev       52.318 %  0.28
         DCR: count        140 min         44 max         92 sum                 6746 sum_quad               327658 avg          48.1857 stddev        4.307 %  0.02
      SIGNAL: count          2 min        309 max        993 sum                 1302 sum_quad              1081530 avg         651.0000 stddev      342.000 %  0.00
    ITLBREAL: count        293 min         11 max         14 sum                 3515 sum_quad                42175 avg          11.9966 stddev        0.155 %  0.01
    ITLBVIRT: count     113822 min         20 max        338 sum              2595412 sum_quad             60256824 avg          22.8024 stddev        3.074 %  9.44
    DTLBREAL: count        242 min         11 max         14 sum                 2908 sum_quad                34974 avg          12.0165 stddev        0.352 %  0.01
    DTLBVIRT: count      66687 min         21 max        329 sum              1530048 sum_quad             35434926 avg          22.9437 stddev        2.224 %  5.56
     SYSCALL: count         72 min          9 max         10 sum                  649 sum_quad                 5851 avg           9.0139 stddev        0.117 %  0.00
         ISI: count         56 min          9 max         10 sum                  506 sum_quad                 4574 avg           9.0357 stddev        0.186 %  0.00
         DSI: count         49 min          9 max         10 sum                  448 sum_quad                 4102 avg           9.1429 stddev        0.350 %  0.00
    EMULINST: count     211220 min          7 max       7700 sum              3292984 sum_quad           5797023806 avg          15.5903 stddev      164.931 % 11.97
         DEC: count       6582 min         49 max        322 sum               367567 sum_quad             22996737 avg          55.8443 stddev       19.373 %  1.34
      EXTINT: count          4 min         79 max        513 sum                  797 sum_quad               290423 avg         199.2500 stddev      181.398 %  0.00

TIMEINGUEST: count 399993 min 0 max 3952 sum 19626191 sum_quad 61148587807 avg 49.0663 stddev 387.900 % 71.36

---

[diffstat]

 arch/powerpc/include/asm/kvm_host.h         |   49 ++++++++
 arch/powerpc/include/asm/kvm_timing_stats.h |  142 ++++++++++++++++++++++++
 arch/powerpc/include/asm/mmu-44x.h          |    1
 arch/powerpc/kernel/asm-offsets.c           |   11 +
 arch/powerpc/kvm/Kconfig                    |    9 +
 arch/powerpc/kvm/booke.c                    |   35 +++---
 arch/powerpc/kvm/booke.h                    |    7 +
 arch/powerpc/kvm/booke_interrupts.S         |   24 ++++
 arch/powerpc/kvm/powerpc.c                  |  163 +++++++++++++++++++++++++++-
 9 files changed, 425 insertions(+), 16 deletions(-)

[diff]

arch/powerpc/include/asm/kvm_host.h +49 -0
@@ -71,7 +71,43 @@
 	u32 word2;
 };
 
+enum kvm_exit_types {
+	MMIO_EXITS,
+	DCR_EXITS,
+	SIGNAL_EXITS,
+	ITLB_REAL_MISS_EXITS,
+	ITLB_VIRT_MISS_EXITS,
+	DTLB_REAL_MISS_EXITS,
+	DTLB_VIRT_MISS_EXITS,
+	SYSCALL_EXITS,
+	ISI_EXITS,
+	DSI_EXITS,
+	EMULATED_INST_EXITS,
+	EMULATED_MTMSRWE_EXITS,
+	DEC_EXITS,
+	EXT_INTR_EXITS,
+	HALT_WAKEUP,
+	USR_PR_INST,
+	FP_UNAVAIL,
+	DEBUG_EXITS,
+	TIMEINGUEST,
+	__NUMBER_OF_KVM_EXIT_TYPES
+};
+
+#ifdef CONFIG_KVM_BOOKE_EXIT_TIMING
+/* allow access to big endian 32bit upper/lower parts and 64bit var */
+typedef union {
+	u64 tv64;
+	struct {
+		u32 tbu, tbl;
+	} tv32;
+} exit_timing_t;
+#endif
+
 struct kvm_arch {
+#ifdef CONFIG_KVM_BOOKE_EXIT_TIMING
+	unsigned int vm_id;
+#endif
 };
 
 struct kvm_vcpu_arch {
@@ -130,6 +166,19 @@
 	u32 dbcr0;
 	u32 dbcr1;
 
+#ifdef CONFIG_KVM_BOOKE_EXIT_TIMING
+	exit_timing_t timing_exit;
+	exit_timing_t timing_last_enter;
+	u32 last_exit_type;
+	u32 timing_count_type[__NUMBER_OF_KVM_EXIT_TYPES];
+	u64 timing_sum_duration[__NUMBER_OF_KVM_EXIT_TYPES];
+	u64 timing_sum_quad_duration[__NUMBER_OF_KVM_EXIT_TYPES];
+	u64 timing_min_duration[__NUMBER_OF_KVM_EXIT_TYPES];
+	u64 timing_max_duration[__NUMBER_OF_KVM_EXIT_TYPES];
+	u64 timing_last_exit;
+	struct dentry *debugfs_exit_timing;
+#endif
+
 	u32 last_inst;
 	ulong fault_dear;
 	ulong fault_esr;
arch/powerpc/include/asm/kvm_timing_stats.h new file +168 -0

168 lines not on this page · raw message

arch/powerpc/include/asm/mmu-44x.h +1 -0
@@ -56,6 +56,7 @@
 #ifndef __ASSEMBLY__
 
 extern unsigned int tlb_44x_hwater;
+extern unsigned int tlb_44x_index;
 
 typedef struct {
 	unsigned long id;
arch/powerpc/kernel/asm-offsets.c +11 -0
@@ -387,5 +387,16 @@
 	DEFINE(PTE_SHIFT, PTE_SHIFT);
 #endif
 
+#ifdef CONFIG_KVM_BOOKE_EXIT_TIMING
+	DEFINE(VCPU_TIMING_EXIT_TBU, offsetof(struct kvm_vcpu,
+						arch.timing_exit.tv32.tbu));
+	DEFINE(VCPU_TIMING_EXIT_TBL, offsetof(struct kvm_vcpu,
+						arch.timing_exit.tv32.tbl));
+	DEFINE(VCPU_TIMING_LAST_ENTER_TBU, offsetof(struct kvm_vcpu,
+					arch.timing_last_enter.tv32.tbu));
+	DEFINE(VCPU_TIMING_LAST_ENTER_TBL, offsetof(struct kvm_vcpu,
+					arch.timing_last_enter.tv32.tbl));
+#endif
+
 	return 0;
 }
arch/powerpc/kvm/Kconfig +9 -0
@@ -34,6 +34,15 @@
 	---help---
 	  KVM can run unmodified 440 guest kernels on 440 host processors.
 
+config KVM_BOOKE_EXIT_TIMING
+	bool "Trace detailed exit Timing"
+	depends on KVM && 44x
+	---help---
+	  Inserts code to trace timestamps for every exit/enter cycle. A per vcpu
+	  report is available in debugfs kvm/VM_###/VPCU_###_exit_timing.
+	  The overhead is relatively small, however it is not recommended for
+	  production environments.
+
 config KVM_TRACE
 	bool "KVM trace support"
 	depends on KVM && MARKERS && SYSFS
arch/powerpc/kvm/booke.c +22 -13
@@ -27,6 +27,7 @@
 #include <asm/cputable.h>
 #include <asm/uaccess.h>
 #include <asm/kvm_ppc.h>
+#include <asm/kvm_timing_stats.h>
 #include <asm/cacheflush.h>
 
 #include "booke.h"
@@ -183,6 +184,9 @@
 	enum emulation_result er;
 	int r = RESUME_HOST;
 
+	/* update before a new last_exit_type is rewritten */
+	update_timing_stats(vcpu);
+
 	local_irq_enable();
 
 	run->exit_reason = KVM_EXIT_UNKNOWN;
@@ -196,7 +200,7 @@
 		break;
 
 	case BOOKE_INTERRUPT_EXTERNAL:
-		vcpu->stat.ext_intr_exits++;
+		account_exit(vcpu, EXT_INTR_EXITS);
 		if (need_resched())
 			cond_resched();
 		r = RESUME_GUEST;
@@ -211,7 +215,7 @@
 		 * we do reschedule the host will fault over it. Perhaps we
 		 * should politely restore the host's entries to minimize
 		 * misses before ceding control. */
-		vcpu->stat.dec_exits++;
+		account_exit(vcpu, DEC_EXITS);
 		if (need_resched())
 			cond_resched();
 		r = RESUME_GUEST;
@@ -224,6 +228,7 @@
 			vcpu->arch.esr = vcpu->arch.fault_esr;
 			kvmppc_booke_queue_irqprio(vcpu, BOOKE_IRQPRIO_PROGRAM);
 			r = RESUME_GUEST;
+			account_exit(vcpu, USR_PR_INST);
 			break;
 		}
 
@@ -232,12 +237,12 @@
 		case EMULATE_DONE:
 			/* Future optimization: only reload non-volatiles if
 			 * they were actually modified by emulation. */
-			vcpu->stat.emulated_inst_exits++;
+			account_exit(vcpu, EMULATED_INST_EXITS);
 			r = RESUME_GUEST_NV;
 			break;
 		case EMULATE_DO_DCR:
 			run->exit_reason = KVM_EXIT_DCR;
-			vcpu->stat.dcr_exits++;
+			account_exit(vcpu, DCR_EXITS);
 			r = RESUME_HOST;
 			break;
 		case EMULATE_FAIL:
@@ -257,6 +262,7 @@
 
 	case BOOKE_INTERRUPT_FP_UNAVAIL:
 		kvmppc_booke_queue_irqprio(vcpu, BOOKE_IRQPRIO_FP_UNAVAIL);
+		account_exit(vcpu, FP_UNAVAIL);
 		r = RESUME_GUEST;
 		break;
 
@@ -264,20 +270,20 @@
 		vcpu->arch.dear = vcpu->arch.fault_dear;
 		vcpu->arch.esr = vcpu->arch.fault_esr;
 		kvmppc_booke_queue_irqprio(vcpu, BOOKE_IRQPRIO_DATA_STORAGE);
-		vcpu->stat.dsi_exits++;
+		account_exit(vcpu, DSI_EXITS);
 		r = RESUME_GUEST;
 		break;
 
 	case BOOKE_INTERRUPT_INST_STORAGE:
 		vcpu->arch.esr = vcpu->arch.fault_esr;
 		kvmppc_booke_queue_irqprio(vcpu, BOOKE_IRQPRIO_INST_STORAGE);
-		vcpu->stat.isi_exits++;
+		account_exit(vcpu, ISI_EXITS);
 		r = RESUME_GUEST;
 		break;
 
 	case BOOKE_INTERRUPT_SYSCALL:
 		kvmppc_booke_queue_irqprio(vcpu, BOOKE_IRQPRIO_SYSCALL);
-		vcpu->stat.syscall_exits++;
+		account_exit(vcpu, SYSCALL_EXITS);
 		r = RESUME_GUEST;
 		break;
 
@@ -293,7 +299,7 @@
 			kvmppc_booke_queue_irqprio(vcpu, BOOKE_IRQPRIO_DTLB_MISS);
 			vcpu->arch.dear = vcpu->arch.fault_dear;
 			vcpu->arch.esr = vcpu->arch.fault_esr;
-			vcpu->stat.dtlb_real_miss_exits++;
+			account_exit(vcpu, DTLB_REAL_MISS_EXITS);
 			r = RESUME_GUEST;
 			break;
 		}
@@ -310,13 +316,13 @@
 			 * invoking the guest. */
 			kvmppc_mmu_map(vcpu, eaddr, gfn, gtlbe->tid,
 			               gtlbe->word2);
-			vcpu->stat.dtlb_virt_miss_exits++;
+			account_exit(vcpu, DTLB_VIRT_MISS_EXITS);
 			r = RESUME_GUEST;
 		} else {
 			/* Guest has mapped and accessed a page which is not
 			 * actually RAM. */
 			r = kvmppc_emulate_mmio(run, vcpu);
-			vcpu->stat.mmio_exits++;
+			account_exit(vcpu, MMIO_EXITS);
 		}
 
 		break;
@@ -334,11 +340,11 @@
 		if (!gtlbe) {
 			/* The guest didn't have a mapping for it. */
 			kvmppc_booke_queue_irqprio(vcpu, BOOKE_IRQPRIO_ITLB_MISS);
-			vcpu->stat.itlb_real_miss_exits++;
+			account_exit(vcpu, ITLB_REAL_MISS_EXITS);
 			break;
 		}
 
-		vcpu->stat.itlb_virt_miss_exits++;
+		account_exit(vcpu, ITLB_VIRT_MISS_EXITS);
 
 		gfn = tlb_xlate(gtlbe, eaddr) >> PAGE_SHIFT;
 
@@ -370,6 +376,7 @@
 		mtspr(SPRN_DBSR, dbsr);
 
 		run->exit_reason = KVM_EXIT_DEBUG;
+		account_exit(vcpu, DEBUG_EXITS);
 		r = RESUME_HOST;
 		break;
 	}
@@ -390,7 +397,7 @@
 		if (signal_pending(current)) {
 			run->exit_reason = KVM_EXIT_INTR;
 			r = (-EINTR << 2) | RESUME_HOST | (r & RESUME_FLAG_NV);
-			vcpu->stat.signal_exits++;
+			account_exit(vcpu, SIGNAL_EXITS);
 		}
 	}
 
@@ -409,6 +416,8 @@
 	/* Eye-catching number so we know if the guest takes an interrupt
 	 * before it's programmed its own IVPR. */
 	vcpu->arch.ivpr = 0x55550000;
+
+	init_timing_stats(vcpu);
 
 	return kvmppc_core_vcpu_setup(vcpu);
 }
arch/powerpc/kvm/booke.h +6 -1
@@ -22,6 +22,7 @@
 
 #include <linux/types.h>
 #include <linux/kvm_host.h>
+#include <asm/kvm_timing_stats.h>
 
 /* interrupt priortity ordering */
 #define BOOKE_IRQPRIO_DATA_STORAGE 0
@@ -50,8 +51,12 @@
 
 	vcpu->arch.msr = new_msr;
 
-	if (vcpu->arch.msr & MSR_WE)
+	if (vcpu->arch.msr & MSR_WE) {
+		/* whatever exit it was before, this would clobber its timings
+		 * count MSR_WE wait's in seperate exit category */
+		account_exit(vcpu, EMULATED_MTMSRWE_EXITS);
 		kvm_vcpu_block(vcpu);
+	}
 }
 
 #endif /* __KVM_BOOKE_H__ */
arch/powerpc/kvm/booke_interrupts.S +24 -0
@@ -106,6 +106,18 @@
 
 	li	r6, 1
 	slw	r6, r6, r5
+
+#ifdef CONFIG_KVM_BOOKE_EXIT_TIMING
+	/* save exit time */
+..exit_tbu_overflow_loop:
+	mfspr	r7, SPRN_TBRU
+	mfspr	r8, SPRN_TBRL
+	mfspr	r9, SPRN_TBRU
+	cmpw	r9, r7
+	bne	..exit_tbu_overflow_loop
+	stw	r8, VCPU_TIMING_EXIT_TBL(r4)
+	stw	r9, VCPU_TIMING_EXIT_TBU(r4)
+#endif
 
 	/* Save the faulting instruction and all GPRs for emulation. */
 	andi.	r7, r6, NEED_INST_MASK
@@ -423,6 +435,18 @@
 	lwz	r3, VCPU_SPRG7(r4)
 	mtspr	SPRN_SPRG7, r3
 
+#ifdef CONFIG_KVM_BOOKE_EXIT_TIMING
+	/* save enter time */
+..enter_tbu_overflow_loop:
+	mfspr	r6, SPRN_TBRU
+	mfspr	r7, SPRN_TBRL
+	mfspr	r8, SPRN_TBRU
+	cmpw	r8, r6
+	bne	..enter_tbu_overflow_loop
+	stw	r7, VCPU_TIMING_LAST_ENTER_TBL(r4)
+	stw	r8, VCPU_TIMING_LAST_ENTER_TBU(r4)
+#endif
+
 	/* Finish loading guest volatiles and jump to guest. */
 	lwz	r3, VCPU_CTR(r4)
 	mtctr	r3
arch/powerpc/kvm/powerpc.c +160 -2

190 lines not on this page · raw message

#1 lore raw

This patch reports the square sum in addition to the classic sum/count (+min/max) to allow more details statistical post processing. That way you can process average, % of whole duration and using the square sum also the standard deviation.

A simple way to get these numbers with awk is:

#!/bin/bash
echo "processing file ${1}"
sumsum=awk 'BEGIN { csum=0; sumsum=0; count=0}{ csum=csum+$3; count++; sumsum = sumsum+$9;}END { printf("%s\n", sumsum)}' $1
echo "sum of time ${sumsum}"
awk '!/count 0/ { printf("%s",$0); printf(" avg %16.4lf stddev
%12.3lf %% %5.2f\n",$9/$3, sqrt($11/$3-(($9/$3)*($9/$3))), ($9/('$sumsum'/100))); }' $1

This runs awk twice, because for % of overall time you need the sum the durations and I personally don't like all those "rewind hacks" for awk.

Quoted 52 lines · Ehrhardt Christian

From: Christian Ehrhardt <[email protected]>

Other existing kvm stats are either just counters (kvm_stat) reported for kvm generally or trace based aproaches like kvm_trace.
For kvm on powerpc we had the need to track the timings of the different exit types. While this could be achieved parsing data created with a kvm_trace extension this adds too muhc overhead (at least on embedded powerpc) slowing down the workloads we wanted to measure.

Therefore this patch adds a in kernel exit timing statistic to the powerpc kvm code. These statistic is available per vm&vcpu under the kvm debugfs directory. As this statistic is low, but still some overhead it can be enabled via a .config entry and should be off by default.

Since this patch touched all powerpc kvm_stat code anyway this code is now merged and simpliefied together with the exit timing statistic code (still working with exit timing disabled in .config).

Here is a sample output (after postprocessing with the awk script I'll post in reply to this patch) how the results look like. sum of time 27504898

        MMIO: count        824 min         51 max        555 sum                75825 sum_quad              9232871 avg          92.0206 stddev       52.318 %  0.28
         DCR: count        140 min         44 max         92 sum                 6746 sum_quad               327658 avg          48.1857 stddev        4.307 %  0.02
      SIGNAL: count          2 min        309 max        993 sum                 1302 sum_quad              1081530 avg         651.0000 stddev      342.000 %  0.00
    ITLBREAL: count        293 min         11 max         14 sum                 3515 sum_quad                42175 avg          11.9966 stddev        0.155 %  0.01
    ITLBVIRT: count     113822 min         20 max        338 sum              2595412 sum_quad             60256824 avg          22.8024 stddev        3.074 %  9.44
    DTLBREAL: count        242 min         11 max         14 sum                 2908 sum_quad                34974 avg          12.0165 stddev        0.352 %  0.01
    DTLBVIRT: count      66687 min         21 max        329 sum              1530048 sum_quad             35434926 avg          22.9437 stddev        2.224 %  5.56
     SYSCALL: count         72 min          9 max         10 sum                  649 sum_quad                 5851 avg           9.0139 stddev        0.117 %  0.00
         ISI: count         56 min          9 max         10 sum                  506 sum_quad                 4574 avg           9.0357 stddev        0.186 %  0.00
         DSI: count         49 min          9 max         10 sum                  448 sum_quad                 4102 avg           9.1429 stddev        0.350 %  0.00
    EMULINST: count     211220 min          7 max       7700 sum              3292984 sum_quad           5797023806 avg          15.5903 stddev      164.931 % 11.97
         DEC: count       6582 min         49 max        322 sum               367567 sum_quad             22996737 avg          55.8443 stddev       19.373 %  1.34
      EXTINT: count          4 min         79 max        513 sum                  797 sum_quad               290423 avg         199.2500 stddev      181.398 %  0.00

TIMEINGUEST: count 399993 min 0 max 3952 sum 19626191 sum_quad 61148587807 avg 49.0663 stddev 387.900 % 71.36

---

[diffstat]

 arch/powerpc/include/asm/kvm_host.h         |   49 ++++++++
 arch/powerpc/include/asm/kvm_timing_stats.h |  142 ++++++++++++++++++++++++
 arch/powerpc/include/asm/mmu-44x.h          |    1
 arch/powerpc/kernel/asm-offsets.c           |   11 +
 arch/powerpc/kvm/Kconfig                    |    9 +
 arch/powerpc/kvm/booke.c                    |   35 +++---
 arch/powerpc/kvm/booke.h                    |    7 +
 arch/powerpc/kvm/booke_interrupts.S         |   24 ++++
 arch/powerpc/kvm/powerpc.c                  |  163 +++++++++++++++++++++++++++-
 9 files changed, 425 insertions(+), 16 deletions(-)

[diff]

[...]

Signature · 3 lines
Grüsse / regards, 
Christian Ehrhardt
IBM Linux Technology Center, Open Virtualization
#2 lore raw
In reply to Ehrhardt Christian
Quoted 9 lines · On Tuesday 04 November 2008 06:33:39 Ehrhardt Christian wrote:

From: Christian Ehrhardt <[email protected]>

Other existing kvm stats are either just counters (kvm_stat) reported for kvm generally or trace based aproaches like kvm_trace.
For kvm on powerpc we had the need to track the timings of the different exit types. While this could be achieved parsing data created with a kvm_trace extension this adds too muhc overhead (at least on embedded powerpc) slowing down the workloads we wanted to measure.

Quoted 4 lines

Therefore this patch adds a in kernel exit timing statistic to the powerpc kvm code. These statistic is available per vm&vcpu under the kvm debugfs directory. As this statistic is low, but still some overhead it can be enabled via a .config entry and should be off by default.

It's not just that kvm_trace is "slow" -- I think the important point is that this code is *not* implementing another trace mechanism. It's simply a set of counters. The reason it doesn't fit naturally into kvm_stat is that kvm_stat is designed just to record event frequency, so it aggregates the counters from all vcpus. Right?

Quoted 3 lines

Since this patch touched all powerpc kvm_stat code anyway this code is now merged and simpliefied together with the exit timing statistic code (still working with exit timing disabled in .config).

In general this looks pretty good. I still need to go through it in more detail, but just a couple superficial comments right now:

arch/powerpc/include/asm/mmu-44x.h line 62

Quoted 11 lines
arch/powerpc/include/asm/mmu-44x.h +1 -0
@@ -56,6 +56,7 @@
 #ifndef __ASSEMBLY__
 
 extern unsigned int tlb_44x_hwater;
+extern unsigned int tlb_44x_index;
 
 typedef struct {
 	unsigned long id;

This must have accidentally slipped in to your patch.

arch/powerpc/include/asm/mmu-44x.h line 267

Quoted 11 lines
arch/powerpc/include/asm/mmu-44x.h +4 -0
@@ -108,6 +258,10 @@
 	kvm = kzalloc(sizeof(struct kvm), GFP_KERNEL);
 	if (!kvm)
 		return ERR_PTR(-ENOMEM);
+
+#ifdef CONFIG_KVM_BOOKE_EXIT_TIMING
+	kvm->arch.vm_id = atomic_inc_return(&vm_count);
+#endif
 
 	return kvm;
 }

This "vm_count" stuff caught my eye as looking strange. Is there no better "ID" value you can use? What about qemu's PID?

Signature · 2 lines
Hollis Blanchard
IBM Linux Technology Center