Skip to contentSkip to conversation

perf kvm: option to print events that exceed a duration -v2

PATCH Applied David Ahern 3 participants 6 messages Aug 8, 2013 – Aug 15, 2013 perf events

lore
Share & tools
lore
#0 lore raw

PATCH 1/2 perf kvm: option to print events that exceed a duration -v2

This is useful to spot high latency blips. It is normal for HLT reasons to have long exit times, so strip those from the duration check.

v2: changed threshold to duration per acme's request

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 2ceec81..fa2f3d7 100644
@@ -106,6 +106,7 @@ struct perf_kvm_stat {
 	u64 total_time;
 	u64 total_count;
 	u64 lost_events;
+	u64 duration;
 
 	const char *pid_str;
 	struct intlist *pid_list;
@@ -473,7 +474,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;
@@ -510,12 +511,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->duration && time_diff > kvm->duration) {
+		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);
 }
 
@@ -562,7 +575,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;
 }
@@ -1429,6 +1442,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(0, "duration", &kvm->duration,
+		    "show events other than HALT that take longer than duration usecs"),
 		OPT_END()
 	};
 	const char * const live_usage[] = {
@@ -1467,6 +1482,8 @@ static int kvm_events_live(struct perf_kvm_stat *kvm,
 			usage_with_options(live_usage, live_options);
 	}
 
+	kvm->duration *= 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
#1 lore raw

PATCH 2/2 perf kvm: Update documentation with live command

Update perf-kvm documentation with new live subcommand. Add -p/--pid option for perf-kvm-stat-report as well.

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/Documentation/perf-kvm.txt |   46 +++++++++++++++++++++++++++++++--
 1 file changed, 44 insertions(+), 2 deletions(-)
tools/perf/Documentation/perf-kvm.txt +44 -2
index 326f2cb..ac84db2 100644
@@ -13,6 +13,7 @@ SYNOPSIS
 	{top|record|report|diff|buildid-list}
 'perf kvm' [--host] [--guest] [--guestkallsyms=<path> --guestmodules=<path>
 	| --guestvmlinux=<path>] {top|record|report|diff|buildid-list|stat}
+'perf kvm stat [record|report|live] [<options>]
 
 DESCRIPTION
 -----------
@@ -50,6 +51,10 @@ There are a couple of variants of perf kvm:
   'perf kvm stat report' reports statistical data which includes events
   handled time, samples, and so on.
 
+  'perf kvm stat live' reports statistical data in a live mode (similar to
+  record + report but with statistical data updated live at a given display
+  rate).
+
 OPTIONS
 -------
 -i::
@@ -85,13 +90,50 @@ STAT REPORT OPTIONS
 --vcpu=<value>::
        analyze events which occures on this vcpu. (default: all vcpus)
 
---events=<value>::
-       events to be analyzed. Possible values: vmexit, mmio, ioport.
+--event=<value>::
+       event to be analyzed. Possible values: vmexit, mmio, ioport.
        (default: vmexit)
 -k::
 --key=<value>::
        Sorting key. Possible values: sample (default, sort by samples
        number), time (sort by average time).
+-p::
+--pid=::
+    Analyze events only for given process ID(s) (comma separated list).
+
+STAT LIVE OPTIONS
+-----------------
+-d::
+--display::
+        Time in seconds between display updates
+
+-m::
+--mmap-pages=::
+    Number of mmap data pages. Must be a power of two.
+
+-a::
+--all-cpus::
+        System-wide collection from all CPUs.
+
+-p::
+--pid=::
+    Analyze events only for given process ID(s) (comma separated list).
+
+--vcpu=<value>::
+       analyze events which occures on this vcpu. (default: all vcpus)
+
+
+--event=<value>::
+       event to be analyzed. Possible values: vmexit, mmio, ioport.
+       (default: vmexit)
+
+-k::
+--key=<value>::
+       Sorting key. Possible values: sample (default, sort by samples
+       number), time (sort by average time).
+
+--duration=<value>::
+       Show events other than HLT that take longer than duration usecs.
 
 SEE ALSO
 --------
Signature · 1 line
1.7.10.1
#2 lore raw

Re: [PATCH 2/2] perf kvm: Update documentation with live command

Em Wed, Aug 07, 2013 at 09:56:39PM -0400, David Ahern escreveu:

Quoted 2 lines

Update perf-kvm documentation with new live subcommand. Add -p/--pid option for perf-kvm-stat-report as well.

Minor nitpicks, that I'm fixing up, below. Applied.

Quoted 40 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/Documentation/perf-kvm.txt |   46 +++++++++++++++++++++++++++++++--
 1 file changed, 44 insertions(+), 2 deletions(-)
tools/perf/Documentation/perf-kvm.txt +5 -0
index 326f2cb..ac84db2 100644
@@ -13,6 +13,7 @@ SYNOPSIS
 	{top|record|report|diff|buildid-list}
 'perf kvm' [--host] [--guest] [--guestkallsyms=<path> --guestmodules=<path>
 	| --guestvmlinux=<path>] {top|record|report|diff|buildid-list|stat}
+'perf kvm stat [record|report|live] [<options>]
 
 DESCRIPTION
 -----------
@@ -50,6 +51,10 @@ There are a couple of variants of perf kvm:
   'perf kvm stat report' reports statistical data which includes events
   handled time, samples, and so on.
 
+  'perf kvm stat live' reports statistical data in a live mode (similar to
+  record + report but with statistical data updated live at a given display
+  rate).
+
 OPTIONS
 -------
 -i::
@@ -85,13 +90,50 @@ STAT REPORT OPTIONS
 --vcpu=<value>::
        analyze events which occures on this vcpu. (default: all vcpus)
 

tools/perf/Documentation/perf-kvm.txt STAT REPORT OPTIONS · line 100

Quoted 10 lines
tools/perf/Documentation/perf-kvm.txt +2 -2
---events=<value>::
-       events to be analyzed. Possible values: vmexit, mmio, ioport.
 
 
+--event=<value>::
+       event to be analyzed. Possible values: vmexit, mmio, ioport.
        (default: vmexit)
 -k::
 --key=<value>::
        Sorting key. Possible values: sample (default, sort by samples

Here you start, correctly, with a capital letter.

Quoted 15 lines
tools/perf/Documentation/perf-kvm.txt +14 -0
        number), time (sort by average time).
+-p::
+--pid=::
+    Analyze events only for given process ID(s) (comma separated list).
+
+STAT LIVE OPTIONS
+-----------------
+-d::
+--display::
+        Time in seconds between display updates
+
+-m::
+--mmap-pages=::
+    Number of mmap data pages. Must be a power of two.
+

tools/perf/Documentation/perf-kvm.txt STAT REPORT OPTIONS · line 123

Quoted 10 lines
tools/perf/Documentation/perf-kvm.txt +10 -0
+-a::
+--all-cpus::
+        System-wide collection from all CPUs.
+
+-p::
+--pid=::
+    Analyze events only for given process ID(s) (comma separated list).
+
+--vcpu=<value>::
+       analyze events which occures on this vcpu. (default: all vcpus)

Here you don't.

tools/perf/Documentation/perf-kvm.txt STAT REPORT OPTIONS · line 128

Quoted 5 lines
tools/perf/Documentation/perf-kvm.txt +5 -0
+
+
+--event=<value>::
+       event to be analyzed. Possible values: vmexit, mmio, ioport.
+       (default: vmexit)

Ditto

Quoted 12 lines
tools/perf/Documentation/perf-kvm.txt +7 -0
+-k::
+--key=<value>::
+       Sorting key. Possible values: sample (default, sort by samples
+       number), time (sort by average time).
+
+--duration=<value>::
+       Show events other than HLT that take longer than duration usecs.
 
 SEE ALSO
 --------
Signature · 1 line
1.7.10.1
#3 lore raw

[tip:perf/core] perf kvm: Update documentation with live command

In reply to David Ahern
perf kvm: Update documentation with live command
Commit-ID:  9a6d316692d59c4400a66b01db675abac432b4b2
Gitweb:     http://git.kernel.org/tip/9a6d316692d59c4400a66b01db675abac432b4b2
Author:     David Ahern <[email protected]>
AuthorDate: Wed, 7 Aug 2013 21:56:39 -0400
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Mon, 12 Aug 2013 10:31:05 -0300

perf kvm: Update documentation with live command

Update perf-kvm documentation with new live subcommand. Add -p/--pid option for perf-kvm-stat-report as well.

---
 tools/perf/Documentation/perf-kvm.txt | 46 +++++++++++++++++++++++++++++++++--
 1 file changed, 44 insertions(+), 2 deletions(-)
tools/perf/Documentation/perf-kvm.txt +44 -2
index 326f2cb..ac84db2 100644
@@ -13,6 +13,7 @@ SYNOPSIS
 	{top|record|report|diff|buildid-list}
 'perf kvm' [--host] [--guest] [--guestkallsyms=<path> --guestmodules=<path>
 	| --guestvmlinux=<path>] {top|record|report|diff|buildid-list|stat}
+'perf kvm stat [record|report|live] [<options>]
 
 DESCRIPTION
 -----------
@@ -50,6 +51,10 @@ There are a couple of variants of perf kvm:
   'perf kvm stat report' reports statistical data which includes events
   handled time, samples, and so on.
 
+  'perf kvm stat live' reports statistical data in a live mode (similar to
+  record + report but with statistical data updated live at a given display
+  rate).
+
 OPTIONS
 -------
 -i::
@@ -85,13 +90,50 @@ STAT REPORT OPTIONS
 --vcpu=<value>::
        analyze events which occures on this vcpu. (default: all vcpus)
 
---events=<value>::
-       events to be analyzed. Possible values: vmexit, mmio, ioport.
+--event=<value>::
+       event to be analyzed. Possible values: vmexit, mmio, ioport.
        (default: vmexit)
 -k::
 --key=<value>::
        Sorting key. Possible values: sample (default, sort by samples
        number), time (sort by average time).
+-p::
+--pid=::
+    Analyze events only for given process ID(s) (comma separated list).
+
+STAT LIVE OPTIONS
+-----------------
+-d::
+--display::
+        Time in seconds between display updates
+
+-m::
+--mmap-pages=::
+    Number of mmap data pages. Must be a power of two.
+
+-a::
+--all-cpus::
+        System-wide collection from all CPUs.
+
+-p::
+--pid=::
+    Analyze events only for given process ID(s) (comma separated list).
+
+--vcpu=<value>::
+       analyze events which occures on this vcpu. (default: all vcpus)
+
+
+--event=<value>::
+       event to be analyzed. Possible values: vmexit, mmio, ioport.
+       (default: vmexit)
+
+-k::
+--key=<value>::
+       Sorting key. Possible values: sample (default, sort by samples
+       number), time (sort by average time).
+
+--duration=<value>::
+       Show events other than HLT that take longer than duration usecs.
 
 SEE ALSO
 --------
#4 lore raw
In reply to David Ahern

Em Wed, Aug 07, 2013 at 09:56:38PM -0400, David Ahern escreveu:

Quoted 5 lines

This is useful to spot high latency blips. It is normal for HLT reasons to have long exit times, so strip those from the duration check.

v2: changed threshold to duration per acme's request

Thanks, applied.

#5 lore raw

[tip:perf/core] perf kvm: Option to print events that exceed a duration

In reply to David Ahern
perf kvm: Option to print events that exceed a duration
Commit-ID:  70f7b4a7f3f9a46807b644aa0fcfa7daa0d553e4
Gitweb:     http://git.kernel.org/tip/70f7b4a7f3f9a46807b644aa0fcfa7daa0d553e4
Author:     David Ahern <[email protected]>
AuthorDate: Wed, 7 Aug 2013 21:56:38 -0400
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Mon, 12 Aug 2013 10:31:04 -0300

perf kvm: Option to print events that exceed a duration

This is useful to spot high latency blips. It is normal for HLT reasons to have long exit times, so strip those from the duration check.

v2: changed threshold to duration per acme's request

---
 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 2ceec81..fa2f3d7 100644
@@ -106,6 +106,7 @@ struct perf_kvm_stat {
 	u64 total_time;
 	u64 total_count;
 	u64 lost_events;
+	u64 duration;
 
 	const char *pid_str;
 	struct intlist *pid_list;
@@ -473,7 +474,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;
@@ -510,12 +511,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->duration && time_diff > kvm->duration) {
+		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);
 }
 
@@ -562,7 +575,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;
 }
@@ -1429,6 +1442,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(0, "duration", &kvm->duration,
+		    "show events other than HALT that take longer than duration usecs"),
 		OPT_END()
 	};
 	const char * const live_usage[] = {
@@ -1467,6 +1482,8 @@ static int kvm_events_live(struct perf_kvm_stat *kvm,
 			usage_with_options(live_usage, live_options);
 	}
 
+	kvm->duration *= 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)
 {