diff options
author | David Ahern <dsahern@gmail.com> | 2013-08-07 21:56:38 -0400 |
---|---|---|
committer | Arnaldo Carvalho de Melo <acme@redhat.com> | 2013-08-12 09:31:04 -0400 |
commit | 70f7b4a7f3f9a46807b644aa0fcfa7daa0d553e4 (patch) | |
tree | beaedc789a7aef3c98b1625ec9dc02eeec973c08 /tools/perf/builtin-kvm.c | |
parent | 0a3d23a2568ed5e73bd4fb532dc672fa9f03b1f1 (diff) |
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
Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Runzhen Wang <runzhen@linux.vnet.ibm.com>
Cc: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
Link: http://lkml.kernel.org/r/1375926999-75129-1-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Diffstat (limited to 'tools/perf/builtin-kvm.c')
-rw-r--r-- | tools/perf/builtin-kvm.c | 25 |
1 files changed, 21 insertions, 4 deletions
diff --git a/tools/perf/builtin-kvm.c b/tools/perf/builtin-kvm.c index 2ceec817a2fb..fa2f3d79886a 100644 --- a/tools/perf/builtin-kvm.c +++ b/tools/perf/builtin-kvm.c | |||
@@ -106,6 +106,7 @@ struct perf_kvm_stat { | |||
106 | u64 total_time; | 106 | u64 total_time; |
107 | u64 total_count; | 107 | u64 total_count; |
108 | u64 lost_events; | 108 | u64 lost_events; |
109 | u64 duration; | ||
109 | 110 | ||
110 | const char *pid_str; | 111 | const char *pid_str; |
111 | struct intlist *pid_list; | 112 | struct intlist *pid_list; |
@@ -473,7 +474,7 @@ static bool update_kvm_event(struct kvm_event *event, int vcpu_id, | |||
473 | static bool handle_end_event(struct perf_kvm_stat *kvm, | 474 | static bool handle_end_event(struct perf_kvm_stat *kvm, |
474 | struct vcpu_event_record *vcpu_record, | 475 | struct vcpu_event_record *vcpu_record, |
475 | struct event_key *key, | 476 | struct event_key *key, |
476 | u64 timestamp) | 477 | struct perf_sample *sample) |
477 | { | 478 | { |
478 | struct kvm_event *event; | 479 | struct kvm_event *event; |
479 | u64 time_begin, time_diff; | 480 | u64 time_begin, time_diff; |
@@ -510,12 +511,24 @@ static bool handle_end_event(struct perf_kvm_stat *kvm, | |||
510 | vcpu_record->start_time = 0; | 511 | vcpu_record->start_time = 0; |
511 | 512 | ||
512 | /* seems to happen once in a while during live mode */ | 513 | /* seems to happen once in a while during live mode */ |
513 | if (timestamp < time_begin) { | 514 | if (sample->time < time_begin) { |
514 | pr_debug("End time before begin time; skipping event.\n"); | 515 | pr_debug("End time before begin time; skipping event.\n"); |
515 | return true; | 516 | return true; |
516 | } | 517 | } |
517 | 518 | ||
518 | time_diff = timestamp - time_begin; | 519 | time_diff = sample->time - time_begin; |
520 | |||
521 | if (kvm->duration && time_diff > kvm->duration) { | ||
522 | char decode[32]; | ||
523 | |||
524 | kvm->events_ops->decode_key(kvm, &event->key, decode); | ||
525 | if (strcmp(decode, "HLT")) { | ||
526 | pr_info("%" PRIu64 " VM %d, vcpu %d: %s event took %" PRIu64 "usec\n", | ||
527 | sample->time, sample->pid, vcpu_record->vcpu_id, | ||
528 | decode, time_diff/1000); | ||
529 | } | ||
530 | } | ||
531 | |||
519 | return update_kvm_event(event, vcpu, time_diff); | 532 | return update_kvm_event(event, vcpu, time_diff); |
520 | } | 533 | } |
521 | 534 | ||
@@ -562,7 +575,7 @@ static bool handle_kvm_event(struct perf_kvm_stat *kvm, | |||
562 | return handle_begin_event(kvm, vcpu_record, &key, sample->time); | 575 | return handle_begin_event(kvm, vcpu_record, &key, sample->time); |
563 | 576 | ||
564 | if (kvm->events_ops->is_end_event(evsel, sample, &key)) | 577 | if (kvm->events_ops->is_end_event(evsel, sample, &key)) |
565 | return handle_end_event(kvm, vcpu_record, &key, sample->time); | 578 | return handle_end_event(kvm, vcpu_record, &key, sample); |
566 | 579 | ||
567 | return true; | 580 | return true; |
568 | } | 581 | } |
@@ -1429,6 +1442,8 @@ static int kvm_events_live(struct perf_kvm_stat *kvm, | |||
1429 | OPT_STRING('k', "key", &kvm->sort_key, "sort-key", | 1442 | OPT_STRING('k', "key", &kvm->sort_key, "sort-key", |
1430 | "key for sorting: sample(sort by samples number)" | 1443 | "key for sorting: sample(sort by samples number)" |
1431 | " time (sort by avg time)"), | 1444 | " time (sort by avg time)"), |
1445 | OPT_U64(0, "duration", &kvm->duration, | ||
1446 | "show events other than HALT that take longer than duration usecs"), | ||
1432 | OPT_END() | 1447 | OPT_END() |
1433 | }; | 1448 | }; |
1434 | const char * const live_usage[] = { | 1449 | const char * const live_usage[] = { |
@@ -1467,6 +1482,8 @@ static int kvm_events_live(struct perf_kvm_stat *kvm, | |||
1467 | usage_with_options(live_usage, live_options); | 1482 | usage_with_options(live_usage, live_options); |
1468 | } | 1483 | } |
1469 | 1484 | ||
1485 | kvm->duration *= NSEC_PER_USEC; /* convert usec to nsec */ | ||
1486 | |||
1470 | /* | 1487 | /* |
1471 | * target related setups | 1488 | * target related setups |
1472 | */ | 1489 | */ |