From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753509AbcLMIGS (ORCPT ); Tue, 13 Dec 2016 03:06:18 -0500 Received: from mail-pg0-f68.google.com ([74.125.83.68]:34406 "EHLO mail-pg0-f68.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751985AbcLMIGR (ORCPT ); Tue, 13 Dec 2016 03:06:17 -0500 Date: Tue, 13 Dec 2016 17:05:01 +0900 From: Namhyung Kim To: David Ahern Cc: Arnaldo Carvalho de Melo , Ingo Molnar , Peter Zijlstra , Jiri Olsa , LKML , Andi Kleen , Minchan Kim Subject: Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Message-ID: <20161213080501.GA10539@danjae.aot.lge.com> References: <20161208144755.16673-1-namhyung@kernel.org> <00499939-48a7-217d-8127-47763abf5fbd@gmail.com> <20161212172620.GD4142@danjae.aot.lge.com> <4be90f86-ec74-de6a-fb10-03e749d02c3a@gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline In-Reply-To: <4be90f86-ec74-de6a-fb10-03e749d02c3a@gmail.com> User-Agent: Mutt/1.7.2 (2016-11-26) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.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 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 Signed-off-by: Namhyung Kim --- 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