linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
@ 2016-12-08 14:47 Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 1/6] perf sched timehist: Split is_idle_sample() Namhyung Kim
                   ` (6 more replies)
  0 siblings, 7 replies; 28+ messages in thread
From: Namhyung Kim @ 2016-12-08 14:47 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

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

^ permalink raw reply	[flat|nested] 28+ messages in thread

* [PATCH v2 1/6] perf sched timehist: Split is_idle_sample()
  2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
@ 2016-12-08 14:47 ` Namhyung Kim
  2016-12-20 19:19   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data Namhyung Kim
                   ` (5 subsequent siblings)
  6 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-08 14:47 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

The is_idle_sample() function actually does more than determining
whether sample come from idle task.  Split the callchain part into
save_task_callchain() to make it clearer.

Also checking prev_pid from trace data looks preferred than just
checking sample->pid since it's possible, although rare, to have invalid
0 pid/tid on scheduling an exiting task.

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

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1a3f1be93372..46aa4705f321 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -1939,39 +1939,40 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 	r->total_run_time += r->dt_run;
 }
 
-static bool is_idle_sample(struct perf_sched *sched,
-			   struct perf_sample *sample,
-			   struct perf_evsel *evsel,
-			   struct machine *machine)
+static bool is_idle_sample(struct perf_sample *sample,
+			   struct perf_evsel *evsel)
 {
-	struct thread *thread;
-	struct callchain_cursor *cursor = &callchain_cursor;
-
 	/* pid 0 == swapper == idle task */
-	if (sample->pid == 0)
-		return true;
+	if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0)
+		return (perf_evsel__intval(evsel, sample, "prev_pid") == 0);
 
-	if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0) {
-		if (perf_evsel__intval(evsel, sample, "prev_pid") == 0)
-			return true;
-	}
+	return (sample->pid == 0);
+}
+
+static void save_task_callchain(struct perf_sched *sched,
+				struct perf_sample *sample,
+				struct perf_evsel *evsel,
+				struct machine *machine)
+{
+	struct callchain_cursor *cursor = &callchain_cursor;
+	struct thread *thread;
 
 	/* want main thread for process - has maps */
 	thread = machine__findnew_thread(machine, sample->pid, sample->pid);
 	if (thread == NULL) {
 		pr_debug("Failed to get thread for pid %d.\n", sample->pid);
-		return false;
+		return;
 	}
 
 	if (!symbol_conf.use_callchain || sample->callchain == NULL)
-		return false;
+		return;
 
 	if (thread__resolve_callchain(thread, cursor, evsel, sample,
 				      NULL, NULL, sched->max_stack + 2) != 0) {
 		if (verbose)
 			error("Failed to resolve callchain. Skipping\n");
 
-		return false;
+		return;
 	}
 
 	callchain_cursor_commit(cursor);
@@ -1994,8 +1995,6 @@ static bool is_idle_sample(struct perf_sched *sched,
 
 		callchain_cursor_advance(cursor);
 	}
-
-	return false;
 }
 
 /*
@@ -2111,7 +2110,7 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 {
 	struct thread *thread;
 
-	if (is_idle_sample(sched, sample, evsel, machine)) {
+	if (is_idle_sample(sample, evsel)) {
 		thread = get_idle_thread(sample->cpu);
 		if (thread == NULL)
 			pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
@@ -2124,6 +2123,8 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 			pr_debug("Failed to get thread for tid %d. skipping sample.\n",
 				 sample->tid);
 		}
+
+		save_task_callchain(sched, sample, evsel, machine);
 	}
 
 	return thread;
-- 
2.10.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data
  2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 1/6] perf sched timehist: Split is_idle_sample() Namhyung Kim
@ 2016-12-08 14:47 ` Namhyung Kim
  2016-12-20 19:20   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 3/6] perf sched timehist: Save callchain when entering idle Namhyung Kim
                   ` (4 subsequent siblings)
  6 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-08 14:47 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

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

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v2 3/6] perf sched timehist: Save callchain when entering idle
  2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 1/6] perf sched timehist: Split is_idle_sample() Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data Namhyung Kim
@ 2016-12-08 14:47 ` Namhyung Kim
  2016-12-13  8:06   ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 4/6] perf sched timehist: Skip non-idle events when necessary Namhyung Kim
                   ` (3 subsequent siblings)
  6 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-08 14:47 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

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

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v2 4/6] perf sched timehist: Skip non-idle events when necessary
  2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
                   ` (2 preceding siblings ...)
  2016-12-08 14:47 ` [PATCH v2 3/6] perf sched timehist: Save callchain when entering idle Namhyung Kim
@ 2016-12-08 14:47 ` Namhyung Kim
  2016-12-20 19:21   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 5/6] perf sched timehist: Add -I/--idle-hist option Namhyung Kim
                   ` (2 subsequent siblings)
  6 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-08 14:47 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

Sometimes it only focuses on idle-related events like upcoming idle-hist
feature.  In this case we don't want to see other event to reduce noise.

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

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 4c5c58ce8958..da3ff3253741 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2189,7 +2189,9 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 }
 
 static bool timehist_skip_sample(struct perf_sched *sched,
-				 struct thread *thread)
+				 struct thread *thread,
+				 struct perf_evsel *evsel,
+				 struct perf_sample *sample)
 {
 	bool rc = false;
 
@@ -2198,10 +2200,19 @@ static bool timehist_skip_sample(struct perf_sched *sched,
 		sched->skipped_samples++;
 	}
 
+	if (sched->idle_hist) {
+		if (strcmp(perf_evsel__name(evsel), "sched:sched_switch"))
+			rc = true;
+		else if (perf_evsel__intval(evsel, sample, "prev_pid") != 0 &&
+			 perf_evsel__intval(evsel, sample, "next_pid") != 0)
+			rc = true;
+	}
+
 	return rc;
 }
 
 static void timehist_print_wakeup_event(struct perf_sched *sched,
+					struct perf_evsel *evsel,
 					struct perf_sample *sample,
 					struct machine *machine,
 					struct thread *awakened)
@@ -2214,8 +2225,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
 		return;
 
 	/* show wakeup unless both awakee and awaker are filtered */
-	if (timehist_skip_sample(sched, thread) &&
-	    timehist_skip_sample(sched, awakened)) {
+	if (timehist_skip_sample(sched, thread, evsel, sample) &&
+	    timehist_skip_sample(sched, awakened, evsel, sample)) {
 		return;
 	}
 
@@ -2260,7 +2271,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,
 	/* show wakeups if requested */
 	if (sched->show_wakeups &&
 	    !perf_time__skip_sample(&sched->ptime, sample->time))
-		timehist_print_wakeup_event(sched, sample, machine, thread);
+		timehist_print_wakeup_event(sched, evsel, sample, machine, thread);
 
 	return 0;
 }
@@ -2287,8 +2298,8 @@ static void timehist_print_migration_event(struct perf_sched *sched,
 	if (thread == NULL)
 		return;
 
-	if (timehist_skip_sample(sched, thread) &&
-	    timehist_skip_sample(sched, migrated)) {
+	if (timehist_skip_sample(sched, thread, evsel, sample) &&
+	    timehist_skip_sample(sched, migrated, evsel, sample)) {
 		return;
 	}
 
@@ -2373,7 +2384,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 		goto out;
 	}
 
-	if (timehist_skip_sample(sched, thread))
+	if (timehist_skip_sample(sched, thread, evsel, sample))
 		goto out;
 
 	tr = thread__get_runtime(thread);
-- 
2.10.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v2 5/6] perf sched timehist: Add -I/--idle-hist option
  2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
                   ` (3 preceding siblings ...)
  2016-12-08 14:47 ` [PATCH v2 4/6] perf sched timehist: Skip non-idle events when necessary Namhyung Kim
@ 2016-12-08 14:47 ` Namhyung Kim
  2016-12-08 14:47 ` [PATCH v2 6/6] perf sched timehist: Show callchains for idle stat Namhyung Kim
  2016-12-10 16:32 ` [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) David Ahern
  6 siblings, 0 replies; 28+ messages in thread
From: Namhyung Kim @ 2016-12-08 14:47 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

The --idle-hist option is to analyze system idle state so which process
makes cpu to go idle.  If this option is specified, non-idle events will
be skipped and processes switching to/from idle will be shown.

This option is mostly useful when used with --summary(-only) option.  In
the idle-time summary view, idle time is accounted to previous thread
which is run before idle task.

The example output looks like following:

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

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/Documentation/perf-sched.txt |  4 ++++
 tools/perf/builtin-sched.c              | 38 ++++++++++++++++++++++++++++-----
 2 files changed, 37 insertions(+), 5 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 7775b1eb2bee..76173969ab80 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -132,6 +132,10 @@ OPTIONS for 'perf sched timehist'
 --migrations::
 	Show migration events.
 
+-I::
+--idle-hist::
+	Show idle-related events only.
+
 --time::
 	Only analyze samples within given time window: <start>,<stop>. Times
 	have the format seconds.microseconds. If start is not given (i.e., time
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index da3ff3253741..6dc9e00d6392 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2420,7 +2420,28 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 			t = ptime->end;
 	}
 
-	timehist_update_runtime_stats(tr, t, tprev);
+	if (!sched->idle_hist || thread->tid == 0) {
+		timehist_update_runtime_stats(tr, t, tprev);
+
+		if (sched->idle_hist) {
+			struct idle_thread_runtime *itr = (void *)tr;
+			struct thread_runtime *last_tr;
+
+			BUG_ON(thread->tid != 0);
+
+			if (itr->last_thread == NULL)
+				goto out;
+
+			/* add current idle time as last thread's runtime */
+			last_tr = thread__get_runtime(itr->last_thread);
+			if (last_tr == NULL)
+				goto out;
+
+			timehist_update_runtime_stats(last_tr, t, tprev);
+
+			itr->last_thread = NULL;
+		}
+	}
 
 	if (!sched->summary_only)
 		timehist_print_sample(sched, sample, &al, thread, t);
@@ -2542,9 +2563,15 @@ static void timehist_print_summary(struct perf_sched *sched,
 	if (comm_width < 30)
 		comm_width = 30;
 
-	printf("\nRuntime summary\n");
-	printf("%*s  parent   sched-in  ", comm_width, "comm");
-	printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
+	if (sched->idle_hist) {
+		printf("\nIdle-time summary\n");
+		printf("%*s  parent  sched-out  ", comm_width, "comm");
+		printf("  idle-time   min-idle    avg-idle    max-idle  stddev  migrations\n");
+	} else {
+		printf("\nRuntime summary\n");
+		printf("%*s  parent   sched-in  ", comm_width, "comm");
+		printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
+	}
 	printf("%*s            (count)  ", comm_width, "");
 	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
 	printf("%.117s\n", graph_dotted_line);
@@ -2560,7 +2587,7 @@ static void timehist_print_summary(struct perf_sched *sched,
 		printf("<no terminated tasks>\n");
 
 	/* CPU idle stats not tracked when samples were skipped */
-	if (sched->skipped_samples)
+	if (sched->skipped_samples && !sched->idle_hist)
 		return;
 
 	printf("\nIdle stats:\n");
@@ -3106,6 +3133,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
 	OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
 	OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
+	OPT_BOOLEAN('I', "idle-hist", &sched.idle_hist, "Show idle events only"),
 	OPT_STRING(0, "time", &sched.time_str, "str",
 		   "Time span for analysis (start,stop)"),
 	OPT_PARENT(sched_options)
-- 
2.10.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v2 6/6] perf sched timehist: Show callchains for idle stat
  2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
                   ` (4 preceding siblings ...)
  2016-12-08 14:47 ` [PATCH v2 5/6] perf sched timehist: Add -I/--idle-hist option Namhyung Kim
@ 2016-12-08 14:47 ` Namhyung Kim
  2016-12-20 19:22   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
  2016-12-10 16:32 ` [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) David Ahern
  6 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-08 14:47 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

When --idle-hist option is used with --summary, it now shows idle stats
with callchains like below:

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

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

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 6dc9e00d6392..724134203632 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2438,6 +2438,9 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 				goto out;
 
 			timehist_update_runtime_stats(last_tr, t, tprev);
+			if (itr->cursor.nr)
+				callchain_append(&itr->callchain, &itr->cursor,
+						 t - tprev);
 
 			itr->last_thread = NULL;
 		}
@@ -2548,6 +2551,60 @@ static int show_deadthread_runtime(struct thread *t, void *priv)
 	return __show_thread_runtime(t, priv);
 }
 
+static size_t callchain__fprintf_folded(FILE *fp, struct callchain_node *node)
+{
+	const char *sep = " <- ";
+	struct callchain_list *chain;
+	size_t ret = 0;
+	char bf[1024];
+	bool first;
+
+	if (node == NULL)
+		return 0;
+
+	ret = callchain__fprintf_folded(fp, node->parent);
+	first = (ret == 0);
+
+	list_for_each_entry(chain, &node->val, list) {
+		if (chain->ip >= PERF_CONTEXT_MAX)
+			continue;
+		if (chain->ms.sym && chain->ms.sym->ignore)
+			continue;
+		ret += fprintf(fp, "%s%s", first ? "" : sep,
+			       callchain_list__sym_name(chain, bf, sizeof(bf),
+							false));
+		first = false;
+	}
+
+	return ret;
+}
+
+static size_t timehist_print_idlehist_callchain(struct rb_root *root)
+{
+	size_t ret = 0;
+	FILE *fp = stdout;
+	struct callchain_node *chain;
+	struct rb_node *rb_node = rb_first(root);
+
+	printf("  %16s  %8s  %s\n", "Idle time (msec)", "Count", "Callchains");
+	printf("  %.16s  %.8s  %.50s\n", graph_dotted_line, graph_dotted_line,
+	       graph_dotted_line);
+
+	while (rb_node) {
+		chain = rb_entry(rb_node, struct callchain_node, rb_node);
+		rb_node = rb_next(rb_node);
+
+		ret += fprintf(fp, "  ");
+		print_sched_time(chain->hit, 12);
+		ret += 16;  /* print_sched_time returns 2nd arg + 4 */
+		ret += fprintf(fp, " %8d  ", chain->count);
+		ret += callchain__fprintf_folded(fp, chain);
+		ret += fprintf(fp, "\n");
+	}
+
+	return ret;
+}
+
 static void timehist_print_summary(struct perf_sched *sched,
 				   struct perf_session *session)
 {
@@ -2606,6 +2663,35 @@ static void timehist_print_summary(struct perf_sched *sched,
 			printf("    CPU %2d idle entire time window\n", i);
 	}
 
+	if (sched->idle_hist && symbol_conf.use_callchain) {
+		callchain_param.mode  = CHAIN_FOLDED;
+		callchain_param.value = CCVAL_PERIOD;
+
+		callchain_register_param(&callchain_param);
+
+		printf("\nIdle stats by callchain:\n");
+		for (i = 0; i < idle_max_cpu; ++i) {
+			struct idle_thread_runtime *itr;
+
+			t = idle_threads[i];
+			if (!t)
+				continue;
+
+			itr = thread__priv(t);
+			if (itr == NULL)
+				continue;
+
+			callchain_param.sort(&itr->sorted_root, &itr->callchain,
+					     0, &callchain_param);
+
+			printf("  CPU %2d:", i);
+			print_sched_time(itr->tr.total_run_time, 6);
+			printf(" msec\n");
+			timehist_print_idlehist_callchain(&itr->sorted_root);
+			printf("\n");
+		}
+	}
+
 	printf("\n"
 	       "    Total number of unique tasks: %" PRIu64 "\n"
 	       "Total number of context switches: %" PRIu64 "\n"
-- 
2.10.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
  2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
                   ` (5 preceding siblings ...)
  2016-12-08 14:47 ` [PATCH v2 6/6] perf sched timehist: Show callchains for idle stat Namhyung Kim
@ 2016-12-10 16:32 ` David Ahern
  2016-12-12 17:26   ` Namhyung Kim
  6 siblings, 1 reply; 28+ messages in thread
From: David Ahern @ 2016-12-10 16:32 UTC (permalink / raw)
  To: Namhyung Kim, Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Andi Kleen, Minchan Kim

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.

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
  2016-12-10 16:32 ` [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) David Ahern
@ 2016-12-12 17:26   ` Namhyung Kim
  2016-12-12 17:37     ` David Ahern
  0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-12 17:26 UTC (permalink / raw)
  To: David Ahern
  Cc: Arnaldo Carvalho de Melo, Ingo Molnar, Peter Zijlstra, Jiri Olsa,
	LKML, Andi Kleen, Minchan Kim

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

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
  2016-12-12 17:26   ` Namhyung Kim
@ 2016-12-12 17:37     ` David Ahern
  2016-12-13  8:05       ` Namhyung Kim
  0 siblings, 1 reply; 28+ messages in thread
From: David Ahern @ 2016-12-12 17:37 UTC (permalink / raw)
  To: Namhyung Kim
  Cc: Arnaldo Carvalho de Melo, Ingo Molnar, Peter Zijlstra, Jiri Olsa,
	LKML, Andi Kleen, Minchan Kim

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.

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
  2016-12-12 17:37     ` David Ahern
@ 2016-12-13  8:05       ` Namhyung Kim
  2016-12-14 21:33         ` David Ahern
  0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-13  8:05 UTC (permalink / raw)
  To: David Ahern
  Cc: Arnaldo Carvalho de Melo, Ingo Molnar, Peter Zijlstra, Jiri Olsa,
	LKML, Andi Kleen, Minchan Kim

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

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
@ 2016-12-13  8:06   ` Namhyung Kim
  2016-12-13  8:06     ` [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist Namhyung Kim
                       ` (2 more replies)
  0 siblings, 3 replies; 28+ messages in thread
From: Namhyung Kim @ 2016-12-13  8:06 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

When idle hist is enabled, the itr->last_thread should be set so that
it can find which thread run before idle task.  But it was only set in
the save_idle_callchain().  This makes idle task doesn't show up in
the output when callchain is not recorded.

Before:

  $ perf sched timehist --idle-hist
  Samples do not have callchains.
             time    cpu  task name             wait time  sch delay   run time
                          [tid/pid]                (msec)     (msec)     (msec)
  --------------- ------  --------------------  ---------  ---------  ---------
    197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
    197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
    197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
    197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
    197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.000
    197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.000
    ...

After:

    197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
    197731.753914 [0001]  <idle>                    0.000      0.000      0.079
    197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
    197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
    197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
    197731.754903 [0002]  <idle>                    0.047      0.000      0.567
    197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
    197731.755922 [0002]  <idle>                    0.078      0.000      0.941
    197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
    197731.756625 [0003]  <idle>                    0.123      0.000      2.709
    ...

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

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 0750e938a656..405a91d0515f 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)
 	return idle_threads[cpu];
 }
 
-static void save_idle_callchain(struct thread *thread,
+static void save_idle_callchain(struct idle_thread_runtime *itr,
 				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);
 }
 
@@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 
 		save_task_callchain(sched, sample, evsel, machine);
 		if (sched->idle_hist) {
+			struct thread *idle;
+			struct idle_thread_runtime *itr;
+
+			idle = get_idle_thread(sample->cpu);
+			if (idle == NULL) {
+				pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
+				return NULL;
+			}
+
+			itr = thread__priv(idle);
+			if (itr == NULL)
+				return NULL;
+
+			itr->last_thread = thread;
+
 			/* copy task callchain when entering to idle */
 			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
-				save_idle_callchain(thread, sample);
+				save_idle_callchain(itr, sample);
 		}
 	}
 
-- 
2.10.2

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist
  2016-12-13  8:06   ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Namhyung Kim
@ 2016-12-13  8:06     ` Namhyung Kim
  2016-12-13 10:32       ` Arnaldo Carvalho de Melo
  2016-12-20 19:21       ` [tip:perf/urgent] perf sched timehist: Add -I/--idle-hist option tip-bot for Namhyung Kim
  2016-12-13 10:32     ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Arnaldo Carvalho de Melo
  2016-12-20 19:20     ` [tip:perf/urgent] perf sched timehist: Save callchain when entering idle tip-bot for Namhyung Kim
  2 siblings, 2 replies; 28+ messages in thread
From: Namhyung Kim @ 2016-12-13  8:06 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

When --idle-hist option is used, run/wait time and sched delay value
should be shown for idle task only.  But due to internal accounting, a
last thread has same value of next idle task's and it was shown.

In the below example, firefox after idle task has same run time of
idle task's.

  $ perf sched timehist --idle-hist
  Samples do not have callchains.
             time    cpu  task name             wait time  sch delay   run time
                          [tid/pid]                (msec)     (msec)     (msec)
  --------------- ------  --------------------  ---------  ---------  ---------
    197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
    197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
    197731.754903 [0002]  <idle>                    0.047      0.000      0.567
    197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
    197731.755922 [0002]  <idle>                    0.078      0.000      0.941
    197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
  <SNIP>

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

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 405a91d0515f..64a0959bccd7 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2439,6 +2439,15 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 				goto out;
 
 			timehist_update_runtime_stats(last_tr, t, tprev);
+			/*
+			 * remove delta time of last thread as it's not updated
+			 * and otherwise it will show an invalid value next
+			 * time.  we only care total run time and run stat.
+			 */
+			last_tr->dt_run = 0;
+			last_tr->dt_wait = 0;
+			last_tr->dt_delay = 0;
+
 			if (itr->cursor.nr)
 				callchain_append(&itr->callchain, &itr->cursor,
 						 t - tprev);
-- 
2.10.2

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* Re: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
  2016-12-13  8:06   ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Namhyung Kim
  2016-12-13  8:06     ` [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist Namhyung Kim
@ 2016-12-13 10:32     ` Arnaldo Carvalho de Melo
  2016-12-13 10:49       ` Namhyung Kim
  2016-12-20 19:20     ` [tip:perf/urgent] perf sched timehist: Save callchain when entering idle tip-bot for Namhyung Kim
  2 siblings, 1 reply; 28+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-12-13 10:32 UTC (permalink / raw)
  To: Namhyung Kim
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

Em Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
> When idle hist is enabled, the itr->last_thread should be set so that
> it can find which thread run before idle task.  But it was only set in
> the save_idle_callchain().  This makes idle task doesn't show up in
> the output when callchain is not recorded.

It is important to provide a Fixes: tag so that I can check if the
problem was introduced by some patch still not sent to Ingo, in which
case I could try and merge them, is this the case here?

- Arnaldo 

> Before:
> 
>   $ perf sched timehist --idle-hist
>   Samples do not have callchains.
>              time    cpu  task name             wait time  sch delay   run time
>                           [tid/pid]                (msec)     (msec)     (msec)
>   --------------- ------  --------------------  ---------  ---------  ---------
>     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
>     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
>     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
>     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
>     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.000
>     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.000
>     ...
> 
> After:
> 
>     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
>     197731.753914 [0001]  <idle>                    0.000      0.000      0.079
>     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
>     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
>     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
>     197731.754903 [0002]  <idle>                    0.047      0.000      0.567
>     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
>     197731.755922 [0002]  <idle>                    0.078      0.000      0.941
>     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
>     197731.756625 [0003]  <idle>                    0.123      0.000      2.709
>     ...
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/builtin-sched.c | 33 +++++++++++++++++----------------
>  1 file changed, 17 insertions(+), 16 deletions(-)
> 
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 0750e938a656..405a91d0515f 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)
>  	return idle_threads[cpu];
>  }
>  
> -static void save_idle_callchain(struct thread *thread,
> +static void save_idle_callchain(struct idle_thread_runtime *itr,
>  				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);
>  }
>  
> @@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
>  
>  		save_task_callchain(sched, sample, evsel, machine);
>  		if (sched->idle_hist) {
> +			struct thread *idle;
> +			struct idle_thread_runtime *itr;
> +
> +			idle = get_idle_thread(sample->cpu);
> +			if (idle == NULL) {
> +				pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
> +				return NULL;
> +			}
> +
> +			itr = thread__priv(idle);
> +			if (itr == NULL)
> +				return NULL;
> +
> +			itr->last_thread = thread;
> +
>  			/* copy task callchain when entering to idle */
>  			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
> -				save_idle_callchain(thread, sample);
> +				save_idle_callchain(itr, sample);
>  		}
>  	}
>  
> -- 
> 2.10.2

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist
  2016-12-13  8:06     ` [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist Namhyung Kim
@ 2016-12-13 10:32       ` Arnaldo Carvalho de Melo
  2016-12-13 10:54         ` Namhyung Kim
  2016-12-20 19:21       ` [tip:perf/urgent] perf sched timehist: Add -I/--idle-hist option tip-bot for Namhyung Kim
  1 sibling, 1 reply; 28+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-12-13 10:32 UTC (permalink / raw)
  To: Namhyung Kim
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

Em Tue, Dec 13, 2016 at 05:06:32PM +0900, Namhyung Kim escreveu:
> When --idle-hist option is used, run/wait time and sched delay value
> should be shown for idle task only.  But due to internal accounting, a
> last thread has same value of next idle task's and it was shown.
> 
> In the below example, firefox after idle task has same run time of
> idle task's.

Same as last message, is this something I can fold into a patch yet in
my perf/core branch?

- Arnaldo
 
>   $ perf sched timehist --idle-hist
>   Samples do not have callchains.
>              time    cpu  task name             wait time  sch delay   run time
>                           [tid/pid]                (msec)     (msec)     (msec)
>   --------------- ------  --------------------  ---------  ---------  ---------
>     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
>     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
>     197731.754903 [0002]  <idle>                    0.047      0.000      0.567
>     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
>     197731.755922 [0002]  <idle>                    0.078      0.000      0.941
>     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
>   <SNIP>
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  tools/perf/builtin-sched.c | 9 +++++++++
>  1 file changed, 9 insertions(+)
> 
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 405a91d0515f..64a0959bccd7 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -2439,6 +2439,15 @@ static int timehist_sched_change_event(struct perf_tool *tool,
>  				goto out;
>  
>  			timehist_update_runtime_stats(last_tr, t, tprev);
> +			/*
> +			 * remove delta time of last thread as it's not updated
> +			 * and otherwise it will show an invalid value next
> +			 * time.  we only care total run time and run stat.
> +			 */
> +			last_tr->dt_run = 0;
> +			last_tr->dt_wait = 0;
> +			last_tr->dt_delay = 0;
> +
>  			if (itr->cursor.nr)
>  				callchain_append(&itr->callchain, &itr->cursor,
>  						 t - tprev);
> -- 
> 2.10.2

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
  2016-12-13 10:32     ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Arnaldo Carvalho de Melo
@ 2016-12-13 10:49       ` Namhyung Kim
  2016-12-13 12:03         ` Arnaldo Carvalho de Melo
  2016-12-13 13:04         ` Arnaldo Carvalho de Melo
  0 siblings, 2 replies; 28+ messages in thread
From: Namhyung Kim @ 2016-12-13 10:49 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

Hi Arnaldo,

On Tue, Dec 13, 2016 at 07:32:02AM -0300, Arnaldo Carvalho de Melo wrote:
> Em Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
> > When idle hist is enabled, the itr->last_thread should be set so that
> > it can find which thread run before idle task.  But it was only set in
> > the save_idle_callchain().  This makes idle task doesn't show up in
> > the output when callchain is not recorded.
> 
> It is important to provide a Fixes: tag so that I can check if the
> problem was introduced by some patch still not sent to Ingo, in which
> case I could try and merge them, is this the case here?

Yes,

Fixes: b50c3ab0f1cc ("perf sched timehist: Save callchain when entering idle")

Thanks,
Namhyung


> 
> > Before:
> > 
> >   $ perf sched timehist --idle-hist
> >   Samples do not have callchains.
> >              time    cpu  task name             wait time  sch delay   run time
> >                           [tid/pid]                (msec)     (msec)     (msec)
> >   --------------- ------  --------------------  ---------  ---------  ---------
> >     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
> >     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
> >     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> >     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
> >     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> >     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> >     ...
> > 
> > After:
> > 
> >     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
> >     197731.753914 [0001]  <idle>                    0.000      0.000      0.079
> >     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
> >     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> >     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
> >     197731.754903 [0002]  <idle>                    0.047      0.000      0.567
> >     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
> >     197731.755922 [0002]  <idle>                    0.078      0.000      0.941
> >     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
> >     197731.756625 [0003]  <idle>                    0.123      0.000      2.709
> >     ...
> > 
> > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > ---
> >  tools/perf/builtin-sched.c | 33 +++++++++++++++++----------------
> >  1 file changed, 17 insertions(+), 16 deletions(-)
> > 
> > diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> > index 0750e938a656..405a91d0515f 100644
> > --- a/tools/perf/builtin-sched.c
> > +++ b/tools/perf/builtin-sched.c
> > @@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)
> >  	return idle_threads[cpu];
> >  }
> >  
> > -static void save_idle_callchain(struct thread *thread,
> > +static void save_idle_callchain(struct idle_thread_runtime *itr,
> >  				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);
> >  }
> >  
> > @@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
> >  
> >  		save_task_callchain(sched, sample, evsel, machine);
> >  		if (sched->idle_hist) {
> > +			struct thread *idle;
> > +			struct idle_thread_runtime *itr;
> > +
> > +			idle = get_idle_thread(sample->cpu);
> > +			if (idle == NULL) {
> > +				pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
> > +				return NULL;
> > +			}
> > +
> > +			itr = thread__priv(idle);
> > +			if (itr == NULL)
> > +				return NULL;
> > +
> > +			itr->last_thread = thread;
> > +
> >  			/* copy task callchain when entering to idle */
> >  			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
> > -				save_idle_callchain(thread, sample);
> > +				save_idle_callchain(itr, sample);
> >  		}
> >  	}
> >  
> > -- 
> > 2.10.2

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist
  2016-12-13 10:32       ` Arnaldo Carvalho de Melo
@ 2016-12-13 10:54         ` Namhyung Kim
  2016-12-13 13:12           ` Arnaldo Carvalho de Melo
  0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2016-12-13 10:54 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

On Tue, Dec 13, 2016 at 07:32:36AM -0300, Arnaldo Carvalho de Melo wrote:
> Em Tue, Dec 13, 2016 at 05:06:32PM +0900, Namhyung Kim escreveu:
> > When --idle-hist option is used, run/wait time and sched delay value
> > should be shown for idle task only.  But due to internal accounting, a
> > last thread has same value of next idle task's and it was shown.
> > 
> > In the below example, firefox after idle task has same run time of
> > idle task's.
> 
> Same as last message, is this something I can fold into a patch yet in
> my perf/core branch?

Yep,

Fixes: 78de3657008b ("perf sched timehist: Add -I/--idle-hist option")

I guess it makes a conflict on the callchain code.  In case it doesn't
look obvious to resolve, please let me know..

Thanks,
Namhyung


> 
> - Arnaldo
>  
> >   $ perf sched timehist --idle-hist
> >   Samples do not have callchains.
> >              time    cpu  task name             wait time  sch delay   run time
> >                           [tid/pid]                (msec)     (msec)     (msec)
> >   --------------- ------  --------------------  ---------  ---------  ---------
> >     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> >     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
> >     197731.754903 [0002]  <idle>                    0.047      0.000      0.567
> >     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
> >     197731.755922 [0002]  <idle>                    0.078      0.000      0.941
> >     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
> >   <SNIP>
> > 
> > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > ---
> >  tools/perf/builtin-sched.c | 9 +++++++++
> >  1 file changed, 9 insertions(+)
> > 
> > diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> > index 405a91d0515f..64a0959bccd7 100644
> > --- a/tools/perf/builtin-sched.c
> > +++ b/tools/perf/builtin-sched.c
> > @@ -2439,6 +2439,15 @@ static int timehist_sched_change_event(struct perf_tool *tool,
> >  				goto out;
> >  
> >  			timehist_update_runtime_stats(last_tr, t, tprev);
> > +			/*
> > +			 * remove delta time of last thread as it's not updated
> > +			 * and otherwise it will show an invalid value next
> > +			 * time.  we only care total run time and run stat.
> > +			 */
> > +			last_tr->dt_run = 0;
> > +			last_tr->dt_wait = 0;
> > +			last_tr->dt_delay = 0;
> > +
> >  			if (itr->cursor.nr)
> >  				callchain_append(&itr->callchain, &itr->cursor,
> >  						 t - tprev);
> > -- 
> > 2.10.2

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
  2016-12-13 10:49       ` Namhyung Kim
@ 2016-12-13 12:03         ` Arnaldo Carvalho de Melo
  2016-12-13 13:04         ` Arnaldo Carvalho de Melo
  1 sibling, 0 replies; 28+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-12-13 12:03 UTC (permalink / raw)
  To: Namhyung Kim
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

Em Tue, Dec 13, 2016 at 07:49:44PM +0900, Namhyung Kim escreveu:
> Hi Arnaldo,
> 
> On Tue, Dec 13, 2016 at 07:32:02AM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
> > > When idle hist is enabled, the itr->last_thread should be set so that
> > > it can find which thread run before idle task.  But it was only set in
> > > the save_idle_callchain().  This makes idle task doesn't show up in
> > > the output when callchain is not recorded.
> > 
> > It is important to provide a Fixes: tag so that I can check if the
> > problem was introduced by some patch still not sent to Ingo, in which
> > case I could try and merge them, is this the case here?
> 
> Yes,
> 
> Fixes: b50c3ab0f1cc ("perf sched timehist: Save callchain when entering idle")

Thanks, will try and merge this and the other one so that we remove
those as bisection problems when looking for problems in this area.

- Arnaldo
 
> Thanks,
> Namhyung
> 
> 
> > 
> > > Before:
> > > 
> > >   $ perf sched timehist --idle-hist
> > >   Samples do not have callchains.
> > >              time    cpu  task name             wait time  sch delay   run time
> > >                           [tid/pid]                (msec)     (msec)     (msec)
> > >   --------------- ------  --------------------  ---------  ---------  ---------
> > >     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
> > >     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
> > >     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
> > >     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     ...
> > > 
> > > After:
> > > 
> > >     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
> > >     197731.753914 [0001]  <idle>                    0.000      0.000      0.079
> > >     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
> > >     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
> > >     197731.754903 [0002]  <idle>                    0.047      0.000      0.567
> > >     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
> > >     197731.755922 [0002]  <idle>                    0.078      0.000      0.941
> > >     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
> > >     197731.756625 [0003]  <idle>                    0.123      0.000      2.709
> > >     ...
> > > 
> > > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > > ---
> > >  tools/perf/builtin-sched.c | 33 +++++++++++++++++----------------
> > >  1 file changed, 17 insertions(+), 16 deletions(-)
> > > 
> > > diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> > > index 0750e938a656..405a91d0515f 100644
> > > --- a/tools/perf/builtin-sched.c
> > > +++ b/tools/perf/builtin-sched.c
> > > @@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)
> > >  	return idle_threads[cpu];
> > >  }
> > >  
> > > -static void save_idle_callchain(struct thread *thread,
> > > +static void save_idle_callchain(struct idle_thread_runtime *itr,
> > >  				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);
> > >  }
> > >  
> > > @@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
> > >  
> > >  		save_task_callchain(sched, sample, evsel, machine);
> > >  		if (sched->idle_hist) {
> > > +			struct thread *idle;
> > > +			struct idle_thread_runtime *itr;
> > > +
> > > +			idle = get_idle_thread(sample->cpu);
> > > +			if (idle == NULL) {
> > > +				pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
> > > +				return NULL;
> > > +			}
> > > +
> > > +			itr = thread__priv(idle);
> > > +			if (itr == NULL)
> > > +				return NULL;
> > > +
> > > +			itr->last_thread = thread;
> > > +
> > >  			/* copy task callchain when entering to idle */
> > >  			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
> > > -				save_idle_callchain(thread, sample);
> > > +				save_idle_callchain(itr, sample);
> > >  		}
> > >  	}
> > >  
> > > -- 
> > > 2.10.2

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains
  2016-12-13 10:49       ` Namhyung Kim
  2016-12-13 12:03         ` Arnaldo Carvalho de Melo
@ 2016-12-13 13:04         ` Arnaldo Carvalho de Melo
  1 sibling, 0 replies; 28+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-12-13 13:04 UTC (permalink / raw)
  To: Namhyung Kim
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

Em Tue, Dec 13, 2016 at 07:49:44PM +0900, Namhyung Kim escreveu:
> Hi Arnaldo,
> 
> On Tue, Dec 13, 2016 at 07:32:02AM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Tue, Dec 13, 2016 at 05:06:31PM +0900, Namhyung Kim escreveu:
> > > When idle hist is enabled, the itr->last_thread should be set so that
> > > it can find which thread run before idle task.  But it was only set in
> > > the save_idle_callchain().  This makes idle task doesn't show up in
> > > the output when callchain is not recorded.
> > 
> > It is important to provide a Fixes: tag so that I can check if the
> > problem was introduced by some patch still not sent to Ingo, in which
> > case I could try and merge them, is this the case here?
> 
> Yes,
> 
> Fixes: b50c3ab0f1cc ("perf sched timehist: Save callchain when entering idle")

Ok, merged this fix with b50c3ab0f1cc, adding a second Link tag pointing
to this fix, now to the second fix...

- Arnaldo
 
> Thanks,
> Namhyung
> 
> 
> > 
> > > Before:
> > > 
> > >   $ perf sched timehist --idle-hist
> > >   Samples do not have callchains.
> > >              time    cpu  task name             wait time  sch delay   run time
> > >                           [tid/pid]                (msec)     (msec)     (msec)
> > >   --------------- ------  --------------------  ---------  ---------  ---------
> > >     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
> > >     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
> > >     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
> > >     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     ...
> > > 
> > > After:
> > > 
> > >     197731.753834 [0001]  perf[27469]               0.000      0.000      0.000
> > >     197731.753914 [0001]  <idle>                    0.000      0.000      0.079
> > >     197731.753915 [0003]  migration/3[23]           0.000      0.000      0.000
> > >     197731.754335 [0002]  firefox[17773/17739]      0.000      0.000      0.000
> > >     197731.754486 [0001]  sleep[27470]              0.000      0.000      0.000
> > >     197731.754903 [0002]  <idle>                    0.047      0.000      0.567
> > >     197731.754981 [0002]  firefox[17773/17739]      0.000      0.000      0.567
> > >     197731.755922 [0002]  <idle>                    0.078      0.000      0.941
> > >     197731.755994 [0002]  firefox[17773/17739]      0.000      0.000      0.941
> > >     197731.756625 [0003]  <idle>                    0.123      0.000      2.709
> > >     ...
> > > 
> > > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > > ---
> > >  tools/perf/builtin-sched.c | 33 +++++++++++++++++----------------
> > >  1 file changed, 17 insertions(+), 16 deletions(-)
> > > 
> > > diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> > > index 0750e938a656..405a91d0515f 100644
> > > --- a/tools/perf/builtin-sched.c
> > > +++ b/tools/perf/builtin-sched.c
> > > @@ -2102,26 +2102,12 @@ static struct thread *get_idle_thread(int cpu)
> > >  	return idle_threads[cpu];
> > >  }
> > >  
> > > -static void save_idle_callchain(struct thread *thread,
> > > +static void save_idle_callchain(struct idle_thread_runtime *itr,
> > >  				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);
> > >  }
> > >  
> > > @@ -2179,9 +2165,24 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
> > >  
> > >  		save_task_callchain(sched, sample, evsel, machine);
> > >  		if (sched->idle_hist) {
> > > +			struct thread *idle;
> > > +			struct idle_thread_runtime *itr;
> > > +
> > > +			idle = get_idle_thread(sample->cpu);
> > > +			if (idle == NULL) {
> > > +				pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
> > > +				return NULL;
> > > +			}
> > > +
> > > +			itr = thread__priv(idle);
> > > +			if (itr == NULL)
> > > +				return NULL;
> > > +
> > > +			itr->last_thread = thread;
> > > +
> > >  			/* copy task callchain when entering to idle */
> > >  			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
> > > -				save_idle_callchain(thread, sample);
> > > +				save_idle_callchain(itr, sample);
> > >  		}
> > >  	}
> > >  
> > > -- 
> > > 2.10.2

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist
  2016-12-13 10:54         ` Namhyung Kim
@ 2016-12-13 13:12           ` Arnaldo Carvalho de Melo
  0 siblings, 0 replies; 28+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-12-13 13:12 UTC (permalink / raw)
  To: Namhyung Kim
  Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, David Ahern,
	Andi Kleen, Minchan Kim

Em Tue, Dec 13, 2016 at 07:54:42PM +0900, Namhyung Kim escreveu:
> On Tue, Dec 13, 2016 at 07:32:36AM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Tue, Dec 13, 2016 at 05:06:32PM +0900, Namhyung Kim escreveu:
> > > When --idle-hist option is used, run/wait time and sched delay value
> > > should be shown for idle task only.  But due to internal accounting, a
> > > last thread has same value of next idle task's and it was shown.
> > > 
> > > In the below example, firefox after idle task has same run time of
> > > idle task's.
> > 
> > Same as last message, is this something I can fold into a patch yet in
> > my perf/core branch?
> 
> Yep,
> 
> Fixes: 78de3657008b ("perf sched timehist: Add -I/--idle-hist option")
> 
> I guess it makes a conflict on the callchain code.  In case it doesn't
> look obvious to resolve, please let me know..

Ok, fixed up, after building it, before 'rebase --continue', we get:

           time    cpu  task name             wait time  sch delay   run time
                        [tid/pid]                (msec)     (msec)     (msec)
--------------- ------  --------------------  ---------  ---------  ---------
   47548.582141 [0000]  perf[17869]               0.000      0.000      0.000 
   47548.583814 [0003]  rcu_sched[7]              0.000      0.000      0.000 
   47548.583825 [0003]  <idle>                    0.005      0.000      0.010 
   47548.583826 [0002]  rcuos/0[9]                0.000      0.000      0.000 
   47548.583828 [0003]  rcu_sched[7]              0.000      0.000      0.000 
   47548.587797 [0003]  <idle>                    0.002      0.000      3.969 
   47548.587799 [0003]  rcu_sched[7]              0.000      0.000      0.000 
   47548.587799 [0002]  <idle>                    0.011      0.000      3.973 
   47548.587808 [0002]  rcuos/0[9]                0.000      0.000      0.000 
   47548.594979 [0002]  <idle>                    0.008      0.000      7.171 
   47548.595014 [0002]  Timer[4869/4832]          0.000      0.000      0.000 
   47548.595064 [0001]  firefox[4832]             0.000      0.000      0.000 
   47548.603831 [0002]  <idle>                    0.034      0.000      8.817 
   47548.603874 [0001]  <idle>                    0.054      0.000      8.809

Which matches what you state as being the fix (task runtime after idle task).

git rebase --continue next...

- Arnaldo

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
  2016-12-13  8:05       ` Namhyung Kim
@ 2016-12-14 21:33         ` David Ahern
  2016-12-15 15:17           ` Namhyung Kim
  0 siblings, 1 reply; 28+ messages in thread
From: David Ahern @ 2016-12-14 21:33 UTC (permalink / raw)
  To: Namhyung Kim
  Cc: Arnaldo Carvalho de Melo, Ingo Molnar, Peter Zijlstra, Jiri Olsa,
	LKML, Andi Kleen, Minchan Kim

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

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2)
  2016-12-14 21:33         ` David Ahern
@ 2016-12-15 15:17           ` Namhyung Kim
  0 siblings, 0 replies; 28+ messages in thread
From: Namhyung Kim @ 2016-12-15 15:17 UTC (permalink / raw)
  To: David Ahern
  Cc: Arnaldo Carvalho de Melo, Ingo Molnar, Peter Zijlstra, Jiri Olsa,
	LKML, Andi Kleen, Minchan Kim

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

^ permalink raw reply	[flat|nested] 28+ messages in thread

* [tip:perf/urgent] perf sched timehist: Split is_idle_sample()
  2016-12-08 14:47 ` [PATCH v2 1/6] perf sched timehist: Split is_idle_sample() Namhyung Kim
@ 2016-12-20 19:19   ` tip-bot for Namhyung Kim
  0 siblings, 0 replies; 28+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-12-20 19:19 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: namhyung, linux-kernel, andi, mingo, jolsa, tglx, hpa, acme,
	peterz, minchan, dsahern

Commit-ID:  96039c7c52e03b7d6dd773664e74b79e3ae9856a
Gitweb:     http://git.kernel.org/tip/96039c7c52e03b7d6dd773664e74b79e3ae9856a
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Thu, 8 Dec 2016 23:47:50 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 15 Dec 2016 16:25:44 -0300

perf sched timehist: Split is_idle_sample()

The is_idle_sample() function actually does more than determining
whether sample come from idle task.  Split the callchain part into
save_task_callchain() to make it clearer.

Also checking prev_pid from trace data looks preferred than just
checking sample->pid since it's possible, although rare, to have invalid
0 pid/tid on scheduling an exiting task.

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-2-namhyung@kernel.org
[ Remove some needless () in some return statements ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 39 ++++++++++++++++++++-------------------
 1 file changed, 20 insertions(+), 19 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1a3f1be..966eddc 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -1939,39 +1939,40 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
 	r->total_run_time += r->dt_run;
 }
 
-static bool is_idle_sample(struct perf_sched *sched,
-			   struct perf_sample *sample,
-			   struct perf_evsel *evsel,
-			   struct machine *machine)
+static bool is_idle_sample(struct perf_sample *sample,
+			   struct perf_evsel *evsel)
 {
-	struct thread *thread;
-	struct callchain_cursor *cursor = &callchain_cursor;
-
 	/* pid 0 == swapper == idle task */
-	if (sample->pid == 0)
-		return true;
+	if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0)
+		return perf_evsel__intval(evsel, sample, "prev_pid") == 0;
 
-	if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0) {
-		if (perf_evsel__intval(evsel, sample, "prev_pid") == 0)
-			return true;
-	}
+	return sample->pid == 0;
+}
+
+static void save_task_callchain(struct perf_sched *sched,
+				struct perf_sample *sample,
+				struct perf_evsel *evsel,
+				struct machine *machine)
+{
+	struct callchain_cursor *cursor = &callchain_cursor;
+	struct thread *thread;
 
 	/* want main thread for process - has maps */
 	thread = machine__findnew_thread(machine, sample->pid, sample->pid);
 	if (thread == NULL) {
 		pr_debug("Failed to get thread for pid %d.\n", sample->pid);
-		return false;
+		return;
 	}
 
 	if (!symbol_conf.use_callchain || sample->callchain == NULL)
-		return false;
+		return;
 
 	if (thread__resolve_callchain(thread, cursor, evsel, sample,
 				      NULL, NULL, sched->max_stack + 2) != 0) {
 		if (verbose)
 			error("Failed to resolve callchain. Skipping\n");
 
-		return false;
+		return;
 	}
 
 	callchain_cursor_commit(cursor);
@@ -1994,8 +1995,6 @@ static bool is_idle_sample(struct perf_sched *sched,
 
 		callchain_cursor_advance(cursor);
 	}
-
-	return false;
 }
 
 /*
@@ -2111,7 +2110,7 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 {
 	struct thread *thread;
 
-	if (is_idle_sample(sched, sample, evsel, machine)) {
+	if (is_idle_sample(sample, evsel)) {
 		thread = get_idle_thread(sample->cpu);
 		if (thread == NULL)
 			pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
@@ -2124,6 +2123,8 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 			pr_debug("Failed to get thread for tid %d. skipping sample.\n",
 				 sample->tid);
 		}
+
+		save_task_callchain(sched, sample, evsel, machine);
 	}
 
 	return thread;

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [tip:perf/urgent] perf sched timehist: Introduce struct idle_time_data
  2016-12-08 14:47 ` [PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data Namhyung Kim
@ 2016-12-20 19:20   ` tip-bot for Namhyung Kim
  0 siblings, 0 replies; 28+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-12-20 19:20 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: andi, linux-kernel, jolsa, hpa, tglx, dsahern, namhyung, mingo,
	peterz, minchan, acme

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

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [tip:perf/urgent] perf sched timehist: Save callchain when entering idle
  2016-12-13  8:06   ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Namhyung Kim
  2016-12-13  8:06     ` [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist Namhyung Kim
  2016-12-13 10:32     ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Arnaldo Carvalho de Melo
@ 2016-12-20 19:20     ` tip-bot for Namhyung Kim
  2 siblings, 0 replies; 28+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-12-20 19:20 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: linux-kernel, andi, peterz, acme, dsahern, namhyung, hpa,
	minchan, jolsa, mingo, tglx

Commit-ID:  699b5b920db04a6ff5c03a519e4c182aeb350952
Gitweb:     http://git.kernel.org/tip/699b5b920db04a6ff5c03a519e4c182aeb350952
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Thu, 8 Dec 2016 23:47:52 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 15 Dec 2016 16:25:44 -0300

perf sched timehist: Save callchain when entering idle

In order to investigate the idleness reason, it is necessary to keep the
callchains when entering idle.  This can be identified by the
sched:sched_switch event having the next_pid field as 0.

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-4-namhyung@kernel.org
Link: http://lkml.kernel.org/r/20161213080632.19099-1-namhyung@kernel.org
[ Merged fix from Namhyung, see second Link: tag ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 30 ++++++++++++++++++++++++++++++
 1 file changed, 30 insertions(+)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index e108b0f..dc83b80 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,15 @@ static struct thread *get_idle_thread(int cpu)
 	return idle_threads[cpu];
 }
 
+static void save_idle_callchain(struct idle_thread_runtime *itr,
+				struct perf_sample *sample)
+{
+	if (!symbol_conf.use_callchain || sample->callchain == NULL)
+		return;
+
+	callchain_cursor__copy(&itr->cursor, &callchain_cursor);
+}
+
 /*
  * handle runtime stats saved per thread
  */
@@ -2154,6 +2164,26 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 		}
 
 		save_task_callchain(sched, sample, evsel, machine);
+		if (sched->idle_hist) {
+			struct thread *idle;
+			struct idle_thread_runtime *itr;
+
+			idle = get_idle_thread(sample->cpu);
+			if (idle == NULL) {
+				pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
+				return NULL;
+			}
+
+			itr = thread__priv(idle);
+			if (itr == NULL)
+				return NULL;
+
+			itr->last_thread = thread;
+
+			/* copy task callchain when entering to idle */
+			if (perf_evsel__intval(evsel, sample, "next_pid") == 0)
+				save_idle_callchain(itr, sample);
+		}
 	}
 
 	return thread;

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [tip:perf/urgent] perf sched timehist: Skip non-idle events when necessary
  2016-12-08 14:47 ` [PATCH v2 4/6] perf sched timehist: Skip non-idle events when necessary Namhyung Kim
@ 2016-12-20 19:21   ` tip-bot for Namhyung Kim
  0 siblings, 0 replies; 28+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-12-20 19:21 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: peterz, tglx, jolsa, andi, minchan, hpa, mingo, dsahern,
	namhyung, acme, linux-kernel

Commit-ID:  a4b2b6f56e0cfe729cf89318d44b6a875b31d95a
Gitweb:     http://git.kernel.org/tip/a4b2b6f56e0cfe729cf89318d44b6a875b31d95a
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Thu, 8 Dec 2016 23:47:53 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 15 Dec 2016 16:25:44 -0300

perf sched timehist: Skip non-idle events when necessary

Sometimes it only focuses on idle-related events like upcoming idle-hist
feature.  In this case we don't want to see other event to reduce noise.

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-5-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 25 ++++++++++++++++++-------
 1 file changed, 18 insertions(+), 7 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index dc83b80..c8e7848 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2190,7 +2190,9 @@ static struct thread *timehist_get_thread(struct perf_sched *sched,
 }
 
 static bool timehist_skip_sample(struct perf_sched *sched,
-				 struct thread *thread)
+				 struct thread *thread,
+				 struct perf_evsel *evsel,
+				 struct perf_sample *sample)
 {
 	bool rc = false;
 
@@ -2199,10 +2201,19 @@ static bool timehist_skip_sample(struct perf_sched *sched,
 		sched->skipped_samples++;
 	}
 
+	if (sched->idle_hist) {
+		if (strcmp(perf_evsel__name(evsel), "sched:sched_switch"))
+			rc = true;
+		else if (perf_evsel__intval(evsel, sample, "prev_pid") != 0 &&
+			 perf_evsel__intval(evsel, sample, "next_pid") != 0)
+			rc = true;
+	}
+
 	return rc;
 }
 
 static void timehist_print_wakeup_event(struct perf_sched *sched,
+					struct perf_evsel *evsel,
 					struct perf_sample *sample,
 					struct machine *machine,
 					struct thread *awakened)
@@ -2215,8 +2226,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
 		return;
 
 	/* show wakeup unless both awakee and awaker are filtered */
-	if (timehist_skip_sample(sched, thread) &&
-	    timehist_skip_sample(sched, awakened)) {
+	if (timehist_skip_sample(sched, thread, evsel, sample) &&
+	    timehist_skip_sample(sched, awakened, evsel, sample)) {
 		return;
 	}
 
@@ -2261,7 +2272,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool,
 	/* show wakeups if requested */
 	if (sched->show_wakeups &&
 	    !perf_time__skip_sample(&sched->ptime, sample->time))
-		timehist_print_wakeup_event(sched, sample, machine, thread);
+		timehist_print_wakeup_event(sched, evsel, sample, machine, thread);
 
 	return 0;
 }
@@ -2288,8 +2299,8 @@ static void timehist_print_migration_event(struct perf_sched *sched,
 	if (thread == NULL)
 		return;
 
-	if (timehist_skip_sample(sched, thread) &&
-	    timehist_skip_sample(sched, migrated)) {
+	if (timehist_skip_sample(sched, thread, evsel, sample) &&
+	    timehist_skip_sample(sched, migrated, evsel, sample)) {
 		return;
 	}
 
@@ -2374,7 +2385,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 		goto out;
 	}
 
-	if (timehist_skip_sample(sched, thread))
+	if (timehist_skip_sample(sched, thread, evsel, sample))
 		goto out;
 
 	tr = thread__get_runtime(thread);

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [tip:perf/urgent] perf sched timehist: Add -I/--idle-hist option
  2016-12-13  8:06     ` [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist Namhyung Kim
  2016-12-13 10:32       ` Arnaldo Carvalho de Melo
@ 2016-12-20 19:21       ` tip-bot for Namhyung Kim
  1 sibling, 0 replies; 28+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-12-20 19:21 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: peterz, andi, dsahern, linux-kernel, mingo, minchan, acme, tglx,
	namhyung, hpa, jolsa

Commit-ID:  07235f84ece6b66f43334881806aad3467cf3d84
Gitweb:     http://git.kernel.org/tip/07235f84ece6b66f43334881806aad3467cf3d84
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Thu, 8 Dec 2016 23:47:54 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 15 Dec 2016 16:25:45 -0300

perf sched timehist: Add -I/--idle-hist option

The --idle-hist option is to analyze system idle state so which process
makes cpu to go idle.  If this option is specified, non-idle events will
be skipped and processes switching to/from idle will be shown.

This option is mostly useful when used with --summary(-only) option.  In
the idle-time summary view, idle time is accounted to previous thread
which is run before idle task.

The example output looks like following:

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

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
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-6-namhyung@kernel.org
Link: http://lkml.kernel.org/r/20161213080632.19099-2-namhyung@kernel.org
[ Merged fix sent by Namhyumg, as posted in the second Link: tag ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/Documentation/perf-sched.txt |  4 +++
 tools/perf/builtin-sched.c              | 46 +++++++++++++++++++++++++++++----
 2 files changed, 45 insertions(+), 5 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 7775b1e..7617396 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -132,6 +132,10 @@ OPTIONS for 'perf sched timehist'
 --migrations::
 	Show migration events.
 
+-I::
+--idle-hist::
+	Show idle-related events only.
+
 --time::
 	Only analyze samples within given time window: <start>,<stop>. Times
 	have the format seconds.microseconds. If start is not given (i.e., time
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index c8e7848..0b14265 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2421,7 +2421,36 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 			t = ptime->end;
 	}
 
-	timehist_update_runtime_stats(tr, t, tprev);
+	if (!sched->idle_hist || thread->tid == 0) {
+		timehist_update_runtime_stats(tr, t, tprev);
+
+		if (sched->idle_hist) {
+			struct idle_thread_runtime *itr = (void *)tr;
+			struct thread_runtime *last_tr;
+
+			BUG_ON(thread->tid != 0);
+
+			if (itr->last_thread == NULL)
+				goto out;
+
+			/* add current idle time as last thread's runtime */
+			last_tr = thread__get_runtime(itr->last_thread);
+			if (last_tr == NULL)
+				goto out;
+
+			timehist_update_runtime_stats(last_tr, t, tprev);
+			/*
+			 * remove delta time of last thread as it's not updated
+			 * and otherwise it will show an invalid value next
+			 * time.  we only care total run time and run stat.
+			 */
+			last_tr->dt_run = 0;
+			last_tr->dt_wait = 0;
+			last_tr->dt_delay = 0;
+
+			itr->last_thread = NULL;
+		}
+	}
 
 	if (!sched->summary_only)
 		timehist_print_sample(sched, sample, &al, thread, t);
@@ -2543,9 +2572,15 @@ static void timehist_print_summary(struct perf_sched *sched,
 	if (comm_width < 30)
 		comm_width = 30;
 
-	printf("\nRuntime summary\n");
-	printf("%*s  parent   sched-in  ", comm_width, "comm");
-	printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
+	if (sched->idle_hist) {
+		printf("\nIdle-time summary\n");
+		printf("%*s  parent  sched-out  ", comm_width, "comm");
+		printf("  idle-time   min-idle    avg-idle    max-idle  stddev  migrations\n");
+	} else {
+		printf("\nRuntime summary\n");
+		printf("%*s  parent   sched-in  ", comm_width, "comm");
+		printf("   run-time    min-run     avg-run     max-run  stddev  migrations\n");
+	}
 	printf("%*s            (count)  ", comm_width, "");
 	printf("     (msec)     (msec)      (msec)      (msec)       %%\n");
 	printf("%.117s\n", graph_dotted_line);
@@ -2561,7 +2596,7 @@ static void timehist_print_summary(struct perf_sched *sched,
 		printf("<no terminated tasks>\n");
 
 	/* CPU idle stats not tracked when samples were skipped */
-	if (sched->skipped_samples)
+	if (sched->skipped_samples && !sched->idle_hist)
 		return;
 
 	printf("\nIdle stats:\n");
@@ -3107,6 +3142,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
 	OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"),
 	OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
+	OPT_BOOLEAN('I', "idle-hist", &sched.idle_hist, "Show idle events only"),
 	OPT_STRING(0, "time", &sched.time_str, "str",
 		   "Time span for analysis (start,stop)"),
 	OPT_PARENT(sched_options)

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [tip:perf/urgent] perf sched timehist: Show callchains for idle stat
  2016-12-08 14:47 ` [PATCH v2 6/6] perf sched timehist: Show callchains for idle stat Namhyung Kim
@ 2016-12-20 19:22   ` tip-bot for Namhyung Kim
  0 siblings, 0 replies; 28+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-12-20 19:22 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: tglx, hpa, minchan, mingo, acme, dsahern, andi, peterz, jolsa,
	namhyung, linux-kernel

Commit-ID:  ba957ebb54893acaf3dc846031073a63f021cee1
Gitweb:     http://git.kernel.org/tip/ba957ebb54893acaf3dc846031073a63f021cee1
Author:     Namhyung Kim <namhyung@kernel.org>
AuthorDate: Thu, 8 Dec 2016 23:47:55 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Thu, 15 Dec 2016 16:25:45 -0300

perf sched timehist: Show callchains for idle stat

When --idle-hist option is used with --summary, it now shows idle stats
with callchains like below:

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

Committer notes:

Extra testing:

  # uname -a
  Linux jouet 4.8.8-300.fc25.x86_64 #1 SMP Tue Nov 15 18:10:06 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

1) Run 'perf sched record -g'

2) Run 'perf sched timehist --idle --summary'

<SNIP>
  Idle stats by callchain:
  CPU  0: 13456.840 msec
  Idle time (msec) Count Callchains
  ---------------- ----- --------------------------------------------------
          5386.637  3283 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
          2750.238  2299 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- do_syscall_64
          1275.672  1287 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- entry_SYSCALL_64_fastpath
           936.322   452 worker_thread <- kthread <- ret_from_fork
           741.311   385 rcu_nocb_kthread <- kthread <- ret_from_fork
           729.385   248 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_ppoll
           365.386   229 irq_thread <- kthread <- ret_from_fork
           338.934   265 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- entry_SYSCALL_64_fastpath
           219.488   201 schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
           186.839   410 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- do_syscall_64
           142.541    59 kvm_vcpu_block <- kvm_arch_vcpu_ioctl_run <- kvm_vcpu_ioctl <- do_vfs_ioctl <- sys_ioctl
            83.887    92 smpboot_thread_fn <- kthread <- ret_from_fork
            62.722    96 do_exit <- do_group_exit <- 0x2a5594 <- entry_SYSCALL_64_fastpath
            47.894    83 pipe_wait <- pipe_read <- __vfs_read <- vfs_read <- sys_read
            46.554    61 rcu_gp_kthread <- kthread <- ret_from_fork
            34.337    21 schedule_timeout <- intel_fbc_work_fn <- process_one_work <- worker_thread <- kthread
            29.521    14 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_select <- core_sys_select
            20.274    10 schedule_timeout <- io_schedule_timeout <- bit_wait_io <- __wait_on_bit <- out_of_line_wait_on_bit
            15.085    55 schedule_timeout <- unix_stream_read_generic <- unix_stream_recvmsg <- sock_recvmsg <- SYSC_recvfrom
<SNIP>

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
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-7-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-sched.c | 86 ++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 86 insertions(+)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 0b14265..c1c07bf 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2448,6 +2448,9 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 			last_tr->dt_wait = 0;
 			last_tr->dt_delay = 0;
 
+			if (itr->cursor.nr)
+				callchain_append(&itr->callchain, &itr->cursor, t - tprev);
+
 			itr->last_thread = NULL;
 		}
 	}
@@ -2557,6 +2560,60 @@ static int show_deadthread_runtime(struct thread *t, void *priv)
 	return __show_thread_runtime(t, priv);
 }
 
+static size_t callchain__fprintf_folded(FILE *fp, struct callchain_node *node)
+{
+	const char *sep = " <- ";
+	struct callchain_list *chain;
+	size_t ret = 0;
+	char bf[1024];
+	bool first;
+
+	if (node == NULL)
+		return 0;
+
+	ret = callchain__fprintf_folded(fp, node->parent);
+	first = (ret == 0);
+
+	list_for_each_entry(chain, &node->val, list) {
+		if (chain->ip >= PERF_CONTEXT_MAX)
+			continue;
+		if (chain->ms.sym && chain->ms.sym->ignore)
+			continue;
+		ret += fprintf(fp, "%s%s", first ? "" : sep,
+			       callchain_list__sym_name(chain, bf, sizeof(bf),
+							false));
+		first = false;
+	}
+
+	return ret;
+}
+
+static size_t timehist_print_idlehist_callchain(struct rb_root *root)
+{
+	size_t ret = 0;
+	FILE *fp = stdout;
+	struct callchain_node *chain;
+	struct rb_node *rb_node = rb_first(root);
+
+	printf("  %16s  %8s  %s\n", "Idle time (msec)", "Count", "Callchains");
+	printf("  %.16s  %.8s  %.50s\n", graph_dotted_line, graph_dotted_line,
+	       graph_dotted_line);
+
+	while (rb_node) {
+		chain = rb_entry(rb_node, struct callchain_node, rb_node);
+		rb_node = rb_next(rb_node);
+
+		ret += fprintf(fp, "  ");
+		print_sched_time(chain->hit, 12);
+		ret += 16;  /* print_sched_time returns 2nd arg + 4 */
+		ret += fprintf(fp, " %8d  ", chain->count);
+		ret += callchain__fprintf_folded(fp, chain);
+		ret += fprintf(fp, "\n");
+	}
+
+	return ret;
+}
+
 static void timehist_print_summary(struct perf_sched *sched,
 				   struct perf_session *session)
 {
@@ -2615,6 +2672,35 @@ static void timehist_print_summary(struct perf_sched *sched,
 			printf("    CPU %2d idle entire time window\n", i);
 	}
 
+	if (sched->idle_hist && symbol_conf.use_callchain) {
+		callchain_param.mode  = CHAIN_FOLDED;
+		callchain_param.value = CCVAL_PERIOD;
+
+		callchain_register_param(&callchain_param);
+
+		printf("\nIdle stats by callchain:\n");
+		for (i = 0; i < idle_max_cpu; ++i) {
+			struct idle_thread_runtime *itr;
+
+			t = idle_threads[i];
+			if (!t)
+				continue;
+
+			itr = thread__priv(t);
+			if (itr == NULL)
+				continue;
+
+			callchain_param.sort(&itr->sorted_root, &itr->callchain,
+					     0, &callchain_param);
+
+			printf("  CPU %2d:", i);
+			print_sched_time(itr->tr.total_run_time, 6);
+			printf(" msec\n");
+			timehist_print_idlehist_callchain(&itr->sorted_root);
+			printf("\n");
+		}
+	}
+
 	printf("\n"
 	       "    Total number of unique tasks: %" PRIu64 "\n"
 	       "Total number of context switches: %" PRIu64 "\n"

^ permalink raw reply related	[flat|nested] 28+ messages in thread

end of thread, other threads:[~2016-12-20 19:23 UTC | newest]

Thread overview: 28+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-12-08 14:47 [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) Namhyung Kim
2016-12-08 14:47 ` [PATCH v2 1/6] perf sched timehist: Split is_idle_sample() Namhyung Kim
2016-12-20 19:19   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
2016-12-08 14:47 ` [PATCH v2 2/6] perf sched timehist: Introduce struct idle_time_data Namhyung Kim
2016-12-20 19:20   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
2016-12-08 14:47 ` [PATCH v2 3/6] perf sched timehist: Save callchain when entering idle Namhyung Kim
2016-12-13  8:06   ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Namhyung Kim
2016-12-13  8:06     ` [PATCH 2/2] perf sched timehist: Fix invalid runtime in the idle hist Namhyung Kim
2016-12-13 10:32       ` Arnaldo Carvalho de Melo
2016-12-13 10:54         ` Namhyung Kim
2016-12-13 13:12           ` Arnaldo Carvalho de Melo
2016-12-20 19:21       ` [tip:perf/urgent] perf sched timehist: Add -I/--idle-hist option tip-bot for Namhyung Kim
2016-12-13 10:32     ` [PATCH 1/2] perf sched timehist: Fix --idle-hist when no callchains Arnaldo Carvalho de Melo
2016-12-13 10:49       ` Namhyung Kim
2016-12-13 12:03         ` Arnaldo Carvalho de Melo
2016-12-13 13:04         ` Arnaldo Carvalho de Melo
2016-12-20 19:20     ` [tip:perf/urgent] perf sched timehist: Save callchain when entering idle tip-bot for Namhyung Kim
2016-12-08 14:47 ` [PATCH v2 4/6] perf sched timehist: Skip non-idle events when necessary Namhyung Kim
2016-12-20 19:21   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
2016-12-08 14:47 ` [PATCH v2 5/6] perf sched timehist: Add -I/--idle-hist option Namhyung Kim
2016-12-08 14:47 ` [PATCH v2 6/6] perf sched timehist: Show callchains for idle stat Namhyung Kim
2016-12-20 19:22   ` [tip:perf/urgent] " tip-bot for Namhyung Kim
2016-12-10 16:32 ` [PATCHSET 0/6] perf sched timehist: Introduce --idle-hist option (v2) David Ahern
2016-12-12 17:26   ` Namhyung Kim
2016-12-12 17:37     ` David Ahern
2016-12-13  8:05       ` Namhyung Kim
2016-12-14 21:33         ` David Ahern
2016-12-15 15:17           ` Namhyung Kim

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).