perf kvm: option to print events that exceed a duration -v2
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
--- 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
@@ -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
@@ -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
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.
--- tools/perf/Documentation/perf-kvm.txt | 46 +++++++++++++++++++++++++++++++-- 1 file changed, 44 insertions(+), 2 deletions(-)
tools/perf/Documentation/perf-kvm.txt +44 -2
@@ -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
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
Signed-off-by David Ahern <[email protected]>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@@ -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
-0number), 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
tip-bot for David Ahern
merge bot[tip:perf/core] perf kvm: Update documentation with live command
In reply to David Ahernperf 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
@@ -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 --------
Arnaldo Carvalho de Melo
AppliedEm 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.
tip-bot for David Ahern
merge bot[tip:perf/core] perf kvm: Option to print events that exceed a duration
In reply to David Ahernperf 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
@@ -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
@@ -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 ) {