Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1540473 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option  (v2) Namhyung Kim <namhyung@kernel.org> - 2016-12-12 18:30 +0100
    Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option  (v2) David Ahern <dsahern@gmail.com> - 2016-12-12 18:40 +0100
      Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option  (v2) Namhyung Kim <namhyung@kernel.org> - 2016-12-13 09:10 +0100
        Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option  (v2) David Ahern <dsahern@gmail.com> - 2016-12-14 22:40 +0100
          Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option  (v2) Namhyung Kim <namhyung@kernel.org> - 2016-12-15 16:20 +0100

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

Hi David,

On Sat, Dec 10, 2016 at 09:32:54AM -0700, David Ahern wrote:
> On 12/8/16 7:47 AM, Namhyung Kim wrote:
> > Hi,
> > 
> > This patchset implements the idle hist feature which analyze reason of system
> > idle.  Sometimes I need to investigate what makes CPUs to go idle even though
> > I have jobs to do.  It may be due to I/O, waiting on lock or whatever.
> > 
> 
> ...
> 
> > Namhyung Kim (6):
> >   perf sched timehist: Split is_idle_sample()
> >   perf sched timehist: Introduce struct idle_time_data
> >   perf sched timehist: Save callchain when entering idle
> >   perf sched timehist: Skip non-idle events when necessary
> >   perf sched timehist: Add -I/--idle-hist option
> >   perf sched timehist: Show callchains for idle stat
> > 
> >  tools/perf/Documentation/perf-sched.txt |   4 +
> >  tools/perf/builtin-sched.c              | 252 +++++++++++++++++++++++++++-----
> >  2 files changed, 222 insertions(+), 34 deletions(-)
> > 
> 
> LGTM
> 
> Acked-by: David Ahern <dsahern@gmail.com>

Thanks!

> 
> Suggested improvement: Add the length of the time window. ie., data collected
> (or analyzed over if --time is used) for N.M seconds. Puts the amount of idle
> time into perspective.

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?

Thanks,
Namhyung

[toc] | [next] | [standalone]

#1540479

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.

[toc] | [prev] | [next] | [standalone]

#1540890

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

[toc] | [prev] | [next] | [standalone]

#1542216

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;
> 

[toc] | [prev] | [next] | [standalone]

#1542814

On Wed, Dec 14, 2016 at 02:33:45PM -0700, David Ahern wrote:
> 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.

Right, I'll keep the actual sampling window within the ptime then.

Thanks,
Namhyung

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

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web