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 <namhy...@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 <dsah...@gmail.com>
Signed-off-by: Namhyung Kim <namhy...@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
