[PATCH 0/9] perf: kvm live mode

[PATCH 0/9] perf: kvm live mode

[David Ahern]

Hi Arnaldo:

Update to the kvm-live series. Per your comment on IRC I removed
then need to refactor or restore an tracepoint parsing code.
Hopefully this is sufficient to make into your core branch and
be ready for 3.12.

David Ahern (9):
  perf top: move CONSOLE_CLEAR to header file
  perf stats: add max and min stats
  perf session: export a few functions for event processing
  perf kvm: split out tracepoints from record args
  perf kvm: add live mode - v3
  perf kvm: add min and max stats to display
  perf kvm: option to print events that exceed a threshold
  perf kvm: debug for missing vmexit/vmentry event
  perf kvm stat report: Add option to analyze specific VM

 tools/perf/builtin-kvm.c  |  755 ++++++++++++++++++++++++++++++++++++++++++---
 tools/perf/builtin-top.c  |    2 -
 tools/perf/perf.h         |    3 +
 tools/perf/util/session.c |   12 +-
 tools/perf/util/session.h |    7 +
 tools/perf/util/stat.c    |    6 +
 tools/perf/util/stat.h    |    9 +
 tools/perf/util/top.h     |    2 +
 8 files changed, 749 insertions(+), 47 deletions(-)

-- 
1.7.10.1

[PATCH 1/9] perf top: move CONSOLE_CLEAR to header file

[David Ahern]

For use with kvm-live mode.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/builtin-top.c |    2 --
 tools/perf/util/top.h    |    2 ++
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-top.c b/tools/perf/builtin-top.c
index bbf4635..9101f7c 100644
--- a/tools/perf/builtin-top.c
+++ b/tools/perf/builtin-top.c
@@ -238,8 +238,6 @@ out_unlock:
 	pthread_mutex_unlock(&notes->lock);
 }
 
-static const char		CONSOLE_CLEAR[] = "^[[H^[[2J";
-
 static struct hist_entry *perf_evsel__add_hist_entry(struct perf_evsel *evsel,
 						     struct addr_location *al,
 						     struct perf_sample *sample)
diff --git a/tools/perf/util/top.h b/tools/perf/util/top.h
index df46be9..b554ffc 100644
--- a/tools/perf/util/top.h
+++ b/tools/perf/util/top.h
@@ -39,6 +39,8 @@ struct perf_top {
 	float		   min_percent;
 };
 
+#define CONSOLE_CLEAR "^[[H^[[2J"
+
 size_t perf_top__header_snprintf(struct perf_top *top, char *bf, size_t size);
 void perf_top__reset_sample_counters(struct perf_top *top);
 #endif /* __PERF_TOP_H */
-- 
1.7.10.1

[PATCH 2/9] perf stats: add max and min stats

[David Ahern]

Need an initialization function to set min to -1 to
differentiate from an actual min of 0.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/util/stat.c |    6 ++++++
 tools/perf/util/stat.h |    9 +++++++++
 2 files changed, 15 insertions(+)

diff --git a/tools/perf/util/stat.c b/tools/perf/util/stat.c
index 7c59c28..6506b3d 100644
--- a/tools/perf/util/stat.c
+++ b/tools/perf/util/stat.c
@@ -10,6 +10,12 @@ void update_stats(struct stats *stats, u64 val)
 	delta = val - stats->mean;
 	stats->mean += delta / stats->n;
 	stats->M2 += delta*(val - stats->mean);
+
+	if (val > stats->max)
+		stats->max = val;
+
+	if (val < stats->min)
+		stats->min = val;
 }
 
 double avg_stats(struct stats *stats)
diff --git a/tools/perf/util/stat.h b/tools/perf/util/stat.h
index 588367c..ae8ccd7 100644
--- a/tools/perf/util/stat.h
+++ b/tools/perf/util/stat.h
@@ -6,6 +6,7 @@
 struct stats
 {
 	double n, mean, M2;
+	u64 max, min;
 };
 
 void update_stats(struct stats *stats, u64 val);
@@ -13,4 +14,12 @@ double avg_stats(struct stats *stats);
 double stddev_stats(struct stats *stats);
 double rel_stddev_stats(double stddev, double avg);
 
+static inline void init_stats(struct stats *stats)
+{
+	stats->n    = 0.0;
+	stats->mean = 0.0;
+	stats->M2   = 0.0;
+	stats->min  = (u64) -1;
+	stats->max  = 0;
+}
 #endif
-- 
1.7.10.1

[PATCH 3/9] perf session: export a few functions for event processing

[David Ahern]

Allows kvm live mode to reuse the event processing and ordered samples
processing used by the perf-report path.

v2: removed flush_sample_queue as noticed by Jiri

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/util/session.c |   12 ++++++------
 tools/perf/util/session.h |    7 +++++++
 2 files changed, 13 insertions(+), 6 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index a0ce5a4..b5ebd47 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -250,7 +250,7 @@ static int process_finished_round(struct perf_tool *tool,
 				  union perf_event *event,
 				  struct perf_session *session);
 
-static void perf_tool__fill_defaults(struct perf_tool *tool)
+void perf_tool__fill_defaults(struct perf_tool *tool)
 {
 	if (tool->sample == NULL)
 		tool->sample = process_event_sample_stub;
@@ -495,7 +495,7 @@ static int perf_session_deliver_event(struct perf_session *session,
 				      u64 file_offset);
 
 static int flush_sample_queue(struct perf_session *s,
-			       struct perf_tool *tool)
+		       struct perf_tool *tool)
 {
 	struct ordered_samples *os = &s->ordered_samples;
 	struct list_head *head = &os->samples;
@@ -1049,10 +1049,10 @@ static void event_swap(union perf_event *event, bool sample_id_all)
 		swap(event, sample_id_all);
 }
 
-static int perf_session__process_event(struct perf_session *session,
-				       union perf_event *event,
-				       struct perf_tool *tool,
-				       u64 file_offset)
+int perf_session__process_event(struct perf_session *session,
+				union perf_event *event,
+				struct perf_tool *tool,
+				u64 file_offset)
 {
 	struct perf_sample sample;
 	int ret;
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index ad8d3d4..9818fc2 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -56,6 +56,13 @@ int __perf_session__process_events(struct perf_session *self,
 int perf_session__process_events(struct perf_session *self,
 				 struct perf_tool *tool);
 
+int perf_session__process_event(struct perf_session *session,
+				union perf_event *event,
+				struct perf_tool *tool,
+				u64 file_offset);
+
+void perf_tool__fill_defaults(struct perf_tool *tool);
+
 int perf_session__resolve_callchain(struct perf_session *self, struct perf_evsel *evsel,
 				    struct thread *thread,
 				    struct ip_callchain *chain,
-- 
1.7.10.1

[PATCH 4/9] perf kvm: split out tracepoints from record args

[David Ahern]

Needed by kvm live command. Make record_args a local while we are
messing with the args.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/builtin-kvm.c |   30 +++++++++++++++++++-----------
 1 file changed, 19 insertions(+), 11 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 24b78ae..7d14a3a 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -801,16 +801,11 @@ exit:
 	return ret;
 }
 
-static const char * const record_args[] = {
-	"record",
-	"-R",
-	"-f",
-	"-m", "1024",
-	"-c", "1",
-	"-e", "kvm:kvm_entry",
-	"-e", "kvm:kvm_exit",
-	"-e", "kvm:kvm_mmio",
-	"-e", "kvm:kvm_pio",
+static const char * const kvm_events_tp[] = {
+	"kvm:kvm_entry",
+	"kvm:kvm_exit",
+	"kvm:kvm_mmio",
+	"kvm:kvm_pio",
 };
 
 #define STRDUP_FAIL_EXIT(s)		\
@@ -826,8 +821,16 @@ kvm_events_record(struct perf_kvm_stat *kvm, int argc, const char **argv)
 {
 	unsigned int rec_argc, i, j;
 	const char **rec_argv;
+	const char * const record_args[] = {
+		"record",
+		"-R",
+		"-f",
+		"-m", "1024",
+		"-c", "1",
+	};
 
-	rec_argc = ARRAY_SIZE(record_args) + argc + 2;
+	rec_argc = ARRAY_SIZE(record_args) + argc + 2 +
+		   2 * ARRAY_SIZE(kvm_events_tp);
 	rec_argv = calloc(rec_argc + 1, sizeof(char *));
 
 	if (rec_argv == NULL)
@@ -836,6 +839,11 @@ kvm_events_record(struct perf_kvm_stat *kvm, int argc, const char **argv)
 	for (i = 0; i < ARRAY_SIZE(record_args); i++)
 		rec_argv[i] = STRDUP_FAIL_EXIT(record_args[i]);
 
+	for (j = 0; j < ARRAY_SIZE(kvm_events_tp); j++) {
+		rec_argv[i++] = "-e";
+		rec_argv[i++] = STRDUP_FAIL_EXIT(kvm_events_tp[j]);
+	}
+
 	rec_argv[i++] = STRDUP_FAIL_EXIT("-o");
 	rec_argv[i++] = STRDUP_FAIL_EXIT(kvm->file_name);
 
-- 
1.7.10.1

[PATCH 5/9] perf kvm: add live mode - v3

[David Ahern]

perf kvm stat currently requires back to back record and report commands
to see stats. e.g,.

  perf kvm stat record -p $pid -- sleep 1
  perf kvm stat report

This is inconvenvient for on box monitoring of a VM. This patch introduces
a 'live' mode that in effect combines the record plus report into one
command. e.g., to monitor a single VM:

  perf kvm stat live -p $pid

or all VMs:

  perf kvm stat live

Same stats options for the record+report path work with the live mode.
Display rate defaults to 1 second and can be changed using the -d option.

v3:
updated to use existing tracepoint parsing code

v2:
removed ABSTIME arg from timerfd_settime as mentioned by Namhyung
only call perf_kvm__handle_stdin when poll returns activity.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/builtin-kvm.c |  644 ++++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 618 insertions(+), 26 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 7d14a3a..12f7593 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -2,6 +2,7 @@
 #include "perf.h"
 
 #include "util/evsel.h"
+#include "util/evlist.h"
 #include "util/util.h"
 #include "util/cache.h"
 #include "util/symbol.h"
@@ -15,9 +16,12 @@
 #include <lk/debugfs.h>
 #include "util/tool.h"
 #include "util/stat.h"
+#include "util/top.h"
 
 #include <sys/prctl.h>
+#include <sys/timerfd.h>
 
+#include <termios.h>
 #include <semaphore.h>
 #include <pthread.h>
 #include <math.h>
@@ -82,6 +86,8 @@ struct exit_reasons_table {
 
 struct perf_kvm_stat {
 	struct perf_tool    tool;
+	struct perf_record_opts opts;
+	struct perf_evlist  *evlist;
 	struct perf_session *session;
 
 	const char *file_name;
@@ -96,10 +102,16 @@ struct perf_kvm_stat {
 	struct kvm_events_ops *events_ops;
 	key_cmp_fun compare;
 	struct list_head kvm_events_cache[EVENTS_CACHE_SIZE];
+
 	u64 total_time;
 	u64 total_count;
+	u64 lost_events;
 
 	struct rb_root result;
+
+	int timerfd;
+	unsigned int display_time;
+	bool live;
 };
 
 
@@ -320,6 +332,23 @@ static void init_kvm_event_record(struct perf_kvm_stat *kvm)
 		INIT_LIST_HEAD(&kvm->kvm_events_cache[i]);
 }
 
+static void clear_events_cache_stats(struct list_head *kvm_events_cache)
+{
+	struct list_head *head;
+	struct kvm_event *event;
+	unsigned int i;
+
+	for (i = 0; i < EVENTS_CACHE_SIZE; i++) {
+		head = &kvm_events_cache[i];
+		list_for_each_entry(event, head, hash_entry) {
+			/* reset stats for event */
+			memset(&event->total, 0, sizeof(event->total));
+			memset(event->vcpu, 0,
+			       event->max_vcpu * sizeof(*event->vcpu));
+		}
+	}
+}
+
 static int kvm_events_hash_fn(u64 key)
 {
 	return key & (EVENTS_CACHE_SIZE - 1);
@@ -472,7 +501,11 @@ static bool handle_end_event(struct perf_kvm_stat *kvm,
 	vcpu_record->last_event = NULL;
 	vcpu_record->start_time = 0;
 
-	BUG_ON(timestamp < time_begin);
+	/* seems to happen once in a while during live mode */
+	if (timestamp < time_begin) {
+		pr_debug("End time before begin time; skipping event.\n");
+		return true;
+	}
 
 	time_diff = timestamp - time_begin;
 	return update_kvm_event(event, vcpu, time_diff);
@@ -639,24 +672,60 @@ static struct kvm_event *pop_from_result(struct rb_root *result)
 	return container_of(node, struct kvm_event, rb);
 }
 
-static void print_vcpu_info(int vcpu)
+static void print_vcpu_info(struct perf_kvm_stat *kvm)
 {
+	int vcpu = kvm->trace_vcpu;
+
 	pr_info("Analyze events for ");
 
+	if (kvm->live) {
+		if (kvm->opts.target.system_wide)
+			pr_info("all VMs, ");
+		else if (kvm->opts.target.pid)
+			pr_info("pid(s) %s, ", kvm->opts.target.pid);
+		else if (kvm->opts.target.tid)
+			pr_info("tid(s) %s, ", kvm->opts.target.tid);
+		else if (kvm->opts.target.cpu_list)
+			pr_info("host cpu(s) %s, ", kvm->opts.target.cpu_list);
+		else
+			pr_info("dazed and confused on what is monitored, ");
+	}
+
 	if (vcpu == -1)
 		pr_info("all VCPUs:\n\n");
 	else
 		pr_info("VCPU %d:\n\n", vcpu);
 }
 
+static void show_timeofday(void)
+{
+	char date[64];
+	struct timeval tv;
+	struct tm ltime;
+
+	gettimeofday(&tv, NULL);
+	if (localtime_r(&tv.tv_sec, &ltime)) {
+		strftime(date, sizeof(date), "%H:%M:%S", &ltime);
+		pr_info("%s.%06ld", date, tv.tv_usec);
+	} else
+		pr_info("00:00:00.000000");
+
+	return;
+}
+
 static void print_result(struct perf_kvm_stat *kvm)
 {
 	char decode[20];
 	struct kvm_event *event;
 	int vcpu = kvm->trace_vcpu;
 
+	if (kvm->live) {
+		puts(CONSOLE_CLEAR);
+		show_timeofday();
+	}
+
 	pr_info("\n\n");
-	print_vcpu_info(vcpu);
+	print_vcpu_info(kvm);
 	pr_info("%20s ", kvm->events_ops->name);
 	pr_info("%10s ", "Samples");
 	pr_info("%9s ", "Samples%");
@@ -683,6 +752,20 @@ static void print_result(struct perf_kvm_stat *kvm)
 
 	pr_info("\nTotal Samples:%" PRIu64 ", Total events handled time:%.2fus.\n\n",
 		kvm->total_count, kvm->total_time / 1e3);
+
+	if (kvm->lost_events)
+		pr_info("\nLost events: %" PRIu64 "\n\n", kvm->lost_events);
+}
+
+static int process_lost_event(struct perf_tool *tool,
+			      union perf_event *event __maybe_unused,
+			      struct perf_sample *sample __maybe_unused,
+			      struct machine *machine __maybe_unused)
+{
+	struct perf_kvm_stat *kvm = container_of(tool, struct perf_kvm_stat, tool);
+
+	kvm->lost_events++;
+	return 0;
 }
 
 static int process_sample_event(struct perf_tool *tool,
@@ -707,10 +790,20 @@ static int process_sample_event(struct perf_tool *tool,
 	return 0;
 }
 
-static int get_cpu_isa(struct perf_session *session)
+static int cpu_isa_config(struct perf_kvm_stat *kvm)
 {
-	char *cpuid = session->header.env.cpuid;
-	int isa;
+	char buf[64], *cpuid;
+	int err, isa;
+
+	if (kvm->live) {
+		err = get_cpuid(buf, sizeof(buf));
+		if (err != 0) {
+			pr_err("Failed to look up CPU type (Intel or AMD)\n");
+			return err;
+		}
+		cpuid = buf;
+	} else
+		cpuid = kvm->session->header.env.cpuid;
 
 	if (strstr(cpuid, "Intel"))
 		isa = 1;
@@ -718,10 +811,338 @@ static int get_cpu_isa(struct perf_session *session)
 		isa = 0;
 	else {
 		pr_err("CPU %s is not supported.\n", cpuid);
-		isa = -ENOTSUP;
+		return -ENOTSUP;
 	}
 
-	return isa;
+	if (isa == 1) {
+		kvm->exit_reasons = vmx_exit_reasons;
+		kvm->exit_reasons_size = ARRAY_SIZE(vmx_exit_reasons);
+		kvm->exit_reasons_isa = "VMX";
+	}
+
+	return 0;
+}
+
+static bool verify_vcpu(int vcpu)
+{
+	int nr_cpus;
+
+	if (vcpu != -1 && vcpu < 0) {
+		pr_err("Invalid vcpu:%d.\n", vcpu);
+		return false;
+	}
+
+	nr_cpus = sysconf(_SC_NPROCESSORS_ONLN);
+	if ((nr_cpus > 0) && (vcpu > nr_cpus - 1)) {
+		pr_err("Invalid vcpu:%d.\n", vcpu);
+		return false;
+	}
+
+	return true;
+}
+
+#define PERF_KVM__MAX_EVENTS_PER_MMAP  1000
+
+static s64 perf_kvm__mmap_read_idx(struct perf_kvm_stat *kvm, int idx)
+{
+	union perf_event *event;
+	s64 n = 0;
+	int err;
+
+	while ((event = perf_evlist__mmap_read(kvm->evlist, idx)) != NULL) {
+		err = perf_session__process_event(kvm->session, event,
+						  &kvm->tool, 0);
+		if (err) {
+			pr_err("Failed to process event\n");
+			return err;
+		}
+		n++;
+
+		/* limit events per mmap handled all at once */
+		if (n == PERF_KVM__MAX_EVENTS_PER_MMAP)
+			break;
+	}
+
+	return n;
+}
+
+static int perf_kvm__mmap_read(struct perf_kvm_stat *kvm)
+{
+	int i, err, throttled = 0;
+	s64 n, ntotal = 0;
+
+	for (i = 0; i < kvm->evlist->nr_mmaps; i++) {
+		n = perf_kvm__mmap_read_idx(kvm, i);
+		if (n < 0)
+			return -1;
+		ntotal += n;
+		if (n == PERF_KVM__MAX_EVENTS_PER_MMAP)
+			throttled = 1;
+	}
+
+	/* flush queue after each round in which we processed events */
+	if (ntotal) {
+		err = kvm->tool.finished_round(&kvm->tool, NULL, kvm->session);
+		if (err) {
+			if (kvm->lost_events)
+				pr_info("\nLost events: %" PRIu64 "\n\n",
+					kvm->lost_events);
+			return err;
+		}
+	}
+
+	return throttled;
+}
+
+static volatile int done;
+
+static void sig_handler(int sig __maybe_unused)
+{
+	done = 1;
+}
+
+static int perf_kvm__timerfd_create(struct perf_kvm_stat *kvm)
+{
+	struct itimerspec new_value;
+	int rc = -1;
+
+	kvm->timerfd = timerfd_create(CLOCK_MONOTONIC, TFD_NONBLOCK);
+	if (kvm->timerfd < 0) {
+		pr_err("timerfd_create failed\n");
+		goto out;
+	}
+
+	new_value.it_value.tv_sec = kvm->display_time;
+	new_value.it_value.tv_nsec = 0;
+	new_value.it_interval.tv_sec = kvm->display_time;
+	new_value.it_interval.tv_nsec = 0;
+
+	if (timerfd_settime(kvm->timerfd, 0, &new_value, NULL) != 0) {
+		pr_err("timerfd_settime failed: %d\n", errno);
+		close(kvm->timerfd);
+		goto out;
+	}
+
+	rc = 0;
+out:
+	return rc;
+}
+
+static int perf_kvm__handle_timerfd(struct perf_kvm_stat *kvm)
+{
+	uint64_t c;
+	int rc;
+
+	rc = read(kvm->timerfd, &c, sizeof(uint64_t));
+	if (rc < 0) {
+		if (errno == EAGAIN)
+			return 0;
+
+		pr_err("Failed to read timer fd: %d\n", errno);
+		return -1;
+	}
+
+	if (rc != sizeof(uint64_t)) {
+		pr_err("Error reading timer fd - invalid size returned\n");
+		return -1;
+	}
+
+	if (c != 1)
+		pr_debug("Missed timer beats: %" PRIu64 "\n", c-1);
+
+	/* update display */
+	sort_result(kvm);
+	print_result(kvm);
+
+	/* reset counts */
+	clear_events_cache_stats(kvm->kvm_events_cache);
+	kvm->total_count = 0;
+	kvm->total_time = 0;
+	kvm->lost_events = 0;
+
+	return 0;
+}
+
+static int fd_set_nonblock(int fd)
+{
+	long arg = 0;
+
+	arg = fcntl(fd, F_GETFL);
+	if (arg < 0) {
+		pr_err("Failed to get current flags for fd %d\n", fd);
+		return -1;
+	}
+
+	if (fcntl(fd, F_SETFL, arg | O_NONBLOCK) < 0) {
+		pr_err("Failed to set non-block option on fd %d\n", fd);
+		return -1;
+	}
+
+	return 0;
+}
+
+static
+int perf_kvm__handle_stdin(struct termios *tc_now, struct termios *tc_save)
+{
+	int c;
+
+	tcsetattr(0, TCSANOW, tc_now);
+	c = getc(stdin);
+	tcsetattr(0, TCSAFLUSH, tc_save);
+
+	if (c == 'q')
+		return 1;
+
+	return 0;
+}
+
+static int kvm_events_live_report(struct perf_kvm_stat *kvm)
+{
+	struct pollfd *pollfds = NULL;
+	int nr_fds, nr_stdin, ret, err = -EINVAL;
+	struct termios tc, save;
+
+	/* live flag must be set first */
+	kvm->live = true;
+
+	ret = cpu_isa_config(kvm);
+	if (ret < 0)
+		return ret;
+
+	if (!verify_vcpu(kvm->trace_vcpu) ||
+	    !select_key(kvm) ||
+	    !register_kvm_events_ops(kvm)) {
+		goto out;
+	}
+
+	init_kvm_event_record(kvm);
+
+	tcgetattr(0, &save);
+	tc = save;
+	tc.c_lflag &= ~(ICANON | ECHO);
+	tc.c_cc[VMIN] = 0;
+	tc.c_cc[VTIME] = 0;
+
+	signal(SIGINT, sig_handler);
+	signal(SIGTERM, sig_handler);
+
+	/* copy pollfds -- need to add timerfd and stdin */
+	nr_fds = kvm->evlist->nr_fds;
+	pollfds = zalloc(sizeof(struct pollfd) * (nr_fds + 2));
+	if (!pollfds) {
+		err = -ENOMEM;
+		goto out;
+	}
+	memcpy(pollfds, kvm->evlist->pollfd,
+		sizeof(struct pollfd) * kvm->evlist->nr_fds);
+
+	/* add timer fd */
+	if (perf_kvm__timerfd_create(kvm) < 0) {
+		err = -1;
+		goto out;
+	}
+
+	pollfds[nr_fds].fd = kvm->timerfd;
+	pollfds[nr_fds].events = POLLIN;
+	nr_fds++;
+
+	pollfds[nr_fds].fd = fileno(stdin);
+	pollfds[nr_fds].events = POLLIN;
+	nr_stdin = nr_fds;
+	nr_fds++;
+	if (fd_set_nonblock(fileno(stdin)) != 0)
+		goto out;
+
+	/* everything is good - enable the events and process */
+	perf_evlist__enable(kvm->evlist);
+
+	while (!done) {
+		int rc;
+
+		rc = perf_kvm__mmap_read(kvm);
+		if (rc < 0)
+			break;
+
+		err = perf_kvm__handle_timerfd(kvm);
+		if (err)
+			goto out;
+
+		if (pollfds[nr_stdin].revents & POLLIN)
+			done = perf_kvm__handle_stdin(&tc, &save);
+
+		if (!rc && !done)
+			err = poll(pollfds, nr_fds, 100);
+	}
+
+	perf_evlist__disable(kvm->evlist);
+
+	if (err == 0) {
+		sort_result(kvm);
+		print_result(kvm);
+	}
+
+out:
+	if (kvm->timerfd >= 0)
+		close(kvm->timerfd);
+
+	if (pollfds)
+		free(pollfds);
+
+	return err;
+}
+
+static int kvm_live_open_events(struct perf_kvm_stat *kvm)
+{
+	int err, rc = -1;
+	struct perf_evsel *pos;
+	struct perf_evlist *evlist = kvm->evlist;
+
+	perf_evlist__config(evlist, &kvm->opts);
+
+	/*
+	 * Note: exclude_{guest,host} do not apply here.
+	 *       This command processes KVM tracepoints from host only
+	 */
+	list_for_each_entry(pos, &evlist->entries, node) {
+		struct perf_event_attr *attr = &pos->attr;
+
+		/* make sure these *are* set */
+		attr->sample_type |= PERF_SAMPLE_TID;
+		attr->sample_type |= PERF_SAMPLE_TIME;
+		attr->sample_type |= PERF_SAMPLE_CPU;
+		attr->sample_type |= PERF_SAMPLE_RAW;
+		/* make sure these are *not*; want as small a sample as possible */
+		attr->sample_type &= ~PERF_SAMPLE_PERIOD;
+		attr->sample_type &= ~PERF_SAMPLE_IP;
+		attr->sample_type &= ~PERF_SAMPLE_CALLCHAIN;
+		attr->sample_type &= ~PERF_SAMPLE_ADDR;
+		attr->sample_type &= ~PERF_SAMPLE_READ;
+
+		attr->sample_period = 1;
+
+		attr->watermark = 0;
+		attr->wakeup_events = 1000;
+
+		/* will enable all once we are ready */
+		attr->disabled = 1;
+	}
+
+	err = perf_evlist__open(evlist);
+	if (err < 0) {
+		printf("Couldn't create the events: %s\n", strerror(errno));
+		goto out;
+	}
+
+	if (perf_evlist__mmap(evlist, kvm->opts.mmap_pages, false) < 0) {
+		ui__error("Failed to mmap the events: %s\n", strerror(errno));
+		perf_evlist__close(evlist);
+		goto out;
+	}
+
+	rc = 0;
+
+out:
+	return rc;
 }
 
 static int read_events(struct perf_kvm_stat *kvm)
@@ -749,30 +1170,13 @@ static int read_events(struct perf_kvm_stat *kvm)
 	 * Do not use 'isa' recorded in kvm_exit tracepoint since it is not
 	 * traced in the old kernel.
 	 */
-	ret = get_cpu_isa(kvm->session);
-
+	ret = cpu_isa_config(kvm);
 	if (ret < 0)
 		return ret;
 
-	if (ret == 1) {
-		kvm->exit_reasons = vmx_exit_reasons;
-		kvm->exit_reasons_size = ARRAY_SIZE(vmx_exit_reasons);
-		kvm->exit_reasons_isa = "VMX";
-	}
-
 	return perf_session__process_events(kvm->session, &kvm->tool);
 }
 
-static bool verify_vcpu(int vcpu)
-{
-	if (vcpu != -1 && vcpu < 0) {
-		pr_err("Invalid vcpu:%d.\n", vcpu);
-		return false;
-	}
-
-	return true;
-}
-
 static int kvm_events_report_vcpu(struct perf_kvm_stat *kvm)
 {
 	int ret = -EINVAL;
@@ -886,6 +1290,190 @@ kvm_events_report(struct perf_kvm_stat *kvm, int argc, const char **argv)
 	return kvm_events_report_vcpu(kvm);
 }
 
+static struct perf_evlist *kvm_live_event_list(void)
+{
+	struct perf_evlist *evlist;
+	char *tp, *name, *sys;
+	unsigned int j;
+	int err = -1;
+
+	evlist = perf_evlist__new();
+	if (evlist == NULL)
+		return NULL;
+
+	for (j = 0; j < ARRAY_SIZE(kvm_events_tp); j++) {
+
+		tp = strdup(kvm_events_tp[j]);
+		if (tp == NULL)
+			goto out;
+
+		/* split tracepoint into subsystem and name */
+		sys = tp;
+		name = strchr(tp, ':');
+		if (name == NULL) {
+			pr_err("Error parsing %s tracepoint: subsystem delimiter not found\n",
+				kvm_events_tp[j]);
+			free(tp);
+			goto out;
+		}
+		*name = '\0';
+		name++;
+
+		if (perf_evlist__add_newtp(evlist, sys, name, NULL)) {
+			pr_err("Failed to add %s tracepoint to the list\n", kvm_events_tp[j]);
+			free(tp);
+			goto out;
+		}
+
+		free(tp);
+	}
+
+	err = 0;
+
+out:
+	if (err) {
+		perf_evlist__delete(evlist);
+		evlist = NULL;
+	}
+
+	return evlist;
+}
+
+static int kvm_events_live(struct perf_kvm_stat *kvm,
+			   int argc, const char **argv)
+{
+	char errbuf[BUFSIZ];
+	int err;
+
+	const struct option live_options[] = {
+		OPT_STRING('p', "pid", &kvm->opts.target.pid, "pid",
+			"record events on existing process id"),
+		OPT_STRING('t', "tid", &kvm->opts.target.tid, "tid",
+			"record events on existing thread id"),
+		OPT_STRING('C', "cpu", &kvm->opts.target.cpu_list, "cpu",
+			"list of host cpus to monitor"),
+		OPT_UINTEGER('m', "mmap-pages", &kvm->opts.mmap_pages,
+			"number of mmap data pages"),
+		OPT_INCR('v', "verbose", &verbose,
+			"be more verbose (show counter open errors, etc)"),
+		OPT_BOOLEAN('a', "all-cpus", &kvm->opts.target.system_wide,
+			"system-wide collection from all CPUs"),
+		OPT_UINTEGER('d', "display", &kvm->display_time,
+			"time in seconds between display updates"),
+		OPT_STRING(0, "event", &kvm->report_event, "report event",
+			"event for reporting: vmexit, mmio, ioport"),
+		OPT_INTEGER(0, "vcpu", &kvm->trace_vcpu,
+			"vcpu id to report"),
+		OPT_STRING('k', "key", &kvm->sort_key, "sort-key",
+			"key for sorting: sample(sort by samples number)"
+			" time (sort by avg time)"),
+		OPT_END()
+	};
+	const char * const live_usage[] = {
+		"perf kvm stat live [<options>]",
+		NULL
+	};
+
+
+	/* event handling */
+	kvm->tool.sample = process_sample_event;
+	kvm->tool.comm   = perf_event__process_comm;
+	kvm->tool.exit   = perf_event__process_exit;
+	kvm->tool.fork   = perf_event__process_fork;
+	kvm->tool.lost   = process_lost_event;
+	kvm->tool.ordered_samples = true;
+	perf_tool__fill_defaults(&kvm->tool);
+
+	/* set defaults */
+	kvm->display_time = 1;
+	kvm->opts.user_interval = 1;
+	kvm->opts.mmap_pages = 512;
+	kvm->opts.target.uses_mmap = false;
+	kvm->opts.target.uid_str = NULL;
+	kvm->opts.target.uid = UINT_MAX;
+
+	symbol__init();
+	disable_buildid_cache();
+
+	use_browser = 0;
+	setup_browser(false);
+
+	if (argc) {
+		argc = parse_options(argc, argv, live_options,
+				     live_usage, 0);
+		if (argc)
+			usage_with_options(live_usage, live_options);
+	}
+
+	/*
+	 * target related setups
+	 */
+	err = perf_target__validate(&kvm->opts.target);
+	if (err) {
+		perf_target__strerror(&kvm->opts.target, err, errbuf, BUFSIZ);
+		ui__warning("%s", errbuf);
+	}
+
+	if (perf_target__none(&kvm->opts.target))
+		kvm->opts.target.system_wide = true;
+
+
+	/*
+	 * generate the event list
+	 */
+	kvm->evlist = kvm_live_event_list();
+	if (kvm->evlist == NULL) {
+		err = -1;
+		goto out;
+	}
+
+	symbol_conf.nr_events = kvm->evlist->nr_entries;
+
+	if (perf_evlist__create_maps(kvm->evlist, &kvm->opts.target) < 0)
+		usage_with_options(live_usage, live_options);
+
+	/*
+	 * perf session
+	 */
+	kvm->session = perf_session__new(NULL, O_WRONLY, false, false, &kvm->tool);
+	if (kvm->session == NULL) {
+		err = -ENOMEM;
+		goto out;
+	}
+	kvm->session->evlist = kvm->evlist;
+	perf_session__set_id_hdr_size(kvm->session);
+
+
+	if (perf_target__has_task(&kvm->opts.target))
+		perf_event__synthesize_thread_map(&kvm->tool,
+						  kvm->evlist->threads,
+						  perf_event__process,
+						  &kvm->session->machines.host);
+	else
+		perf_event__synthesize_threads(&kvm->tool, perf_event__process,
+					       &kvm->session->machines.host);
+
+
+	err = kvm_live_open_events(kvm);
+	if (err)
+		goto out;
+
+	err = kvm_events_live_report(kvm);
+
+out:
+	exit_browser(0);
+
+	if (kvm->session)
+		perf_session__delete(kvm->session);
+	kvm->session = NULL;
+	if (kvm->evlist) {
+		perf_evlist__delete_maps(kvm->evlist);
+		perf_evlist__delete(kvm->evlist);
+	}
+
+	return err;
+}
+
 static void print_kvm_stat_usage(void)
 {
 	printf("Usage: perf kvm stat <command>\n\n");
@@ -893,6 +1481,7 @@ static void print_kvm_stat_usage(void)
 	printf("# Available commands:\n");
 	printf("\trecord: record kvm events\n");
 	printf("\treport: report statistical data of kvm events\n");
+	printf("\tlive:   live reporting of statistical data of kvm events\n");
 
 	printf("\nOtherwise, it is the alias of 'perf stat':\n");
 }
@@ -922,6 +1511,9 @@ static int kvm_cmd_stat(const char *file_name, int argc, const char **argv)
 	if (!strncmp(argv[1], "rep", 3))
 		return kvm_events_report(&kvm, argc - 1 , argv + 1);
 
+	if (!strncmp(argv[1], "live", 4))
+		return kvm_events_live(&kvm, argc - 1 , argv + 1);
+
 perf_stat:
 	return cmd_stat(argc, argv, NULL);
 }
-- 
1.7.10.1

[PATCH 6/9] perf kvm: add min and max stats to display

[David Ahern]

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/builtin-kvm.c |   21 ++++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 12f7593..5c6e3cd 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -337,14 +337,19 @@ static void clear_events_cache_stats(struct list_head *kvm_events_cache)
 	struct list_head *head;
 	struct kvm_event *event;
 	unsigned int i;
+	int j;
 
 	for (i = 0; i < EVENTS_CACHE_SIZE; i++) {
 		head = &kvm_events_cache[i];
 		list_for_each_entry(event, head, hash_entry) {
 			/* reset stats for event */
-			memset(&event->total, 0, sizeof(event->total));
-			memset(event->vcpu, 0,
-			       event->max_vcpu * sizeof(*event->vcpu));
+			event->total.time = 0;
+			init_stats(&event->total.stats);
+
+			for (j = 0; j < event->max_vcpu; ++j) {
+				event->vcpu[j].time = 0;
+				init_stats(&event->vcpu[j].stats);
+			}
 		}
 	}
 }
@@ -718,6 +723,7 @@ static void print_result(struct perf_kvm_stat *kvm)
 	char decode[20];
 	struct kvm_event *event;
 	int vcpu = kvm->trace_vcpu;
+	struct kvm_event_stats *kvm_stats;
 
 	if (kvm->live) {
 		puts(CONSOLE_CLEAR);
@@ -731,6 +737,8 @@ static void print_result(struct perf_kvm_stat *kvm)
 	pr_info("%9s ", "Samples%");
 
 	pr_info("%9s ", "Time%");
+	pr_info("%10s ", "Min Time");
+	pr_info("%10s ", "Max Time");
 	pr_info("%16s ", "Avg time");
 	pr_info("\n\n");
 
@@ -740,11 +748,18 @@ static void print_result(struct perf_kvm_stat *kvm)
 		ecount = get_event_count(event, vcpu);
 		etime = get_event_time(event, vcpu);
 
+		if (vcpu == -1)
+			kvm_stats = &event->total;
+		else
+			kvm_stats = &event->vcpu[vcpu];
+
 		kvm->events_ops->decode_key(kvm, &event->key, decode);
 		pr_info("%20s ", decode);
 		pr_info("%10llu ", (unsigned long long)ecount);
 		pr_info("%8.2f%% ", (double)ecount / kvm->total_count * 100);
 		pr_info("%8.2f%% ", (double)etime / kvm->total_time * 100);
+		pr_info("%8" PRIu64 "us ", kvm_stats->stats.min / 1000);
+		pr_info("%8" PRIu64 "us ", kvm_stats->stats.max / 1000);
 		pr_info("%9.2fus ( +-%7.2f%% )", (double)etime / ecount/1e3,
 			kvm_event_rel_stddev(vcpu, event));
 		pr_info("\n");
-- 
1.7.10.1

[PATCH 7/9] perf kvm: option to print events that exceed a threshold

[David Ahern]

This is useful to spot high latency blips.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/builtin-kvm.c |   25 +++++++++++++++++++++----
 tools/perf/perf.h        |    3 +++
 2 files changed, 24 insertions(+), 4 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 5c6e3cd..28afc05d 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -106,6 +106,7 @@ struct perf_kvm_stat {
 	u64 total_time;
 	u64 total_count;
 	u64 lost_events;
+	u64 threshold;
 
 	struct rb_root result;
 
@@ -470,7 +471,7 @@ static bool update_kvm_event(struct kvm_event *event, int vcpu_id,
 static bool handle_end_event(struct perf_kvm_stat *kvm,
 			     struct vcpu_event_record *vcpu_record,
 			     struct event_key *key,
-			     u64 timestamp)
+			     struct perf_sample *sample)
 {
 	struct kvm_event *event;
 	u64 time_begin, time_diff;
@@ -507,12 +508,24 @@ static bool handle_end_event(struct perf_kvm_stat *kvm,
 	vcpu_record->start_time = 0;
 
 	/* seems to happen once in a while during live mode */
-	if (timestamp < time_begin) {
+	if (sample->time < time_begin) {
 		pr_debug("End time before begin time; skipping event.\n");
 		return true;
 	}
 
-	time_diff = timestamp - time_begin;
+	time_diff = sample->time - time_begin;
+
+	if (kvm->threshold && time_diff > kvm->threshold) {
+		char decode[32];
+
+		kvm->events_ops->decode_key(kvm, &event->key, decode);
+		if (strcmp(decode, "HLT")) {
+			pr_info("%" PRIu64 " VM %d, vcpu %d: %s event took %" PRIu64 "usec\n",
+				 sample->time, sample->pid, vcpu_record->vcpu_id,
+				 decode, time_diff/1000);
+		}
+	}
+
 	return update_kvm_event(event, vcpu, time_diff);
 }
 
@@ -559,7 +572,7 @@ static bool handle_kvm_event(struct perf_kvm_stat *kvm,
 		return handle_begin_event(kvm, vcpu_record, &key, sample->time);
 
 	if (kvm->events_ops->is_end_event(evsel, sample, &key))
-		return handle_end_event(kvm, vcpu_record, &key, sample->time);
+		return handle_end_event(kvm, vcpu_record, &key, sample);
 
 	return true;
 }
@@ -1382,6 +1395,8 @@ static int kvm_events_live(struct perf_kvm_stat *kvm,
 		OPT_STRING('k', "key", &kvm->sort_key, "sort-key",
 			"key for sorting: sample(sort by samples number)"
 			" time (sort by avg time)"),
+		OPT_U64('T', "threshold", &kvm->threshold,
+		    "show events that take longer than threshold usecs"),
 		OPT_END()
 	};
 	const char * const live_usage[] = {
@@ -1420,6 +1435,8 @@ static int kvm_events_live(struct perf_kvm_stat *kvm,
 			usage_with_options(live_usage, live_options);
 	}
 
+	kvm->threshold *= NSEC_PER_USEC;   /* convert usec to nsec */
+
 	/*
 	 * target related setups
 	 */
diff --git a/tools/perf/perf.h b/tools/perf/perf.h
index 32bd102..cf20187 100644
--- a/tools/perf/perf.h
+++ b/tools/perf/perf.h
@@ -125,6 +125,9 @@
 #ifndef NSEC_PER_SEC
 # define NSEC_PER_SEC			1000000000ULL
 #endif
+#ifndef NSEC_PER_USEC
+# define NSEC_PER_USEC			1000ULL
+#endif
 
 static inline unsigned long long rdclock(void)
 {
-- 
1.7.10.1

[PATCH 8/9] perf kvm: debug for missing vmexit/vmentry event

[David Ahern]

Expected to have missing events for each vcpu when perf is
started. After that should not have missing events.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/builtin-kvm.c |   15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 28afc05d..41dd25a 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -568,11 +568,22 @@ static bool handle_kvm_event(struct perf_kvm_stat *kvm,
 	    (kvm->trace_vcpu != vcpu_record->vcpu_id))
 		return true;
 
-	if (kvm->events_ops->is_begin_event(evsel, sample, &key))
+	if (kvm->events_ops->is_begin_event(evsel, sample, &key)) {
+		if (vcpu_record->start_time) {
+			pr_debug("consecutive begin events (%s) for pid %d, vcpu %d\n",
+				 evsel->name, sample->pid, vcpu_record->vcpu_id);
+		}
 		return handle_begin_event(kvm, vcpu_record, &key, sample->time);
+	}
+
 
-	if (kvm->events_ops->is_end_event(evsel, sample, &key))
+	if (kvm->events_ops->is_end_event(evsel, sample, &key)) {
+		if (vcpu_record->start_time == 0) {
+			pr_debug("consecutive end events (%s) for pid %d, vcpu %d\n",
+				 evsel->name, sample->pid, vcpu_record->vcpu_id);
+		}
 		return handle_end_event(kvm, vcpu_record, &key, sample);
+	}
 
 	return true;
 }
-- 
1.7.10.1

[PATCH 9/9] perf kvm stat report: Add option to analyze specific VM

[David Ahern]

Add an option to analyze a specific VM within a data file. This
allows the collection of kvm events for all VMs and then analyze
data for each VM (or set of VMs) individually.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
---
 tools/perf/builtin-kvm.c |   38 ++++++++++++++++++++++++++++++++++++--
 1 file changed, 36 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 41dd25a..54f9852 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -9,7 +9,7 @@
 #include "util/thread.h"
 #include "util/header.h"
 #include "util/session.h"
-
+#include "util/intlist.h"
 #include "util/parse-options.h"
 #include "util/trace-event.h"
 #include "util/debug.h"
@@ -108,6 +108,9 @@ struct perf_kvm_stat {
 	u64 lost_events;
 	u64 threshold;
 
+	const char *pid_str;
+	struct intlist *pid_list;
+
 	struct rb_root result;
 
 	int timerfd;
@@ -807,16 +810,29 @@ static int process_lost_event(struct perf_tool *tool,
 	return 0;
 }
 
+static bool skip_sample(struct perf_kvm_stat *kvm,
+			struct perf_sample *sample)
+{
+	if (kvm->pid_list && intlist__find(kvm->pid_list, sample->pid) == NULL)
+		return true;
+
+	return false;
+}
+
 static int process_sample_event(struct perf_tool *tool,
 				union perf_event *event,
 				struct perf_sample *sample,
 				struct perf_evsel *evsel,
 				struct machine *machine)
 {
-	struct thread *thread = machine__findnew_thread(machine, sample->tid);
+	struct thread *thread;
 	struct perf_kvm_stat *kvm = container_of(tool, struct perf_kvm_stat,
 						 tool);
 
+	if (skip_sample(kvm, sample))
+		return 0;
+
+	thread = machine__findnew_thread(machine, sample->tid);
 	if (thread == NULL) {
 		pr_debug("problem processing %d event, skipping it.\n",
 			event->header.type);
@@ -1216,11 +1232,27 @@ static int read_events(struct perf_kvm_stat *kvm)
 	return perf_session__process_events(kvm->session, &kvm->tool);
 }
 
+static int parse_target_str(struct perf_kvm_stat *kvm)
+{
+	if (kvm->pid_str) {
+		kvm->pid_list = intlist__new(kvm->pid_str);
+		if (kvm->pid_list == NULL) {
+			pr_err("Error parsing process id string\n");
+			return -EINVAL;
+		}
+	}
+
+	return 0;
+}
+
 static int kvm_events_report_vcpu(struct perf_kvm_stat *kvm)
 {
 	int ret = -EINVAL;
 	int vcpu = kvm->trace_vcpu;
 
+	if (parse_target_str(kvm) != 0)
+		goto exit;
+
 	if (!verify_vcpu(vcpu))
 		goto exit;
 
@@ -1307,6 +1339,8 @@ kvm_events_report(struct perf_kvm_stat *kvm, int argc, const char **argv)
 		OPT_STRING('k', "key", &kvm->sort_key, "sort-key",
 			    "key for sorting: sample(sort by samples number)"
 			    " time (sort by avg time)"),
+		OPT_STRING('p', "pid", &kvm->pid_str, "pid",
+			   "analyze events only for given process id(s)"),
 		OPT_END()
 	};
 
-- 
1.7.10.1

Re: [PATCH 4/9] perf kvm: split out tracepoints from record args

[Xiao Guangrong]

On 08/03/2013 04:05 AM, David Ahern wrote:
> Needed by kvm live command. Make record_args a local while we are
> messing with the args.

Reviewed-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>

Re: [PATCH 5/9] perf kvm: add live mode - v3

[Xiao Guangrong]

Hi David,

Thanks for your nice job! I got some questions.

On 08/03/2013 04:05 AM, David Ahern wrote:

>  static int kvm_events_hash_fn(u64 key)
>  {
>  	return key & (EVENTS_CACHE_SIZE - 1);
> @@ -472,7 +501,11 @@ static bool handle_end_event(struct perf_kvm_stat *kvm,
>  	vcpu_record->last_event = NULL;
>  	vcpu_record->start_time = 0;
> 
> -	BUG_ON(timestamp < time_begin);
> +	/* seems to happen once in a while during live mode */
> +	if (timestamp < time_begin) {
> +		pr_debug("End time before begin time; skipping event.\n");
> +		return true;
> +	}

No idea why it can happen. :(

> +static bool verify_vcpu(int vcpu)
> +{
> +	int nr_cpus;
> +
> +	if (vcpu != -1 && vcpu < 0) {
> +		pr_err("Invalid vcpu:%d.\n", vcpu);
> +		return false;
> +	}
> +
> +	nr_cpus = sysconf(_SC_NPROCESSORS_ONLN);
> +	if ((nr_cpus > 0) && (vcpu > nr_cpus - 1)) {
> +		pr_err("Invalid vcpu:%d.\n", vcpu);
> +		return false;
> +	}

Hmm, kvm can use more vcpus than the cpus on host.

> +static int kvm_events_live(struct perf_kvm_stat *kvm,
> +			   int argc, const char **argv)
> +{
> +	char errbuf[BUFSIZ];
> +	int err;
> +
> +	const struct option live_options[] = {
> +		OPT_STRING('p', "pid", &kvm->opts.target.pid, "pid",
> +			"record events on existing process id"),
> +		OPT_STRING('t', "tid", &kvm->opts.target.tid, "tid",
> +			"record events on existing thread id"),
> +		OPT_STRING('C', "cpu", &kvm->opts.target.cpu_list, "cpu",
> +			"list of host cpus to monitor"),
> +		OPT_UINTEGER('m', "mmap-pages", &kvm->opts.mmap_pages,
> +			"number of mmap data pages"),
> +		OPT_INCR('v', "verbose", &verbose,
> +			"be more verbose (show counter open errors, etc)"),
> +		OPT_BOOLEAN('a', "all-cpus", &kvm->opts.target.system_wide,
> +			"system-wide collection from all CPUs"),
> +		OPT_UINTEGER('d', "display", &kvm->display_time,
> +			"time in seconds between display updates"),
> +		OPT_STRING(0, "event", &kvm->report_event, "report event",
> +			"event for reporting: vmexit, mmio, ioport"),
> +		OPT_INTEGER(0, "vcpu", &kvm->trace_vcpu,
> +			"vcpu id to report"),
> +		OPT_STRING('k', "key", &kvm->sort_key, "sort-key",
> +			"key for sorting: sample(sort by samples number)"
> +			" time (sort by avg time)"),

Why we have so many parameters used for tracking. For KVM, we only need to know
1) which guest is tracked and 2) which vcpu in the guest is tracked and 3) what
kind of events. no?

Others look good to me. :)

Re: [PATCH 2/9] perf stats: add max and min stats

[Xiao Guangrong]

On 08/03/2013 04:05 AM, David Ahern wrote:
> Need an initialization function to set min to -1 to
> differentiate from an actual min of 0.

Reviewed-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>

Re: [PATCH 6/9] perf kvm: add min and max stats to display

[Xiao Guangrong]

On 08/03/2013 04:05 AM, David Ahern wrote:
> Signed-off-by: David Ahern <dsahern@gmail.com>
> Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
> Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
> ---
>  tools/perf/builtin-kvm.c |   21 ++++++++++++++++++---
>  1 file changed, 18 insertions(+), 3 deletions(-)
> 
> diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
> index 12f7593..5c6e3cd 100644
> --- a/tools/perf/builtin-kvm.c
> +++ b/tools/perf/builtin-kvm.c
> @@ -337,14 +337,19 @@ static void clear_events_cache_stats(struct list_head *kvm_events_cache)
>  	struct list_head *head;
>  	struct kvm_event *event;
>  	unsigned int i;
> +	int j;
> 
>  	for (i = 0; i < EVENTS_CACHE_SIZE; i++) {
>  		head = &kvm_events_cache[i];
>  		list_for_each_entry(event, head, hash_entry) {
>  			/* reset stats for event */
> -			memset(&event->total, 0, sizeof(event->total));
> -			memset(event->vcpu, 0,
> -			       event->max_vcpu * sizeof(*event->vcpu));
> +			event->total.time = 0;
> +			init_stats(&event->total.stats);
> +
> +			for (j = 0; j < event->max_vcpu; ++j) {
> +				event->vcpu[j].time = 0;
> +				init_stats(&event->vcpu[j].stats);
> +			}
>  		}
>  	}
>  }
> @@ -718,6 +723,7 @@ static void print_result(struct perf_kvm_stat *kvm)
>  	char decode[20];
>  	struct kvm_event *event;
>  	int vcpu = kvm->trace_vcpu;
> +	struct kvm_event_stats *kvm_stats;
> 
>  	if (kvm->live) {
>  		puts(CONSOLE_CLEAR);
> @@ -731,6 +737,8 @@ static void print_result(struct perf_kvm_stat *kvm)
>  	pr_info("%9s ", "Samples%");
> 
>  	pr_info("%9s ", "Time%");
> +	pr_info("%10s ", "Min Time");
> +	pr_info("%10s ", "Max Time");
>  	pr_info("%16s ", "Avg time");
>  	pr_info("\n\n");
> 
> @@ -740,11 +748,18 @@ static void print_result(struct perf_kvm_stat *kvm)
>  		ecount = get_event_count(event, vcpu);
>  		etime = get_event_time(event, vcpu);
> 
> +		if (vcpu == -1)
> +			kvm_stats = &event->total;
> +		else
> +			kvm_stats = &event->vcpu[vcpu];

Can introduce a function to do it like get_event_count()/get_event_time()?

And the min/max value are updated in patch 2, so others look good to me:
Reviewed-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>

Re: [PATCH 7/9] perf kvm: option to print events that exceed a threshold

[Xiao Guangrong]

On 08/03/2013 04:05 AM, David Ahern wrote:
> This is useful to spot high latency blips.

Yes, it is a good idea.

> 
> Signed-off-by: David Ahern <dsahern@gmail.com>
> Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
> Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
> ---
>  tools/perf/builtin-kvm.c |   25 +++++++++++++++++++++----
>  tools/perf/perf.h        |    3 +++
>  2 files changed, 24 insertions(+), 4 deletions(-)
> 
> diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
> index 5c6e3cd..28afc05d 100644
> --- a/tools/perf/builtin-kvm.c
> +++ b/tools/perf/builtin-kvm.c
> @@ -106,6 +106,7 @@ struct perf_kvm_stat {
>  	u64 total_time;
>  	u64 total_count;
>  	u64 lost_events;
> +	u64 threshold;
> 
>  	struct rb_root result;
> 
> @@ -470,7 +471,7 @@ static bool update_kvm_event(struct kvm_event *event, int vcpu_id,
>  static bool handle_end_event(struct perf_kvm_stat *kvm,
>  			     struct vcpu_event_record *vcpu_record,
>  			     struct event_key *key,
> -			     u64 timestamp)
> +			     struct perf_sample *sample)
>  {
>  	struct kvm_event *event;
>  	u64 time_begin, time_diff;
> @@ -507,12 +508,24 @@ static bool handle_end_event(struct perf_kvm_stat *kvm,
>  	vcpu_record->start_time = 0;
> 
>  	/* seems to happen once in a while during live mode */
> -	if (timestamp < time_begin) {
> +	if (sample->time < time_begin) {
>  		pr_debug("End time before begin time; skipping event.\n");
>  		return true;
>  	}
> 
> -	time_diff = timestamp - time_begin;
> +	time_diff = sample->time - time_begin;
> +
> +	if (kvm->threshold && time_diff > kvm->threshold) {
> +		char decode[32];
> +
> +		kvm->events_ops->decode_key(kvm, &event->key, decode);
> +		if (strcmp(decode, "HLT")) {
> +			pr_info("%" PRIu64 " VM %d, vcpu %d: %s event took %" PRIu64 "usec\n",
> +				 sample->time, sample->pid, vcpu_record->vcpu_id,
> +				 decode, time_diff/1000);
> +		}

Any reason to filter HLT out? it is too frequent? But the info will be missed if
we're really interested in this event.

It shows the info when the events is parsed which is not very readable and analyzable,
can we only record and print the events that cost long time (handle-time > threshould)?

Re: [PATCH 8/9] perf kvm: debug for missing vmexit/vmentry event

[Xiao Guangrong]

On 08/03/2013 04:05 AM, David Ahern wrote:
> Expected to have missing events for each vcpu when perf is
> started. After that should not have missing events.

Sorry, i can not understand what's this info used for.

> 
> Signed-off-by: David Ahern <dsahern@gmail.com>
> Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
> Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
> ---
>  tools/perf/builtin-kvm.c |   15 +++++++++++++--
>  1 file changed, 13 insertions(+), 2 deletions(-)
> 
> diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
> index 28afc05d..41dd25a 100644
> --- a/tools/perf/builtin-kvm.c
> +++ b/tools/perf/builtin-kvm.c
> @@ -568,11 +568,22 @@ static bool handle_kvm_event(struct perf_kvm_stat *kvm,
>  	    (kvm->trace_vcpu != vcpu_record->vcpu_id))
>  		return true;
> 
> -	if (kvm->events_ops->is_begin_event(evsel, sample, &key))
> +	if (kvm->events_ops->is_begin_event(evsel, sample, &key)) {
> +		if (vcpu_record->start_time) {
> +			pr_debug("consecutive begin events (%s) for pid %d, vcpu %d\n",
> +				 evsel->name, sample->pid, vcpu_record->vcpu_id);
> +		}

This is not true, the ->start_time is set in handle_begin_event() for the new alloced
vcpu_record.

If you just want to know the point where is the first event lost, you can track
it in:

static bool handle_end_event(struct perf_kvm_stat *kvm,
			     struct vcpu_event_record *vcpu_record,
			     struct event_key *key,
			     u64 timestamp)
{
	......

	/* The begin event is not caught. */
	if (!time_begin)                       <======
		return true;

Re: [PATCH 9/9] perf kvm stat report: Add option to analyze specific VM

[Xiao Guangrong]

On 08/03/2013 04:05 AM, David Ahern wrote:
> Add an option to analyze a specific VM within a data file. This
> allows the collection of kvm events for all VMs and then analyze
> data for each VM (or set of VMs) individually.

Interesting.

But how can we know which pid is the guest's pid after collecting
the info. Even if the .data file is moved to another box to do
off-analyze?

Re: [PATCH 5/9] perf kvm: add live mode - v3

[David Ahern]

On 8/5/13 1:53 AM, Xiao Guangrong wrote:
> Hi David,
>
> Thanks for your nice job! I got some questions.
>
> On 08/03/2013 04:05 AM, David Ahern wrote:
>
>>   static int kvm_events_hash_fn(u64 key)
>>   {
>>   	return key & (EVENTS_CACHE_SIZE - 1);
>> @@ -472,7 +501,11 @@ static bool handle_end_event(struct perf_kvm_stat *kvm,
>>   	vcpu_record->last_event = NULL;
>>   	vcpu_record->start_time = 0;
>>
>> -	BUG_ON(timestamp < time_begin);
>> +	/* seems to happen once in a while during live mode */
>> +	if (timestamp < time_begin) {
>> +		pr_debug("End time before begin time; skipping event.\n");
>> +		return true;
>> +	}
>
> No idea why it can happen. :(

I saw it triggering quite often early on (last Fall when I started this) 
and I changed the BUG_ON to keep going and get the command working. It 
needs to be revisited and figured out why an end event comes before a 
begin event - might be a start up problem only. But as a start point did 
not seem to hurt to just ignore the sample.

>
>> +static bool verify_vcpu(int vcpu)
>> +{
>> +	int nr_cpus;
>> +
>> +	if (vcpu != -1 && vcpu < 0) {
>> +		pr_err("Invalid vcpu:%d.\n", vcpu);
>> +		return false;
>> +	}
>> +
>> +	nr_cpus = sysconf(_SC_NPROCESSORS_ONLN);
>> +	if ((nr_cpus > 0) && (vcpu > nr_cpus - 1)) {
>> +		pr_err("Invalid vcpu:%d.\n", vcpu);
>> +		return false;
>> +	}
>
> Hmm, kvm can use more vcpus than the cpus on host.

Good point. I'll fix.

>
>> +static int kvm_events_live(struct perf_kvm_stat *kvm,
>> +			   int argc, const char **argv)
>> +{
>> +	char errbuf[BUFSIZ];
>> +	int err;
>> +
>> +	const struct option live_options[] = {
>> +		OPT_STRING('p', "pid", &kvm->opts.target.pid, "pid",
>> +			"record events on existing process id"),
>> +		OPT_STRING('t', "tid", &kvm->opts.target.tid, "tid",
>> +			"record events on existing thread id"),
>> +		OPT_STRING('C', "cpu", &kvm->opts.target.cpu_list, "cpu",
>> +			"list of host cpus to monitor"),
>> +		OPT_UINTEGER('m', "mmap-pages", &kvm->opts.mmap_pages,
>> +			"number of mmap data pages"),
>> +		OPT_INCR('v', "verbose", &verbose,
>> +			"be more verbose (show counter open errors, etc)"),
>> +		OPT_BOOLEAN('a', "all-cpus", &kvm->opts.target.system_wide,
>> +			"system-wide collection from all CPUs"),
>> +		OPT_UINTEGER('d', "display", &kvm->display_time,
>> +			"time in seconds between display updates"),
>> +		OPT_STRING(0, "event", &kvm->report_event, "report event",
>> +			"event for reporting: vmexit, mmio, ioport"),
>> +		OPT_INTEGER(0, "vcpu", &kvm->trace_vcpu,
>> +			"vcpu id to report"),
>> +		OPT_STRING('k', "key", &kvm->sort_key, "sort-key",
>> +			"key for sorting: sample(sort by samples number)"
>> +			" time (sort by avg time)"),
>
> Why we have so many parameters used for tracking. For KVM, we only need to know
> 1) which guest is tracked and 2) which vcpu in the guest is tracked and 3) what
> kind of events. no?

I should drop the cpu_list argument and tid is the same as vcpu so I can 
drop it. 'a' is implicit if pid is not given.

mmap-pages is definitely needed: a LOT of tracepoints get generated.

I'll update.

David

Re: [PATCH 6/9] perf kvm: add min and max stats to display

[David Ahern]

On 8/5/13 2:09 AM, Xiao Guangrong wrote:
> On 08/03/2013 04:05 AM, David Ahern wrote:
>> Signed-off-by: David Ahern <dsahern@gmail.com>
>> Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
>> Cc: Ingo Molnar <mingo@kernel.org>
>> Cc: Frederic Weisbecker <fweisbec@gmail.com>
>> Cc: Peter Zijlstra <peterz@infradead.org>
>> Cc: Jiri Olsa <jolsa@redhat.com>
>> Cc: Namhyung Kim <namhyung@kernel.org>
>> Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
>> Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
>> ---
>>   tools/perf/builtin-kvm.c |   21 ++++++++++++++++++---
>>   1 file changed, 18 insertions(+), 3 deletions(-)
>>
>> diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
>> index 12f7593..5c6e3cd 100644
>> --- a/tools/perf/builtin-kvm.c
>> +++ b/tools/perf/builtin-kvm.c
>> @@ -337,14 +337,19 @@ static void clear_events_cache_stats(struct list_head *kvm_events_cache)
>>   	struct list_head *head;
>>   	struct kvm_event *event;
>>   	unsigned int i;
>> +	int j;
>>
>>   	for (i = 0; i < EVENTS_CACHE_SIZE; i++) {
>>   		head = &kvm_events_cache[i];
>>   		list_for_each_entry(event, head, hash_entry) {
>>   			/* reset stats for event */
>> -			memset(&event->total, 0, sizeof(event->total));
>> -			memset(event->vcpu, 0,
>> -			       event->max_vcpu * sizeof(*event->vcpu));
>> +			event->total.time = 0;
>> +			init_stats(&event->total.stats);
>> +
>> +			for (j = 0; j < event->max_vcpu; ++j) {
>> +				event->vcpu[j].time = 0;
>> +				init_stats(&event->vcpu[j].stats);
>> +			}
>>   		}
>>   	}
>>   }
>> @@ -718,6 +723,7 @@ static void print_result(struct perf_kvm_stat *kvm)
>>   	char decode[20];
>>   	struct kvm_event *event;
>>   	int vcpu = kvm->trace_vcpu;
>> +	struct kvm_event_stats *kvm_stats;
>>
>>   	if (kvm->live) {
>>   		puts(CONSOLE_CLEAR);
>> @@ -731,6 +737,8 @@ static void print_result(struct perf_kvm_stat *kvm)
>>   	pr_info("%9s ", "Samples%");
>>
>>   	pr_info("%9s ", "Time%");
>> +	pr_info("%10s ", "Min Time");
>> +	pr_info("%10s ", "Max Time");
>>   	pr_info("%16s ", "Avg time");
>>   	pr_info("\n\n");
>>
>> @@ -740,11 +748,18 @@ static void print_result(struct perf_kvm_stat *kvm)
>>   		ecount = get_event_count(event, vcpu);
>>   		etime = get_event_time(event, vcpu);
>>
>> +		if (vcpu == -1)
>> +			kvm_stats = &event->total;
>> +		else
>> +			kvm_stats = &event->vcpu[vcpu];
>
> Can introduce a function to do it like get_event_count()/get_event_time()?

leveraging existing code in builtin-kvm.... ;-) I'll make a function.

David

>
> And the min/max value are updated in patch 2, so others look good to me:
> Reviewed-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
>

Re: [PATCH 7/9] perf kvm: option to print events that exceed a threshold

[David Ahern]

On 8/5/13 2:39 AM, Xiao Guangrong wrote:
> On 08/03/2013 04:05 AM, David Ahern wrote:
>> This is useful to spot high latency blips.
>
> Yes, it is a good idea.
>
>>
>> Signed-off-by: David Ahern <dsahern@gmail.com>
>> Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
>> Cc: Ingo Molnar <mingo@kernel.org>
>> Cc: Frederic Weisbecker <fweisbec@gmail.com>
>> Cc: Peter Zijlstra <peterz@infradead.org>
>> Cc: Jiri Olsa <jolsa@redhat.com>
>> Cc: Namhyung Kim <namhyung@kernel.org>
>> Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
>> Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
>> ---
>>   tools/perf/builtin-kvm.c |   25 +++++++++++++++++++++----
>>   tools/perf/perf.h        |    3 +++
>>   2 files changed, 24 insertions(+), 4 deletions(-)
>>
>> diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
>> index 5c6e3cd..28afc05d 100644
>> --- a/tools/perf/builtin-kvm.c
>> +++ b/tools/perf/builtin-kvm.c
>> @@ -106,6 +106,7 @@ struct perf_kvm_stat {
>>   	u64 total_time;
>>   	u64 total_count;
>>   	u64 lost_events;
>> +	u64 threshold;
>>
>>   	struct rb_root result;
>>
>> @@ -470,7 +471,7 @@ static bool update_kvm_event(struct kvm_event *event, int vcpu_id,
>>   static bool handle_end_event(struct perf_kvm_stat *kvm,
>>   			     struct vcpu_event_record *vcpu_record,
>>   			     struct event_key *key,
>> -			     u64 timestamp)
>> +			     struct perf_sample *sample)
>>   {
>>   	struct kvm_event *event;
>>   	u64 time_begin, time_diff;
>> @@ -507,12 +508,24 @@ static bool handle_end_event(struct perf_kvm_stat *kvm,
>>   	vcpu_record->start_time = 0;
>>
>>   	/* seems to happen once in a while during live mode */
>> -	if (timestamp < time_begin) {
>> +	if (sample->time < time_begin) {
>>   		pr_debug("End time before begin time; skipping event.\n");
>>   		return true;
>>   	}
>>
>> -	time_diff = timestamp - time_begin;
>> +	time_diff = sample->time - time_begin;
>> +
>> +	if (kvm->threshold && time_diff > kvm->threshold) {
>> +		char decode[32];
>> +
>> +		kvm->events_ops->decode_key(kvm, &event->key, decode);
>> +		if (strcmp(decode, "HLT")) {
>> +			pr_info("%" PRIu64 " VM %d, vcpu %d: %s event took %" PRIu64 "usec\n",
>> +				 sample->time, sample->pid, vcpu_record->vcpu_id,
>> +				 decode, time_diff/1000);
>> +		}
>
> Any reason to filter HLT out? it is too frequent? But the info will be missed if
> we're really interested in this event.

It is normal for HLT events to be long duration and by not stripping out 
HLT events you get a flood of messages.

It is abnormal for other kvm-exit events to take considerable time and 
those are the ones to emphasize to a user.

>
> It shows the info when the events is parsed which is not very readable and analyzable,
> can we only record and print the events that cost long time (handle-time > threshould)?

With the existing workflow -- record and then report -- those events are 
dumped prior to the stats output so they can be visible.

With the live mode command the intent is to keep going. The console 
output can be reviewed by scrolling up -- or redirect to a file as well 
with tee. I do both options.

We could add another option -- show the high latency events only and not 
the stats output.

David

Re: [PATCH 9/9] perf kvm stat report: Add option to analyze specific VM

[David Ahern]

On 8/5/13 2:57 AM, Xiao Guangrong wrote:
> On 08/03/2013 04:05 AM, David Ahern wrote:
>> Add an option to analyze a specific VM within a data file. This
>> allows the collection of kvm events for all VMs and then analyze
>> data for each VM (or set of VMs) individually.
>
> Interesting.
>
> But how can we know which pid is the guest's pid after collecting
> the info. Even if the .data file is moved to another box to do
> off-analyze?
>

Up to the user to be able to leverage the option by collecting what ever 
information is needed to correlate a qemu pid with a guest VM.

I have 2 use cases. In one I have a set of shell scripts for managing VMs:

   Id   Profile            PID     IP Address        Description
   --   ----------------   -----   ---------------   ----------------
   01   ubuntu10           -       172.16.128.51     Ubuntu 10.04 LTS
   02   f12-x86_64         8841    172.16.128.52     Fedora 12, x86_64
   05   f10-i386           -       172.16.128.55     Fedora 10, i386
   07   f16-i386           -       172.16.128.57
   08   f16-x86_64         -       172.16.128.58
   09   rhel5.5-i386       14716   172.16.128.59     RHEL 5.5, i386
   10   f10-x86_64         -       172.16.128.60
   12   rhel47-vm1         -       172.16.128.62     rhel4.7 - 32-bit
   13   f17                -       172.16.128.63     Fedora 17, x86_64
   15   f14                -       172.16.128.65     Fedora 14 - x86_64
   16   f10-ppc            -       172.16.128.66
   17   f12-ppc            -       172.16.128.67
   19   f16-ppc            -       172.16.128.69
   20   f16-i386-2         -       172.16.128.70     clone of f16-i386
   21   f18-controller     29590   172.16.128.71     cloud controller
   22   f18                29541   172.16.128.72     Fedora 18 - x86_64

Collecting that information allows me to correlate kvm data to a VM pid. 
I can collect the events for the system and then analyze for a specific VM.

In the second use case (product based) there are 2 VMs and a different 
qemu binary name (along with command line arguments) for telling them apart.

David

Re: [PATCH 8/9] perf kvm: debug for missing vmexit/vmentry event

[David Ahern]

On 8/5/13 2:53 AM, Xiao Guangrong wrote:
> On 08/03/2013 04:05 AM, David Ahern wrote:
>> Expected to have missing events for each vcpu when perf is
>> started. After that should not have missing events.
>
> Sorry, i can not understand what's this info used for.

For debugging. Things that should not happen do seem to happen -- 
rarely, but it does

>
>>
>> Signed-off-by: David Ahern <dsahern@gmail.com>
>> Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
>> Cc: Ingo Molnar <mingo@kernel.org>
>> Cc: Frederic Weisbecker <fweisbec@gmail.com>
>> Cc: Peter Zijlstra <peterz@infradead.org>
>> Cc: Jiri Olsa <jolsa@redhat.com>
>> Cc: Namhyung Kim <namhyung@kernel.org>
>> Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
>> Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
>> ---
>>   tools/perf/builtin-kvm.c |   15 +++++++++++++--
>>   1 file changed, 13 insertions(+), 2 deletions(-)
>>
>> diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
>> index 28afc05d..41dd25a 100644
>> --- a/tools/perf/builtin-kvm.c
>> +++ b/tools/perf/builtin-kvm.c
>> @@ -568,11 +568,22 @@ static bool handle_kvm_event(struct perf_kvm_stat *kvm,
>>   	    (kvm->trace_vcpu != vcpu_record->vcpu_id))
>>   		return true;
>>
>> -	if (kvm->events_ops->is_begin_event(evsel, sample, &key))
>> +	if (kvm->events_ops->is_begin_event(evsel, sample, &key)) {
>> +		if (vcpu_record->start_time) {
>> +			pr_debug("consecutive begin events (%s) for pid %d, vcpu %d\n",
>> +				 evsel->name, sample->pid, vcpu_record->vcpu_id);
>> +		}
>
> This is not true, the ->start_time is set in handle_begin_event() for the new alloced
> vcpu_record.
>
> If you just want to know the point where is the first event lost, you can track
> it in:
>
> static bool handle_end_event(struct perf_kvm_stat *kvm,
> 			     struct vcpu_event_record *vcpu_record,
> 			     struct event_key *key,
> 			     u64 timestamp)
> {
> 	......
>
> 	/* The begin event is not caught. */
> 	if (!time_begin)                       <======
> 		return true;
>

Ok. I'll drop the patch. I added it for a reason, but can't remember why 
at the moment.

David

Re: [PATCH 4/9] perf kvm: split out tracepoints from record args

[Arnaldo Carvalho de Melo]

Em Mon, Aug 05, 2013 at 01:09:47PM +0800, Xiao Guangrong escreveu:
> On 08/03/2013 04:05 AM, David Ahern wrote:
> > Needed by kvm live command. Make record_args a local while we are
> > messing with the args.
> 
> Reviewed-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>

Merged up to this one, waiting for the rest with Xiao's comments
addressed,

- Arnaldo

[tip:perf/core] perf top: move CONSOLE_CLEAR to header file

[tip-bot for David Ahern]

Commit-ID:  42ee8c61cb1b7fe7b7ad5071bfb3c609cb0620ca
Gitweb:     http://git.kernel.org/tip/42ee8c61cb1b7fe7b7ad5071bfb3c609cb0620ca
Author:     David Ahern <dsahern@gmail.com>
AuthorDate: Fri, 2 Aug 2013 14:05:39 -0600
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 7 Aug 2013 17:35:26 -0300

perf top: move CONSOLE_CLEAR to header file

For use with kvm-live mode.

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Link: http://lkml.kernel.org/r/1375473947-64285-2-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-top.c | 2 --
 tools/perf/util/top.h    | 2 ++
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-top.c b/tools/perf/builtin-top.c
index bbf4635..9101f7c 100644
--- a/tools/perf/builtin-top.c
+++ b/tools/perf/builtin-top.c
@@ -238,8 +238,6 @@ out_unlock:
 	pthread_mutex_unlock(&notes->lock);
 }
 
-static const char		CONSOLE_CLEAR[] = "^[[H^[[2J";
-
 static struct hist_entry *perf_evsel__add_hist_entry(struct perf_evsel *evsel,
 						     struct addr_location *al,
 						     struct perf_sample *sample)
diff --git a/tools/perf/util/top.h b/tools/perf/util/top.h
index df46be9..b554ffc 100644
--- a/tools/perf/util/top.h
+++ b/tools/perf/util/top.h
@@ -39,6 +39,8 @@ struct perf_top {
 	float		   min_percent;
 };
 
+#define CONSOLE_CLEAR "^[[H^[[2J"
+
 size_t perf_top__header_snprintf(struct perf_top *top, char *bf, size_t size);
 void perf_top__reset_sample_counters(struct perf_top *top);
 #endif /* __PERF_TOP_H */

[tip:perf/core] perf stats: Add max and min stats

[tip-bot for David Ahern]

Commit-ID:  ffe4f3c0d109dc53e1b3448ac457052107f34a84
Gitweb:     http://git.kernel.org/tip/ffe4f3c0d109dc53e1b3448ac457052107f34a84
Author:     David Ahern <dsahern@gmail.com>
AuthorDate: Fri, 2 Aug 2013 14:05:40 -0600
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 7 Aug 2013 17:35:26 -0300

perf stats: Add max and min stats

Need an initialization function to set min to -1 to
differentiate from an actual min of 0.

Signed-off-by: David Ahern <dsahern@gmail.com>
Reviewed-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Link: http://lkml.kernel.org/r/1375473947-64285-3-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/stat.c | 6 ++++++
 tools/perf/util/stat.h | 9 +++++++++
 2 files changed, 15 insertions(+)

diff --git a/tools/perf/util/stat.c b/tools/perf/util/stat.c
index 7c59c28..6506b3d 100644
--- a/tools/perf/util/stat.c
+++ b/tools/perf/util/stat.c
@@ -10,6 +10,12 @@ void update_stats(struct stats *stats, u64 val)
 	delta = val - stats->mean;
 	stats->mean += delta / stats->n;
 	stats->M2 += delta*(val - stats->mean);
+
+	if (val > stats->max)
+		stats->max = val;
+
+	if (val < stats->min)
+		stats->min = val;
 }
 
 double avg_stats(struct stats *stats)
diff --git a/tools/perf/util/stat.h b/tools/perf/util/stat.h
index 588367c..ae8ccd7 100644
--- a/tools/perf/util/stat.h
+++ b/tools/perf/util/stat.h
@@ -6,6 +6,7 @@
 struct stats
 {
 	double n, mean, M2;
+	u64 max, min;
 };
 
 void update_stats(struct stats *stats, u64 val);
@@ -13,4 +14,12 @@ double avg_stats(struct stats *stats);
 double stddev_stats(struct stats *stats);
 double rel_stddev_stats(double stddev, double avg);
 
+static inline void init_stats(struct stats *stats)
+{
+	stats->n    = 0.0;
+	stats->mean = 0.0;
+	stats->M2   = 0.0;
+	stats->min  = (u64) -1;
+	stats->max  = 0;
+}
 #endif

[tip:perf/core] perf session: Export a few functions for event processing

[tip-bot for David Ahern]

Commit-ID:  9c5014022f5d5b09abc8b713da81b3d2db319699
Gitweb:     http://git.kernel.org/tip/9c5014022f5d5b09abc8b713da81b3d2db319699
Author:     David Ahern <dsahern@gmail.com>
AuthorDate: Fri, 2 Aug 2013 14:05:41 -0600
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 7 Aug 2013 17:35:27 -0300

perf session: Export a few functions for event processing

Allows kvm live mode to reuse the event processing and ordered samples
processing used by the perf-report path.

v2: removed flush_sample_queue as noticed by Jiri

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Link: http://lkml.kernel.org/r/1375473947-64285-4-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/util/session.c | 12 ++++++------
 tools/perf/util/session.h |  7 +++++++
 2 files changed, 13 insertions(+), 6 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index a0ce5a4..b5ebd47 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -250,7 +250,7 @@ static int process_finished_round(struct perf_tool *tool,
 				  union perf_event *event,
 				  struct perf_session *session);
 
-static void perf_tool__fill_defaults(struct perf_tool *tool)
+void perf_tool__fill_defaults(struct perf_tool *tool)
 {
 	if (tool->sample == NULL)
 		tool->sample = process_event_sample_stub;
@@ -495,7 +495,7 @@ static int perf_session_deliver_event(struct perf_session *session,
 				      u64 file_offset);
 
 static int flush_sample_queue(struct perf_session *s,
-			       struct perf_tool *tool)
+		       struct perf_tool *tool)
 {
 	struct ordered_samples *os = &s->ordered_samples;
 	struct list_head *head = &os->samples;
@@ -1049,10 +1049,10 @@ static void event_swap(union perf_event *event, bool sample_id_all)
 		swap(event, sample_id_all);
 }
 
-static int perf_session__process_event(struct perf_session *session,
-				       union perf_event *event,
-				       struct perf_tool *tool,
-				       u64 file_offset)
+int perf_session__process_event(struct perf_session *session,
+				union perf_event *event,
+				struct perf_tool *tool,
+				u64 file_offset)
 {
 	struct perf_sample sample;
 	int ret;
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index ad8d3d4..9818fc2 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -56,6 +56,13 @@ int __perf_session__process_events(struct perf_session *self,
 int perf_session__process_events(struct perf_session *self,
 				 struct perf_tool *tool);
 
+int perf_session__process_event(struct perf_session *session,
+				union perf_event *event,
+				struct perf_tool *tool,
+				u64 file_offset);
+
+void perf_tool__fill_defaults(struct perf_tool *tool);
+
 int perf_session__resolve_callchain(struct perf_session *self, struct perf_evsel *evsel,
 				    struct thread *thread,
 				    struct ip_callchain *chain,

[tip:perf/core] perf kvm: Split out tracepoints from record args

[tip-bot for David Ahern]

Commit-ID:  8fdd84c44fd09d783caa4fb81d2d680b0cf07eeb
Gitweb:     http://git.kernel.org/tip/8fdd84c44fd09d783caa4fb81d2d680b0cf07eeb
Author:     David Ahern <dsahern@gmail.com>
AuthorDate: Fri, 2 Aug 2013 14:05:42 -0600
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 7 Aug 2013 17:35:27 -0300

perf kvm: Split out tracepoints from record args

Needed by kvm live command. Make record_args a local while we are
messing with the args.

Signed-off-by: David Ahern <dsahern@gmail.com>
Reviewed-by: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Link: http://lkml.kernel.org/r/1375473947-64285-5-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-kvm.c | 30 +++++++++++++++++++-----------
 1 file changed, 19 insertions(+), 11 deletions(-)

diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c
index 24b78ae..7d14a3a 100644
--- a/tools/perf/builtin-kvm.c
+++ b/tools/perf/builtin-kvm.c
@@ -801,16 +801,11 @@ exit:
 	return ret;
 }
 
-static const char * const record_args[] = {
-	"record",
-	"-R",
-	"-f",
-	"-m", "1024",
-	"-c", "1",
-	"-e", "kvm:kvm_entry",
-	"-e", "kvm:kvm_exit",
-	"-e", "kvm:kvm_mmio",
-	"-e", "kvm:kvm_pio",
+static const char * const kvm_events_tp[] = {
+	"kvm:kvm_entry",
+	"kvm:kvm_exit",
+	"kvm:kvm_mmio",
+	"kvm:kvm_pio",
 };
 
 #define STRDUP_FAIL_EXIT(s)		\
@@ -826,8 +821,16 @@ kvm_events_record(struct perf_kvm_stat *kvm, int argc, const char **argv)
 {
 	unsigned int rec_argc, i, j;
 	const char **rec_argv;
+	const char * const record_args[] = {
+		"record",
+		"-R",
+		"-f",
+		"-m", "1024",
+		"-c", "1",
+	};
 
-	rec_argc = ARRAY_SIZE(record_args) + argc + 2;
+	rec_argc = ARRAY_SIZE(record_args) + argc + 2 +
+		   2 * ARRAY_SIZE(kvm_events_tp);
 	rec_argv = calloc(rec_argc + 1, sizeof(char *));
 
 	if (rec_argv == NULL)
@@ -836,6 +839,11 @@ kvm_events_record(struct perf_kvm_stat *kvm, int argc, const char **argv)
 	for (i = 0; i < ARRAY_SIZE(record_args); i++)
 		rec_argv[i] = STRDUP_FAIL_EXIT(record_args[i]);
 
+	for (j = 0; j < ARRAY_SIZE(kvm_events_tp); j++) {
+		rec_argv[i++] = "-e";
+		rec_argv[i++] = STRDUP_FAIL_EXIT(kvm_events_tp[j]);
+	}
+
 	rec_argv[i++] = STRDUP_FAIL_EXIT("-o");
 	rec_argv[i++] = STRDUP_FAIL_EXIT(kvm->file_name);