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

Groups > linux.kernel > #1538591 > unrolled thread

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

Started byNamhyung Kim <namhyung@kernel.org>
First post2016-12-08 15:50 +0100
Last post2016-12-15 16:20 +0100
Articles 10 — 3 participants

Back to article view | Back to linux.kernel

Contents

  [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim <namhyung@kernel.org> - 2016-12-08 15:50 +0100
    [PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data Namhyung Kim <namhyung@kernel.org> - 2016-12-08 16:00 +0100
      [tip:perf/urgent] perf sched timehist: Introduce struct  idle_time_data tip-bot for Namhyung Kim <tipbot@zytor.com> - 2016-12-20 20:30 +0100
    [PATCH v2 3/6] perf sched timehist: Save callchain when entering idle Namhyung Kim <namhyung@kernel.org> - 2016-12-08 16:00 +0100
    Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option  (v2) David Ahern <dsahern@gmail.com> - 2016-12-10 17:40 +0100
      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

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

FromNamhyung Kim <namhyung@kernel.org>
Date2016-12-08 15:50 +0100
Subject[PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
Message-ID<sM8bf-7j1-3@gated-at.bofh.it>
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.

To identify the reasons it only accounts events related to idle task.  Also it
shows callchains when entering to idle and time how long it's in the idle.
Although it's not perfect, it works well to help finding the reasons.

With --idle-hist option, only idle task's runtime is accounted to previous
task (which makes the cpu go to idle).  With --summary(-only) option, you can
see the total idle stat by task or callchains.

 * v2 changes
  - check prev_pid instead of sample->pid for idle task (due to race in exit path)
  - factor idle task initialization  (David)

The example output looks like below:

  Idle-time summary
                            comm  parent  sched-out    idle-time   min-idle    avg-idle    max-idle  stddev  migrations
                                            (count)       (msec)     (msec)      (msec)      (msec)       %
  ---------------------------------------------------------------------------------------------------------------------
                  rcu_preempt[7]       2         95      550.872      0.011       5.798      23.146    7.63       0
                 migration/1[16]       2          1       15.558     15.558      15.558      15.558    0.00       0
                  khugepaged[39]       2          1        3.062      3.062       3.062       3.062    0.00       0
               kworker/0:1H[124]       2          2        4.728      0.611       2.364       4.116   74.12       0
            systemd-journal[167]       1          1        4.510      4.510       4.510       4.510    0.00       0
              kworker/u16:3[558]       2         13       74.737      0.080       5.749      12.960   21.96       0
             irq/34-iwlwifi[628]       2         21      118.403      0.032       5.638      23.990   24.00       0
              kworker/u17:0[673]       2          1        3.523      3.523       3.523       3.523    0.00       0
                dbus-daemon[722]       1          1        6.743      6.743       6.743       6.743    0.00       0
                    ifplugd[741]       1          1       58.826     58.826      58.826      58.826    0.00       0
            wpa_supplicant[1490]       1          1       13.302     13.302      13.302      13.302    0.00       0
               wpa_actiond[1492]       1          2        4.064      0.168       2.032       3.896   91.72       0
                   dockerd[1500]       1          1        0.055      0.055       0.055       0.055    0.00       0
              dockerd[1516/1500]    1500          1        5.732      5.732       5.732       5.732    0.00       0
              dockerd[1571/1500]    1500          1        0.020      0.020       0.020       0.020    0.00       0
  ...
  
  Idle stats:
      CPU  0 idle for    902.195  msec
      CPU  1 idle for    899.932  msec
      CPU  2 idle for    941.218  msec
      CPU  3 idle for    822.453  msec
  
  Idle stats by callchain:
    CPU  0:   902.195  msec
    Idle time (msec)     Count  Callchains
    ----------------  --------  --------------------------------------------------
             370.589        69  futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- entry_SYSCALL_64_fastpath
             178.799        17  worker_thread <- kthread <- ret_from_fork
             128.352        17  schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
             125.111        19  schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_select <- core_sys_select
              71.599        50  schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
              23.146         1  rcu_gp_kthread <- kthread <- ret_from_fork
               4.510         1  schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- do_syscall_64
               0.085         1  schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- do_restart_poll
  ...


The code is available at 'perf/timehist-idle-v2' branch in my tree:

  git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git 

Any comments are welcome!

Thanks,
Namhyung


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(-)

-- 
2.10.1

[toc] | [next] | [standalone]

#1538594 — [PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data

FromNamhyung Kim <namhyung@kernel.org>
Date2016-12-08 16:00 +0100
Subject[PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data
Message-ID<sM8kW-7mt-7@gated-at.bofh.it>
In reply to#1538591
The struct idle_time_data is to keep idle stats with callchains entering
to the idle task.  The normal thread_runtime calculation is done
transparently since it extends the struct thread_runtime.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-sched.c | 37 +++++++++++++++++++++++++++++++++----
 1 file changed, 33 insertions(+), 4 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 46aa4705f321..6f0687dd392d 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -230,6 +230,15 @@ struct evsel_runtime {
 	u32 ncpu;       /* highest cpu slot allocated */
 };
 
+/* per cpu idle time data */
+struct idle_thread_runtime {
+	struct thread_runtime tr;
+	struct thread *last_thread;
+	struct rb_root sorted_root;
+	struct callchain_root callchain;
+	struct callchain_cursor cursor;
+};
+
 /* track idle times per cpu */
 static struct thread **idle_threads;
 static int idle_max_cpu;
@@ -1997,13 +2006,31 @@ static void save_task_callchain(struct perf_sched *sched,
 	}
 }
 
+static int init_idle_thread(struct thread *thread)
+{
+	struct idle_thread_runtime *itr;
+
+	thread__set_comm(thread, idle_comm, 0);
+
+	itr = zalloc(sizeof(*itr));
+	if (itr == NULL)
+		return -ENOMEM;
+
+	init_stats(&itr->tr.run_stats);
+	callchain_init(&itr->callchain);
+	callchain_cursor_reset(&itr->cursor);
+	thread__set_priv(thread, itr);
+
+	return 0;
+}
+
 /*
  * Track idle stats per cpu by maintaining a local thread
  * struct for the idle task on each cpu.
  */
 static int init_idle_threads(int ncpu)
 {
-	int i;
+	int i, ret;
 
 	idle_threads = zalloc(ncpu * sizeof(struct thread *));
 	if (!idle_threads)
@@ -2017,7 +2044,9 @@ static int init_idle_threads(int ncpu)
 		if (idle_threads[i] == NULL)
 			return -ENOMEM;
 
-		thread__set_comm(idle_threads[i], idle_comm, 0);
+		ret = init_idle_thread(idle_threads[i]);
+		if (ret < 0)
+			return ret;
 	}
 
 	return 0;
@@ -2064,8 +2093,8 @@ static struct thread *get_idle_thread(int cpu)
 		idle_threads[cpu] = thread__new(0, 0);
 
 		if (idle_threads[cpu]) {
-			idle_threads[cpu]->tid = 0;
-			thread__set_comm(idle_threads[cpu], idle_comm, 0);
+			if (init_idle_thread(idle_threads[cpu]) < 0)
+				return NULL;
 		}
 	}
 
-- 
2.10.1

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

#1545409 — [tip:perf/urgent] perf sched timehist: Introduce struct idle_time_data

Fromtip-bot for Namhyung Kim <tipbot@zytor.com>
Date2016-12-20 20:30 +0100
Subject[tip:perf/urgent] perf sched timehist: Introduce struct idle_time_data
Message-ID<sQygT-1i9-27@gated-at.bofh.it>
In reply to#1538594
Commit-ID:  3bc2fa9cb829ccf6527e7117d9af769d93ee6d39
Gitweb:     http://git.kernel.org/tip/3bc2fa9cb829ccf6527e7117d9af769d93ee6d39
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Thu, 8 Dec 2016 23:47:51 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 15 Dec 2016 16:25:44 -0300

perf sched timehist: Introduce struct idle_time_data

The struct idle_time_data is to keep idle stats with callchains entering
to the idle task.  The normal thread_runtime calculation is done
transparently since it extends the struct thread_runtime.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: David Ahern <dsahern@gmail.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Minchan Kim <minchan@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20161208144755.16673-3-namhyung@kernel.org
[ Align struct field names ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 37 +++++++++++++++++++++++++++++++++----
 1 file changed, 33 insertions(+), 4 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 966eddc..e108b0f 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -230,6 +230,15 @@ struct evsel_runtime {
 	u32 ncpu;       /* highest cpu slot allocated */
 };
 
+/* per cpu idle time data */
+struct idle_thread_runtime {
+	struct thread_runtime	tr;
+	struct thread		*last_thread;
+	struct rb_root		sorted_root;
+	struct callchain_root	callchain;
+	struct callchain_cursor	cursor;
+};
+
 /* track idle times per cpu */
 static struct thread **idle_threads;
 static int idle_max_cpu;
@@ -1997,13 +2006,31 @@ static void save_task_callchain(struct perf_sched *sched,
 	}
 }
 
+static int init_idle_thread(struct thread *thread)
+{
+	struct idle_thread_runtime *itr;
+
+	thread__set_comm(thread, idle_comm, 0);
+
+	itr = zalloc(sizeof(*itr));
+	if (itr == NULL)
+		return -ENOMEM;
+
+	init_stats(&itr->tr.run_stats);
+	callchain_init(&itr->callchain);
+	callchain_cursor_reset(&itr->cursor);
+	thread__set_priv(thread, itr);
+
+	return 0;
+}
+
 /*
  * Track idle stats per cpu by maintaining a local thread
  * struct for the idle task on each cpu.
  */
 static int init_idle_threads(int ncpu)
 {
-	int i;
+	int i, ret;
 
 	idle_threads = zalloc(ncpu * sizeof(struct thread *));
 	if (!idle_threads)
@@ -2017,7 +2044,9 @@ static int init_idle_threads(int ncpu)
 		if (idle_threads[i] == NULL)
 			return -ENOMEM;
 
-		thread__set_comm(idle_threads[i], idle_comm, 0);
+		ret = init_idle_thread(idle_threads[i]);
+		if (ret < 0)
+			return ret;
 	}
 
 	return 0;
@@ -2064,8 +2093,8 @@ static struct thread *get_idle_thread(int cpu)
 		idle_threads[cpu] = thread__new(0, 0);
 
 		if (idle_threads[cpu]) {
-			idle_threads[cpu]->tid = 0;
-			thread__set_comm(idle_threads[cpu], idle_comm, 0);
+			if (init_idle_thread(idle_threads[cpu]) < 0)
+				return NULL;
 		}
 	}

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

#1538598 — [PATCH v2 3/6] perf sched timehist: Save callchain when entering idle

FromNamhyung Kim <namhyung@kernel.org>
Date2016-12-08 16:00 +0100
Subject[PATCH v2 3/6] perf sched timehist: Save callchain when entering idle
Message-ID<sM8kW-7mt-31@gated-at.bofh.it>
In reply to#1538591
In order to investigate reason of idle, it needs to keep the callchains
when entering to idle.  This can be identified sched_switch event having
next_pid as 0.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-sched.c | 29 +++++++++++++++++++++++++++++
 1 file changed, 29 insertions(+)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 6f0687dd392d..4c5c58ce8958 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -200,6 +200,7 @@ struct perf_sched {
 	/* options for timehist command */
 	bool		summary;
 	bool		summary_only;
+	bool		idle_hist;
 	bool		show_callchain;
 	unsigned int	max_stack;
 	bool		show_cpu_visual;
@@ -2101,6 +2102,29 @@ static struct thread *get_idle_thread(int cpu)
 	return idle_threads[cpu];
 }
 
+static void save_idle_callchain(struct thread *thread,
+				struct perf_sample *sample)
+{
+	struct thread *idle;
+	struct idle_thread_runtime *itr;
+
+	if (!symbol_conf.use_callchain || sample->callchain == NULL)
+		return;
+
+	idle = get_idle_thread(sample->cpu);
+	if (idle == NULL) {
+		pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
+		return;
+	}
+
+	itr = thread__priv(idle);
+	if (itr == NULL)
+		return;
+
+	itr->last_thread = thread;
+	callchain_cursor__copy(&itr->cursor, &callchain_cursor);
+}
+
 /*
  * handle runtime stats saved per thread
  */
@@ -2154,6 +2178,11 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 		}
 
 		save_task_callchain(sched, sample, evsel, machine);
+		if (sched->idle_hist) {
+			/* copy task callchain when entering to idle */
+			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
+				save_idle_callchain(thread, sample);
+		}
 	}
 
 	return thread;
-- 
2.10.1

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

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

FromDavid Ahern <dsahern@gmail.com>
Date2016-12-10 17:40 +0100
SubjectRe: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
Message-ID<sMSQO-4zr-11@gated-at.bofh.it>
In reply to#1538591
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>

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.

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

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

FromNamhyung Kim <namhyung@kernel.org>
Date2016-12-12 18:30 +0100
SubjectRe: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
Message-ID<sNCAh-796-9@gated-at.bofh.it>
In reply to#1539858
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] | [prev] | [next] | [standalone]

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

FromDavid Ahern <dsahern@gmail.com>
Date2016-12-12 18:40 +0100
SubjectRe: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
Message-ID<sNCJX-7co-7@gated-at.bofh.it>
In reply to#1540473
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 — Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)

FromNamhyung Kim <namhyung@kernel.org>
Date2016-12-13 09:10 +0100
SubjectRe: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
Message-ID<sNQjU-7cA-39@gated-at.bofh.it>
In reply to#1540479
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 — Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)

FromDavid Ahern <dsahern@gmail.com>
Date2016-12-14 22:40 +0100
SubjectRe: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
Message-ID<sOprj-4Yt-5@gated-at.bofh.it>
In reply to#1540890
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 — Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)

FromNamhyung Kim <namhyung@kernel.org>
Date2016-12-15 16:20 +0100
SubjectRe: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
Message-ID<sOFZ7-7nZ-23@gated-at.bofh.it>
In reply to#1542216
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