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

[Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>]

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

Yes, it is a good idea.

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

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

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