Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)

[David Ahern <dsahern@gmail.com>]

On 12/13/16 1:05 AM, Namhyung Kim wrote:
> Hmm... something like this?

yes. 1 comment though ...

> 
> 
> 
> From 5a1702bd15d78b0fe0c31d2d48ec8afa41fbf10c Mon Sep 17 00:00:00 2001
> From: Namhyung Kim <namhyung@kernel.org>
> Date: Tue, 13 Dec 2016 15:05:14 +0900
> Subject: [PATCH] perf sched timehist: Show total scheduling time
> 
> Show length of analyzed sample time and rate of idle task running.
> This also takes care of time range given by --time option.
> 
>   $ perf sched timehist -sI | tail
>   Samples do not have callchains.
>   Idle stats:
>       CPU  0 idle for    930.316  msec  ( 92.93%)
>       CPU  1 idle for    963.614  msec  ( 96.25%)
>       CPU  2 idle for    885.482  msec  ( 88.45%)
>       CPU  3 idle for    938.635  msec  ( 93.76%)
> 
>       Total number of unique tasks: 118
>   Total number of context switches: 2337
>              Total run time (msec): 3718.048
>       Total scheduling time (msec): 1001.131
> 
> Suggested-by: David Ahern <dsahern@gmail.com>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/builtin-sched.c | 19 ++++++++++++++++---
>  1 file changed, 16 insertions(+), 3 deletions(-)
> 
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 64a0959bccd7..9c0b3016e85a 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -209,6 +209,7 @@ struct perf_sched {
>  	u64		skipped_samples;
>  	const char	*time_str;
>  	struct perf_time_interval ptime;
> +	struct perf_time_interval hist_time;
>  };
>  
>  /* per thread run time data */
> @@ -2624,6 +2625,7 @@ static void timehist_print_summary(struct perf_sched *sched,
>  	struct thread *t;
>  	struct thread_runtime *r;
>  	int i;
> +	u64 hist_time = sched->hist_time.end - sched->hist_time.start;
>  
>  	memset(&totals, 0, sizeof(totals));
>  
> @@ -2668,7 +2670,7 @@ static void timehist_print_summary(struct perf_sched *sched,
>  			totals.sched_count += r->run_stats.n;
>  			printf("    CPU %2d idle for ", i);
>  			print_sched_time(r->total_run_time, 6);
> -			printf(" msec\n");
> +			printf(" msec  (%6.2f%%)\n", 100.0 * r->total_run_time / hist_time);
>  		} else
>  			printf("    CPU %2d idle entire time window\n", i);
>  	}
> @@ -2704,12 +2706,16 @@ static void timehist_print_summary(struct perf_sched *sched,
>  
>  	printf("\n"
>  	       "    Total number of unique tasks: %" PRIu64 "\n"
> -	       "Total number of context switches: %" PRIu64 "\n"
> -	       "           Total run time (msec): ",
> +	       "Total number of context switches: %" PRIu64 "\n",
>  	       totals.task_count, totals.sched_count);
>  
> +	printf("           Total run time (msec): ");
>  	print_sched_time(totals.total_run_time, 2);
>  	printf("\n");
> +
> +	printf("    Total scheduling time (msec): ");
> +	print_sched_time(hist_time, 2);
> +	printf("\n");
>  }
>  
>  typedef int (*sched_handler)(struct perf_tool *tool,
> @@ -2731,6 +2737,12 @@ static int perf_timehist__process_sample(struct perf_tool *tool,
>  	if (this_cpu > sched->max_cpu)
>  		sched->max_cpu = this_cpu;
>  
> +	if (sched->hist_time.start == 0)
> +		sched->hist_time.start = sample->time;
> +	/* do not update end time if user gave a ptime */
> +	if (sched->ptime.end == 0)
> +		sched->hist_time.end = sample->time;
> +
>  	if (evsel->handler != NULL) {
>  		sched_handler f = evsel->handler;
>  
> @@ -2814,6 +2826,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
>  		pr_err("Invalid time string\n");
>  		return -EINVAL;
>  	}
> +	sched->hist_time = sched->ptime;

The time given by the user does not necessarily correlate with a time in the file. eg., start time could be way before the file starts or end time way after. 

>  
>  	if (timehist_check_attr(sched, evlist) != 0)
>  		goto out;
>