KVM: perf: kvm events analysis tool

Changlong:

Thanks to David's review, there are some changes:
- add kvm-events compile-depend files to tools/perf/MANIFEST

- fix some typos and little clean up

- rebase it on -tip tree

The output example is following:

#./perf kvm-events report --event mmio --vcpu 3

Analyze events for VCPU 3:

         MMIO Access    Samples  Samples%     Time%         Avg time

        0xfee00380:W      29688    61.16%    64.52%      3.37us ( +-   0.86% )
        0xfee00300:W       6285    12.95%    20.06%      4.95us ( +-   2.34% )
        0xfee00300:R       6285    12.95%     8.08%      1.99us ( +-   0.59% )
        0xfee00310:W       6285    12.95%     7.34%      1.81us ( +-   6.76% )

Total Samples:48543, Total events handled time:155156.31us.

They will be needed by 'perf kvm-events'

---
 arch/x86/include/asm/kvm_host.h |   36 ++++---
 arch/x86/include/asm/svm.h      |  205 +++++++++++++++++++++++++--------------
 arch/x86/include/asm/vmx.h      |  125 ++++++++++++++++--------
 arch/x86/kvm/trace.h            |   89 -----------------
 4 files changed, 233 insertions(+), 222 deletions(-)

index 74c9edf..65b005f 100644
@@ -11,6 +11,24 @@
 #ifndef _ASM_X86_KVM_HOST_H
 #define _ASM_X86_KVM_HOST_H
 
+#define DE_VECTOR 0
+#define DB_VECTOR 1
+#define BP_VECTOR 3
+#define OF_VECTOR 4
+#define BR_VECTOR 5
+#define UD_VECTOR 6
+#define NM_VECTOR 7
+#define DF_VECTOR 8
+#define TS_VECTOR 10
+#define NP_VECTOR 11
+#define SS_VECTOR 12
+#define GP_VECTOR 13
+#define PF_VECTOR 14
+#define MF_VECTOR 16
+#define MC_VECTOR 18
+
+#ifdef __KERNEL__
+
 #include <linux/types.h>
 #include <linux/mm.h>
 #include <linux/mmu_notifier.h>

@@ -73,22 +91,6 @@
 #define KVM_HPAGE_MASK(x)	(~(KVM_HPAGE_SIZE(x) - 1))
 #define KVM_PAGES_PER_HPAGE(x)	(KVM_HPAGE_SIZE(x) / PAGE_SIZE)
 
-#define DE_VECTOR 0
-#define DB_VECTOR 1
-#define BP_VECTOR 3
-#define OF_VECTOR 4
-#define BR_VECTOR 5
-#define UD_VECTOR 6
-#define NM_VECTOR 7
-#define DF_VECTOR 8
-#define TS_VECTOR 10
-#define NP_VECTOR 11
-#define SS_VECTOR 12
-#define GP_VECTOR 13
-#define PF_VECTOR 14
-#define MF_VECTOR 16
-#define MC_VECTOR 18
-
 #define SELECTOR_TI_MASK (1 << 2)
 #define SELECTOR_RPL_MASK 0x03
 

@@ -967,4 +969,6 @@ int kvm_pmu_read_pmc(struct kvm_vcpu *vcpu, unsigned pmc, u64 *data);
 void kvm_handle_pmu_event(struct kvm_vcpu *vcpu);
 void kvm_deliver_pmi(struct kvm_vcpu *vcpu);
 
+#endif
+
 #endif /* _ASM_X86_KVM_HOST_H */

1.7.7.6

'perf kvm-events' will use kvm_exit and kvm_mmio(read...) to calculate mmio read emulated time for the old kernel, in order to trace mmio read event more exactly, we add kvm_mmio_begin to trace the time when mmio read begins

Also, add kvm_mmio_done to trace the time when mmio/pio is completed

---
 arch/x86/kvm/x86.c         |   21 ++++++++++++++-------
 include/trace/events/kvm.h |   37 +++++++++++++++++++++++++++++++++++++
 2 files changed, 51 insertions(+), 7 deletions(-)

index c9d99e5..09acecf 100644
@@ -3808,9 +3808,12 @@ mmio:
 	/*
 	 * Is this MMIO handled locally?
 	 */
+	trace_kvm_mmio_begin(vcpu->vcpu_id, write, gpa);
 	handled = ops->read_write_mmio(vcpu, gpa, bytes, val);
-	if (handled == bytes)
+	if (handled == bytes) {
+		trace_kvm_mmio_done(vcpu->vcpu_id);
 		return X86EMUL_CONTINUE;
+	}
 
 	gpa += handled;
 	bytes -= handled;

@@ -3976,6 +3979,7 @@ static int emulator_pio_in_out(struct kvm_vcpu *vcpu, int size,
 	vcpu->arch.pio.size = size;
 
 	if (!kernel_pio(vcpu, vcpu->arch.pio_data)) {
+		trace_kvm_mmio_done(vcpu->vcpu_id);
 		vcpu->arch.pio.count = 0;
 		return 1;
 	}

@@ -4586,9 +4590,7 @@ restart:
 		inject_emulated_exception(vcpu);
 		r = EMULATE_DONE;
 	} else if (vcpu->arch.pio.count) {
-		if (!vcpu->arch.pio.in)
-			vcpu->arch.pio.count = 0;
-		else
+		if (vcpu->arch.pio.in)
 			writeback = false;
 		r = EMULATE_DO_MMIO;
 	} else if (vcpu->mmio_needed) {

@@ -4619,8 +4621,6 @@ int kvm_fast_pio_out(struct kvm_vcpu *vcpu, int size, unsigned short port)
 	unsigned long val = kvm_register_read(vcpu, VCPU_REGS_RAX);
 	int ret = emulator_pio_out_emulated(&vcpu->arch.emulate_ctxt,
 					    size, port, &val, 1);
-	/* do not return to emulator after return from userspace */
-	vcpu->arch.pio.count = 0;
 	return ret;
 }
 EXPORT_SYMBOL_GPL(kvm_fast_pio_out);

@@ -5451,6 +5451,11 @@ static int complete_mmio(struct kvm_vcpu *vcpu)
 	if (!(vcpu->arch.pio.count || vcpu->mmio_needed))
 		return 1;
 
+	if (vcpu->arch.pio.count && !vcpu->arch.pio.in) {
+		vcpu->arch.pio.count = 0;
+		goto exit;
+	}
+
 	if (vcpu->mmio_needed) {
 		vcpu->mmio_needed = 0;
 		if (!vcpu->mmio_is_write)

@@ -5467,7 +5472,7 @@ static int complete_mmio(struct kvm_vcpu *vcpu)
 			return 0;
 		}
 		if (vcpu->mmio_is_write)
-			return 1;
+			goto exit;
 		vcpu->mmio_read_completed = 1;
 	}
 	vcpu->srcu_idx = srcu_read_lock(&vcpu->kvm->srcu);

@@ -5475,6 +5480,8 @@ static int complete_mmio(struct kvm_vcpu *vcpu)
 	srcu_read_unlock(&vcpu->kvm->srcu, vcpu->srcu_idx);
 	if (r != EMULATE_DONE)
 		return 0;
+exit:
+	trace_kvm_mmio_done(vcpu->vcpu_id);
 	return 1;
 }
 

index 46e3cd8..16c8a6d 100644
@@ -174,6 +174,43 @@ TRACE_EVENT(kvm_mmio,
 		  __entry->len, __entry->gpa, __entry->val)
 );
 
+TRACE_EVENT(kvm_mmio_begin,
+	TP_PROTO(unsigned int vcpu_id, bool rw, u64 gpa),
+	TP_ARGS(vcpu_id, rw, gpa),
+
+	TP_STRUCT__entry(
+		__field(unsigned int, vcpu_id)
+		__field(int, type)
+		__field(u64, gpa)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+		__entry->type = rw ? KVM_TRACE_MMIO_WRITE :
+				      KVM_TRACE_MMIO_READ;
+		__entry->gpa = gpa;
+	),
+
+	TP_printk("vcpu %u mmio %s gpa 0x%llx", __entry->vcpu_id,
+		  __print_symbolic(__entry->type, kvm_trace_symbol_mmio),
+		  __entry->gpa)
+);
+
+TRACE_EVENT(kvm_mmio_done,
+	TP_PROTO(unsigned int vcpu_id),
+	TP_ARGS(vcpu_id),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	vcpu_id		)
+	),
+
+	TP_fast_assign(
+		__entry->vcpu_id = vcpu_id;
+	),
+
+	TP_printk("vcpu %u", __entry->vcpu_id)
+);
+
 #define kvm_fpu_load_symbol	\
 	{0, "unload"},		\
 	{1, "load"}

1.7.7.6

Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly

Usage:
- trace kvm events:
perf kvm-events record, or, if other tracepoints are also interesting, we can append the events like this:
perf kvm-events record -e timer:*

- show the result:
perf kvm-events report

The output example is following:

#./perf kvm-events report --event mmio --vcpu 3

Analyze events for VCPU 3:

         MMIO Access    Samples  Samples%     Time%         Avg time

        0xfee00380:W      29688    61.16%    64.52%      3.37us ( +-   0.86% )
        0xfee00300:W       6285    12.95%    20.06%      4.95us ( +-   2.34% )
        0xfee00300:R       6285    12.95%     8.08%      1.99us ( +-   0.59% )
        0xfee00310:W       6285    12.95%     7.34%      1.81us ( +-   6.76% )

Total Samples:48543, Total events handled time:155156.31us.

---
 tools/perf/MANIFEST             |    3 +
 tools/perf/Makefile             |    1 +
 tools/perf/builtin-kvm-events.c |  855 +++++++++++++++++++++++++++++++++++++++
 tools/perf/builtin.h            |    1 +
 tools/perf/command-list.txt     |    1 +
 tools/perf/perf.c               |    1 +
 tools/perf/util/header.c        |   55 +++-
 tools/perf/util/header.h        |    1 +
 tools/perf/util/thread.h        |    2 +
 9 files changed, 919 insertions(+), 1 deletions(-)
 create mode 100644 tools/perf/builtin-kvm-events.c

index 5476bc0..e01ec73 100644
@@ -13,3 +13,6 @@ arch/*/lib/memset*.S
 include/linux/poison.h
 include/linux/magic.h
 include/linux/hw_breakpoint.h
+arch/x86/include/asm/svm.h
+arch/x86/include/asm/vmx.h
+arch/x86/include/asm/kvm_host.h

index fa04340..d8d7f67 100644
@@ -400,6 +400,7 @@ BUILTIN_OBJS += $(OUTPUT)builtin-probe.o
 BUILTIN_OBJS += $(OUTPUT)builtin-kmem.o
 BUILTIN_OBJS += $(OUTPUT)builtin-lock.o
 BUILTIN_OBJS += $(OUTPUT)builtin-kvm.o
+BUILTIN_OBJS += $(OUTPUT)builtin-kvm-events.o
 BUILTIN_OBJS += $(OUTPUT)builtin-test.o
 BUILTIN_OBJS += $(OUTPUT)builtin-inject.o
 

index b382bd5..fb19e3d 100644
@@ -33,6 +33,7 @@ extern int cmd_probe(int argc, const char **argv, const char *prefix);
 extern int cmd_kmem(int argc, const char **argv, const char *prefix);
 extern int cmd_lock(int argc, const char **argv, const char *prefix);
 extern int cmd_kvm(int argc, const char **argv, const char *prefix);
+extern int cmd_kvm_events(int argc, const char **argv, const char *prefix);
 extern int cmd_test(int argc, const char **argv, const char *prefix);
 extern int cmd_inject(int argc, const char **argv, const char *prefix);
 

index d695fe4..c5e97d8 100644
@@ -22,4 +22,5 @@ perf-probe			mainporcelain common
 perf-kmem			mainporcelain common
 perf-lock			mainporcelain common
 perf-kvm			mainporcelain common
+perf-kvm-events			mainporcelain common
 perf-test			mainporcelain common

index 2b2e225..e767431 100644
@@ -317,6 +317,7 @@ static void handle_internal_command(int argc, const char **argv)
 		{ "kmem",	cmd_kmem,	0 },
 		{ "lock",	cmd_lock,	0 },
 		{ "kvm",	cmd_kvm,	0 },
+		{ "kvm-events", cmd_kvm_events, 0 },
 		{ "test",	cmd_test,	0 },
 		{ "inject",	cmd_inject,	0 },
 	};

index e68f617..58dd315 100644
@@ -93,6 +93,7 @@ int perf_header__process_sections(struct perf_header *header, int fd,
 				  int feat, int fd, void *data));
 
 int perf_header__fprintf_info(struct perf_session *s, FILE *fp, bool full);
+char *perf_header__read_feature(struct perf_session *session, int feat);
 
 int build_id_cache__add_s(const char *sbuild_id, const char *debugdir,
 			  const char *name, bool is_kallsyms);

index 70c2c13..c48ebf3 100644
@@ -16,6 +16,8 @@ struct thread {
 	bool			comm_set;
 	char			*comm;
 	int			comm_len;
+
+	void			*private;
 };
 
 struct machine;

So we already have 'perf kvm':

usage: perf kvm [<options>] {top|record|report|diff|buildid-list}

which is a sub-namespace for all things KVM instrumentation goodies. [ Arguably there should be a 'perf kvm trace' as well, but I digress. ]

So, your new tool has a similar workflow to:

perf kvm record
perf kvm report

but differs from it in terms of events used and in terms of reported output.

To me it appears that your tool is basically pretty similar to 'perf stat', adapted to KVM, right?

So, could your new tool's workflow be simplified like this:

perf kvm stat ..

?

To automatically stat all vcpus in the system, the well-known -a/--all-cpus system-wide method could be used:

perf kvm stat -a ...

with stat output following immediately after it has finished.

It should also be possible to use those new events in a recording fashion - a new, rather logical command sub-space could be used for that:

perf kvm stat record ...
perf kvm stat report ...

[ This could be expanded to regular 'perf stat' as well: 'perf
stat record' and 'perf stat report' would be useful - but I suspect that's outside the scope of your patches. ]

Thanks,

Ingo

Thanks for your review, Ingo!

Actually, the stat information has already been included in the report.

I totally agree with you except i prefer 'perf kvm events' to 'perf kvm stat' :) : it records some specified kvm events and smartly analyze it. I think it matches its doing better.

Well, my problem is that *all* of the 'perf kvm' functionality deals with events :-) So the 'events' does not say much - you just add a variation to the theme without really distinguishing it.

Since 'perf stat' is not yet used and the output of your tool looks quite perf stat alike, why not use that name and standardize all these workflows?

Thanks,

Ingo

Okay, thanks for your advise, Ingo!

Is the fallowing patch good to you?

--------------------------->

Subject: [PATCH 3/3] KVM: perf: kvm events analysis tool

Add 'perf kvm stat' support to analyze kvm vmexit/mmio/ioport smartly

Usage:
- kvm stat
run a command and gather performance counter statistics

- trace kvm events:
perf kvm stat record, or, if other tracepoints are also interesting, we can append the events like this:
perf kvm stat record -e timer:*

- show the result:
perf kvm stat report

The output example is following:

# ./perf kvm stat -e kvm:* -a sleep 3

Performance counter stats for 'sleep 3':

            26,470 kvm:kvm_entry                                                [100.00%]
                 0 kvm:kvm_hypercall                                            [100.00%]
                 0 kvm:kvm_hv_hypercall                                         [100.00%]
             1,359 kvm:kvm_pio                                                  [100.00%]
             1,214 kvm:kvm_cpuid                                                [100.00%]
            13,776 kvm:kvm_apic                                                 [100.00%]

......

# ./perf kvm stat record
^C[ perf record: Woken up 9 times to write data ]
[ perf record: Captured and wrote 20.504 MB perf.data.guest (~895850 samples) ]

# ./perf kvm stat report --event mmio --vcpu 0

Analyze events for VCPU 0:

         MMIO Access    Samples  Samples%     Time%         Avg time

        0xfee00380:W       4835    72.45%    72.36%      3.02us ( +-   0.62% )
        0xfee00300:W        613     9.18%    17.42%      5.73us ( +-   3.46% )
        0xfee00300:R        613     9.18%     5.63%      1.85us ( +-   2.18% )
        0xfee00310:W        613     9.18%     4.58%      1.51us ( +-   3.26% )

Total Samples:6674, Total events handled time:20152.73us.

---
 tools/perf/Documentation/perf-kvm.txt |   30 ++-
 tools/perf/MANIFEST                   |    3 +
 tools/perf/builtin-kvm.c              |  838 ++++++++++++++++++++++++++++++++-
 tools/perf/util/header.c              |   55 +++-
 tools/perf/util/header.h              |    1 +
 tools/perf/util/thread.h              |    2 +
 6 files changed, 924 insertions(+), 5 deletions(-)

index dd84cb2..d52feef 100644
@@ -12,7 +12,7 @@ SYNOPSIS
 	[--guestkallsyms=<path> --guestmodules=<path> | --guestvmlinux=<path>]]
 	{top|record|report|diff|buildid-list}
 'perf kvm' [--host] [--guest] [--guestkallsyms=<path> --guestmodules=<path>
-	| --guestvmlinux=<path>] {top|record|report|diff|buildid-list}
+	| --guestvmlinux=<path>] {top|record|report|diff|buildid-list|stat}
 
 DESCRIPTION
 -----------

@@ -38,6 +38,18 @@ There are a couple of variants of perf kvm:
   so that other tools can be used to fetch packages with matching symbol tables
   for use by perf report.
 
+  'perf kvm stat <command>' to run a command and gather performance counter
+   statistics.
+  Especially, perf 'kvm stat record/report' generates a statistical analysis
+  of KVM events. Currently, vmexit, mmio and ioport events are supported.
+    'perf kvm stat record <command>' records kvm events and the events between
+    start and end <command>.
+    And this command produces a file which contains tracing results of kvm
+    events.
+
+    'perf kvm stat report' reports statistical data which includes events
+    handled time, samples, and so on.
+
 OPTIONS
 -------
 -i::

@@ -68,7 +80,21 @@ OPTIONS
 --guestvmlinux=<path>::
 	Guest os kernel vmlinux.
 
+STAT REPORT OPTIONS
+-------------------
+--vcpu=<value>::
+	analyze events which occures on this vcpu. (default: all vcpus)
+
+--events=<value>::
+	events to be analyzed. Possible values: vmexit, mmio, ioport.
+	(default: vmexit)
+-k::
+--key=<value>::
+	Sorting key. Possible values: sample (default, sort by samples
+	number), time (sort by average time).
+
 SEE ALSO
 --------
 linkperf:perf-top[1], linkperf:perf-record[1], linkperf:perf-report[1],
-linkperf:perf-diff[1], linkperf:perf-buildid-list[1]
+linkperf:perf-diff[1], linkperf:perf-buildid-list[1],
+linkperf:perf-stat[1]

index 5476bc0..e01ec73 100644
@@ -13,3 +13,6 @@ arch/*/lib/memset*.S
 include/linux/poison.h
 include/linux/magic.h
 include/linux/hw_breakpoint.h
+arch/x86/include/asm/svm.h
+arch/x86/include/asm/vmx.h
+arch/x86/include/asm/kvm_host.h

index e68f617..58dd315 100644
@@ -93,6 +93,7 @@ int perf_header__process_sections(struct perf_header *header, int fd,
 				  int feat, int fd, void *data));
 
 int perf_header__fprintf_info(struct perf_session *s, FILE *fp, bool full);
+char *perf_header__read_feature(struct perf_session *session, int feat);
 
 int build_id_cache__add_s(const char *sbuild_id, const char *debugdir,
 			  const char *name, bool is_kallsyms);

index 70c2c13..c48ebf3 100644
@@ -16,6 +16,8 @@ struct thread {
 	bool			comm_set;
 	char			*comm;
 	int			comm_len;
+
+	void			*private;
 };
 
 struct machine;

1.7.7.6