Skip to contentSkip to conversation

perf: kvm live mode

PATCH In review David Ahern 4 participants 27 messages Aug 2, 2013 – Aug 12, 2013 perf events

lore
Share & tools
lore
#0 lore raw

cover perf: kvm live mode

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(-)
Signature · 1 line
1.7.10.1
#1 lore raw

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

For use with kvm-live mode.

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-top.c |    2 --
 tools/perf/util/top.h    |    2 ++
 2 files changed, 2 insertions(+), 2 deletions(-)
tools/perf/builtin-top.c +0 -2
index bbf4635..9101f7c 100644
@@ -238,8 +238,6 @@ out_unlock:
 	pthread_mutex_unlock(&notes->lock);
 }
 
-static const char		CONSOLE_CLEAR[] = "";
-
 static struct hist_entry *perf_evsel__add_hist_entry(struct perf_evsel *evsel,
 						     struct addr_location *al,
 						     struct perf_sample *sample)
tools/perf/util/top.h +2 -0
index df46be9..b554ffc 100644
@@ -39,6 +39,8 @@ struct perf_top {
 	float		   min_percent;
 };
 
+#define CONSOLE_CLEAR ""
+
 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 */
Signature · 1 line
1.7.10.1
#2 lore raw

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

perf top: move CONSOLE_CLEAR to header file
Commit-ID:  42ee8c61cb1b7fe7b7ad5071bfb3c609cb0620ca
Gitweb:     http://git.kernel.org/tip/42ee8c61cb1b7fe7b7ad5071bfb3c609cb0620ca
Author:     David Ahern <[email protected]>
AuthorDate: Fri, 2 Aug 2013 14:05:39 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Wed, 7 Aug 2013 17:35:26 -0300

perf top: move CONSOLE_CLEAR to header file

For use with kvm-live mode.

---
 tools/perf/builtin-top.c | 2 --
 tools/perf/util/top.h    | 2 ++
 2 files changed, 2 insertions(+), 2 deletions(-)
tools/perf/builtin-top.c +0 -2
index bbf4635..9101f7c 100644
@@ -238,8 +238,6 @@ out_unlock:
 	pthread_mutex_unlock(&notes->lock);
 }
 
-static const char		CONSOLE_CLEAR[] = "";
-
 static struct hist_entry *perf_evsel__add_hist_entry(struct perf_evsel *evsel,
 						     struct addr_location *al,
 						     struct perf_sample *sample)
tools/perf/util/top.h +2 -0
index df46be9..b554ffc 100644
@@ -39,6 +39,8 @@ struct perf_top {
 	float		   min_percent;
 };
 
+#define CONSOLE_CLEAR ""
+
 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 */
#3 lore raw

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

In reply to David Ahern

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

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/util/stat.c |    6 ++++++
 tools/perf/util/stat.h |    9 +++++++++
 2 files changed, 15 insertions(+)
tools/perf/util/stat.c +6 -0
index 7c59c28..6506b3d 100644
@@ -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)
tools/perf/util/stat.h +9 -0
index 588367c..ae8ccd7 100644
@@ -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
Signature · 1 line
1.7.10.1
#5 lore raw

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

In reply to David Ahern
perf stats: Add max and min stats
Commit-ID:  ffe4f3c0d109dc53e1b3448ac457052107f34a84
Gitweb:     http://git.kernel.org/tip/ffe4f3c0d109dc53e1b3448ac457052107f34a84
Author:     David Ahern <[email protected]>
AuthorDate: Fri, 2 Aug 2013 14:05:40 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
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.

---
 tools/perf/util/stat.c | 6 ++++++
 tools/perf/util/stat.h | 9 +++++++++
 2 files changed, 15 insertions(+)
tools/perf/util/stat.c +6 -0
index 7c59c28..6506b3d 100644
@@ -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)
tools/perf/util/stat.h +9 -0
index 588367c..ae8ccd7 100644
@@ -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
#6 lore raw

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

In reply to 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

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/util/session.c |   12 ++++++------
 tools/perf/util/session.h |    7 +++++++
 2 files changed, 13 insertions(+), 6 deletions(-)
tools/perf/util/session.c +6 -6
index a0ce5a4..b5ebd47 100644
@@ -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;
tools/perf/util/session.h +7 -0
index ad8d3d4..9818fc2 100644
@@ -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,
Signature · 1 line
1.7.10.1
#7 lore raw

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

perf session: Export a few functions for event processing
Commit-ID:  9c5014022f5d5b09abc8b713da81b3d2db319699
Gitweb:     http://git.kernel.org/tip/9c5014022f5d5b09abc8b713da81b3d2db319699
Author:     David Ahern <[email protected]>
AuthorDate: Fri, 2 Aug 2013 14:05:41 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
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

---
 tools/perf/util/session.c | 12 ++++++------
 tools/perf/util/session.h |  7 +++++++
 2 files changed, 13 insertions(+), 6 deletions(-)
tools/perf/util/session.c +6 -6
index a0ce5a4..b5ebd47 100644
@@ -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;
tools/perf/util/session.h +7 -0
index ad8d3d4..9818fc2 100644
@@ -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,
#8 lore raw

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

In reply to David Ahern

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

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   30 +++++++++++++++++++-----------
 1 file changed, 19 insertions(+), 11 deletions(-)
tools/perf/builtin-kvm.c +19 -11
index 24b78ae..7d14a3a 100644
@@ -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);
 
Signature · 1 line
1.7.10.1
Reviewed-by on v1 4/9
#9 lore raw

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

Quoted 2 lines · David Ahern

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

#10 lore raw

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

Em Mon, Aug 05, 2013 at 01:09:47PM +0800, Xiao Guangrong escreveu:

Quoted 5 lines · David Ahern
Quoted 2 lines

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

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

- Arnaldo

#11 lore raw

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

In reply to David Ahern
perf kvm: Split out tracepoints from record args
Commit-ID:  8fdd84c44fd09d783caa4fb81d2d680b0cf07eeb
Gitweb:     http://git.kernel.org/tip/8fdd84c44fd09d783caa4fb81d2d680b0cf07eeb
Author:     David Ahern <[email protected]>
AuthorDate: Fri, 2 Aug 2013 14:05:42 -0600
Committer:  Arnaldo Carvalho de Melo <[email protected]>
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.

---
 tools/perf/builtin-kvm.c | 30 +++++++++++++++++++-----------
 1 file changed, 19 insertions(+), 11 deletions(-)
tools/perf/builtin-kvm.c +19 -11
index 24b78ae..7d14a3a 100644
@@ -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);
 
#12 lore raw

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

In reply to 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.

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |  644 ++++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 618 insertions(+), 26 deletions(-)
tools/perf/builtin-kvm.c +618 -26
index 7d14a3a..12f7593 100644
@@ -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);
 }
Signature · 1 line
1.7.10.1
#13 lore raw

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

Hi David,

Thanks for your nice job! I got some questions.

tools/perf/builtin-kvm.c static bool handle_end_event(struct perf_kvm_stat *kvm, · line 508

Quoted 13 lines · David Ahern

static int kvm_events_hash_fn(u64 key)
{

tools/perf/builtin-kvm.c +5 -1
 	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. :(

Quoted 4 lines
tools/perf/builtin-kvm.c +4 -0
+static bool verify_vcpu(int vcpu)
+{
+	int nr_cpus;
+

tools/perf/builtin-kvm.c static int get_cpu_isa(struct perf_session *session) · line 839

Quoted 10 lines
tools/perf/builtin-kvm.c +10 -0
+	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.

Quoted 18 lines
tools/perf/builtin-kvm.c +18 -0
+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,

tools/perf/builtin-kvm.c kvm_events_report(struct perf_kvm_stat *kvm, int argc, const char **argv) · line 1369

Quoted 10 lines
tools/perf/builtin-kvm.c +10 -0
+			"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. :)

#14 lore raw

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

Quoted 13 lines · Xiao Guangrong

Hi David,

Thanks for your nice job! I got some questions.

Quoted 7 lines · David Ahern
  static int kvm_events_hash_fn(u64 key)
  {
  	return key & (EVENTS_CACHE_SIZE - 1);
tools/perf/builtin-kvm.c +0 -0
@@ -472,7 +501,11 @@ static bool handle_end_event(struct perf_kvm_stat *kvm,
  	vcpu_record->last_event = NULL;
  	vcpu_record->start_time = 0;
 
Quoted 8 lines

tools/perf/builtin-kvm.c static bool handle_end_event(struct perf_kvm_stat *kvm, · line 508

Quoted 6 lines
tools/perf/builtin-kvm.c +5 -1
-	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.

Quoted 17 lines
Quoted 5 lines
tools/perf/builtin-kvm.c +4 -0
+static bool verify_vcpu(int vcpu)
+{
+	int nr_cpus;
+

tools/perf/builtin-kvm.c static int get_cpu_isa(struct perf_session *session) · line 839

Quoted 10 lines
tools/perf/builtin-kvm.c +10 -0
+	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.

Quoted 25 lines
Quoted 25 lines
tools/perf/builtin-kvm.c +24 -0
+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,
Quoted 8 lines

tools/perf/builtin-kvm.c kvm_events_report(struct perf_kvm_stat *kvm, int argc, const char **argv) · line 1369

Quoted 4 lines
tools/perf/builtin-kvm.c +4 -0
+			"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

#15 lore raw

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

In reply to David Ahern
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   21 ++++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)
tools/perf/builtin-kvm.c +18 -3
index 12f7593..5c6e3cd 100644
@@ -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");
Signature · 1 line
1.7.10.1
Reviewed-by on v1 6/9
#16 lore raw

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

Quoted 58 lines · David Ahern
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   21 ++++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)
tools/perf/builtin-kvm.c +11 -3
index 12f7593..5c6e3cd 100644
@@ -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");
 

tools/perf/builtin-kvm.c static void print_result(struct perf_kvm_stat *kvm) · line 754

Quoted 7 lines
tools/perf/builtin-kvm.c +4 -0
@@ -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:

#17 lore raw

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

Quoted 62 lines · Xiao Guangrong
Quoted 61 lines · David Ahern
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
  tools/perf/builtin-kvm.c |   21 ++++++++++++++++++---
  1 file changed, 18 insertions(+), 3 deletions(-)
tools/perf/builtin-kvm.c +11 -3
index 12f7593..5c6e3cd 100644
@@ -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);
 
Quoted 6 lines

tools/perf/builtin-kvm.c static void print_result(struct perf_kvm_stat *kvm) · line 754

Quoted 4 lines
tools/perf/builtin-kvm.c +4 -0
+		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

Quoted 4 lines

And the min/max value are updated in patch 2, so others look good to me:

#18 lore raw

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

In reply to David Ahern

This is useful to spot high latency blips.

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   25 +++++++++++++++++++++----
 tools/perf/perf.h        |    3 +++
 2 files changed, 24 insertions(+), 4 deletions(-)
tools/perf/builtin-kvm.c +21 -4
index 5c6e3cd..28afc05d 100644
@@ -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
 	 */
tools/perf/perf.h +3 -0
index 32bd102..cf20187 100644
@@ -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)
 {
Signature · 1 line
1.7.10.1
#19 lore raw

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

Quoted 1 line · David Ahern

This is useful to spot high latency blips.

Yes, it is a good idea.

Quoted 48 lines
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   25 +++++++++++++++++++++----
 tools/perf/perf.h        |    3 +++
 2 files changed, 24 insertions(+), 4 deletions(-)
tools/perf/builtin-kvm.c +4 -3
index 5c6e3cd..28afc05d 100644
@@ -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;

tools/perf/builtin-kvm.c static bool handle_end_event(struct perf_kvm_stat *kvm, · line 526

Quoted 10 lines
tools/perf/builtin-kvm.c +10 -0
+
+	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)?

#20 lore raw

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

Quoted 51 lines · Xiao Guangrong
Quoted 1 line · David Ahern

This is useful to spot high latency blips.

Yes, it is a good idea.

Quoted 46 lines
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
  tools/perf/builtin-kvm.c |   25 +++++++++++++++++++++----
  tools/perf/perf.h        |    3 +++
  2 files changed, 24 insertions(+), 4 deletions(-)
tools/perf/builtin-kvm.c +3 -2
index 5c6e3cd..28afc05d 100644
@@ -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;
  	}
 
Quoted 15 lines

tools/perf/builtin-kvm.c static bool handle_end_event(struct perf_kvm_stat *kvm, · line 526

Quoted 12 lines
tools/perf/builtin-kvm.c +11 -1
-	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.

Quoted 3 lines

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

#21 lore raw

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

In reply to David Ahern

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

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)
tools/perf/builtin-kvm.c +13 -2
index 28afc05d..41dd25a 100644
@@ -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;
 }
Signature · 1 line
1.7.10.1
#22 lore raw

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

Quoted 2 lines · David Ahern

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.

Quoted 19 lines
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)
tools/perf/builtin-kvm.c +0 -0
index 28afc05d..41dd25a 100644

tools/perf/builtin-kvm.c static bool handle_kvm_event(struct perf_kvm_stat *kvm, · line 575

Quoted 9 lines
tools/perf/builtin-kvm.c +5 -1
@@ -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;
#23 lore raw

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

Quoted 5 lines · Xiao Guangrong
Quoted 2 lines · David Ahern

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

Quoted 40 lines
Quoted 20 lines
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
  tools/perf/builtin-kvm.c |   15 +++++++++++++--
  1 file changed, 13 insertions(+), 2 deletions(-)
tools/perf/builtin-kvm.c +0 -0
index 28afc05d..41dd25a 100644

tools/perf/builtin-kvm.c static bool handle_kvm_event(struct perf_kvm_stat *kvm, · line 575

Quoted 9 lines
tools/perf/builtin-kvm.c +5 -1
@@ -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)

Quoted 7 lines
{
	......

	/* 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

#24 lore raw

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

In reply to 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.

Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Xiao Guangrong <[email protected]>
Cc Runzhen Wang <[email protected]>
---
 tools/perf/builtin-kvm.c |   38 ++++++++++++++++++++++++++++++++++++--
 1 file changed, 36 insertions(+), 2 deletions(-)
tools/perf/builtin-kvm.c +36 -2
index 41dd25a..54f9852 100644
@@ -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()
 	};
 
Signature · 1 line
1.7.10.1
#25 lore raw

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

Quoted 3 lines · 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.

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?

#26 lore raw

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

Quoted 11 lines · Xiao Guangrong
Quoted 3 lines · 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.

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