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

[Namhyung Kim <namhyung@kernel.org>]

On Mon, Dec 12, 2016 at 10:37:30AM -0700, David Ahern wrote:
> On 12/12/16 10:26 AM, Namhyung Kim wrote:
> > Do you mean adding an elapsed time so that it can see the cpu utilization (or
> > something similar)?  Then we need to expose the elapsed time during record or
> > maybe just use time difference between first and last sample?
> 
> I was thinking tstart = time of first sample analyzed, tend = time of last
> sample analyzed, dt = tend - tstart.
> 
> If the analysis window (dt) is 5 seconds and each cpu is idle for 0.1 seconds
> of that 5 second window then the system is under high load.

Hmm... something like this?



>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;
 
 	if (timehist_check_attr(sched, evlist) != 0)
 		goto out;
-- 
2.10.2