linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH] perf sched timehist: Add --next option
@ 2017-03-14  1:56 Brendan Gregg
  2017-03-14 13:12 ` Arnaldo Carvalho de Melo
  2017-03-15 18:41 ` [tip:perf/core] " tip-bot for Brendan Gregg
  0 siblings, 2 replies; 4+ messages in thread
From: Brendan Gregg @ 2017-03-14  1:56 UTC (permalink / raw)
  To: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
	Alexander Shishkin
  Cc: linux-kernel, Namhyung Kim, Brendan Gregg

The --next option shows the next task for each context switch, providing
more context for the sequence of scheduler events.

$ perf sched timehist --next | head
Samples do not have callchains.
           time    cpu  task name                       wait time  sch delay   run time
                        [tid/pid]                          (msec)     (msec)     (msec)
--------------- ------  ------------------------------  ---------  ---------  ---------
 1136374.793792 [0000]  <idle>                              0.000      0.000      0.000  next: rngd[1524]
 1136374.793801 [0000]  rngd[1524]                          0.000      0.000      0.009  next: swapper/0[0]
 1136374.794048 [0007]  <idle>                              0.000      0.000      0.000  next: yes[30884]
 1136374.794066 [0007]  yes[30884]                          0.000      0.000      0.018  next: swapper/7[0]
 1136374.794126 [0002]  <idle>                              0.000      0.000      0.000  next: rngd[1524]
 1136374.794140 [0002]  rngd[1524]                          0.325      0.006      0.013  next: swapper/2[0]
 1136374.794281 [0003]  <idle>                              0.000      0.000      0.000  next: perf[31070]

Signed-off-by: Brendan Gregg <bgregg@netflix.com>
---
 tools/perf/Documentation/perf-sched.txt |  4 ++++
 tools/perf/builtin-sched.c              | 29 ++++++++++++++++++++++++-----
 2 files changed, 28 insertions(+), 5 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index d33dedd..a092a24 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.
 
+-n::
+--next::
+	Show next task.
+
 -I::
 --idle-hist::
 	Show idle-related events only.
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index b94cf0d..fedc8f2 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -221,6 +221,7 @@ struct perf_sched {
 	unsigned int	max_stack;
 	bool		show_cpu_visual;
 	bool		show_wakeups;
+	bool		show_next;
 	bool		show_migrations;
 	bool		show_state;
 	u64		skipped_samples;
@@ -1897,14 +1898,18 @@ static char task_state_char(struct thread *thread, int state)
 }
 
 static void timehist_print_sample(struct perf_sched *sched,
+				  struct perf_evsel *evsel,
 				  struct perf_sample *sample,
 				  struct addr_location *al,
 				  struct thread *thread,
 				  u64 t, int state)
 {
 	struct thread_runtime *tr = thread__priv(thread);
+	const char *next_comm = perf_evsel__strval(evsel, sample, "next_comm");
+	const u32 next_pid = perf_evsel__intval(evsel, sample, "next_pid");
 	u32 max_cpus = sched->max_cpu + 1;
 	char tstr[64];
+	char nstr[30];
 	u64 wait_time;
 
 	timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
@@ -1937,7 +1942,13 @@ static void timehist_print_sample(struct perf_sched *sched,
 	if (sched->show_state)
 		printf(" %5c ", task_state_char(thread, state));
 
-	if (sched->show_wakeups)
+	if (sched->show_next) {
+		snprintf(nstr, sizeof(nstr), "next: %s[%d]", next_comm,
+			next_pid);
+		printf(" %-*s", comm_width, nstr);
+	}
+
+	if (sched->show_wakeups && !sched->show_next)
 		printf("  %-*s", comm_width, "");
 
 	if (thread->tid == 0)
@@ -2531,7 +2542,8 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 	}
 
 	if (!sched->summary_only)
-		timehist_print_sample(sched, sample, &al, thread, t, state);
+		timehist_print_sample(sched, evsel, sample, &al, thread, t,
+				      state);
 
 out:
 	if (sched->hist_time.start == 0 && t >= ptime->start)
@@ -3340,6 +3352,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('S', "with-summary", &sched.summary,
 		    "Show all syscalls and summary with statistics"),
 	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
+	OPT_BOOLEAN('n', "next", &sched.show_next, "Show next task"),
 	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"),
@@ -3437,10 +3450,16 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 			if (argc)
 				usage_with_options(timehist_usage, timehist_options);
 		}
-		if (sched.show_wakeups && sched.summary_only) {
-			pr_err(" Error: -s and -w are mutually exclusive.\n");
+		if ((sched.show_wakeups || sched.show_next) &&
+		    sched.summary_only) {
+			pr_err(" Error: -s and -[n|w] are mutually exclusive.\n");
 			parse_options_usage(timehist_usage, timehist_options, "s", true);
-			parse_options_usage(NULL, timehist_options, "w", true);
+			if (sched.show_wakeups)
+				parse_options_usage(NULL, timehist_options, "w",
+						    true);
+			if (sched.show_next)
+				parse_options_usage(NULL, timehist_options, "n",
+						    true);
 			return -EINVAL;
 		}
 
-- 
2.7.4

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

* Re: [PATCH] perf sched timehist: Add --next option
  2017-03-14  1:56 [PATCH] perf sched timehist: Add --next option Brendan Gregg
@ 2017-03-14 13:12 ` Arnaldo Carvalho de Melo
  2017-03-15  0:39   ` Brendan Gregg
  2017-03-15 18:41 ` [tip:perf/core] " tip-bot for Brendan Gregg
  1 sibling, 1 reply; 4+ messages in thread
From: Arnaldo Carvalho de Melo @ 2017-03-14 13:12 UTC (permalink / raw)
  To: Brendan Gregg
  Cc: Peter Zijlstra, Ingo Molnar, Alexander Shishkin, linux-kernel,
	Namhyung Kim

Em Tue, Mar 14, 2017 at 01:56:29AM +0000, Brendan Gregg escreveu:
> The --next option shows the next task for each context switch, providing
> more context for the sequence of scheduler events.
> 
> $ perf sched timehist --next | head
> Samples do not have callchains.
>            time    cpu  task name                       wait time  sch delay   run time
>                         [tid/pid]                          (msec)     (msec)     (msec)
> --------------- ------  ------------------------------  ---------  ---------  ---------

Thanks, applied.

Minor request: when printing tool output in the cset comment, please add
two spaces before all lines, my git-am scripts get confused with that
--- thinking its a separator.

- Arnaldo

>  1136374.793792 [0000]  <idle>                              0.000      0.000      0.000  next: rngd[1524]
>  1136374.793801 [0000]  rngd[1524]                          0.000      0.000      0.009  next: swapper/0[0]
>  1136374.794048 [0007]  <idle>                              0.000      0.000      0.000  next: yes[30884]
>  1136374.794066 [0007]  yes[30884]                          0.000      0.000      0.018  next: swapper/7[0]
>  1136374.794126 [0002]  <idle>                              0.000      0.000      0.000  next: rngd[1524]
>  1136374.794140 [0002]  rngd[1524]                          0.325      0.006      0.013  next: swapper/2[0]
>  1136374.794281 [0003]  <idle>                              0.000      0.000      0.000  next: perf[31070]
> 
> Signed-off-by: Brendan Gregg <bgregg@netflix.com>
> ---
>  tools/perf/Documentation/perf-sched.txt |  4 ++++
>  tools/perf/builtin-sched.c              | 29 ++++++++++++++++++++++++-----
>  2 files changed, 28 insertions(+), 5 deletions(-)
> 
> diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
> index d33dedd..a092a24 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.
>  
> +-n::
> +--next::
> +	Show next task.
> +
>  -I::
>  --idle-hist::
>  	Show idle-related events only.
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index b94cf0d..fedc8f2 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -221,6 +221,7 @@ struct perf_sched {
>  	unsigned int	max_stack;
>  	bool		show_cpu_visual;
>  	bool		show_wakeups;
> +	bool		show_next;
>  	bool		show_migrations;
>  	bool		show_state;
>  	u64		skipped_samples;
> @@ -1897,14 +1898,18 @@ static char task_state_char(struct thread *thread, int state)
>  }
>  
>  static void timehist_print_sample(struct perf_sched *sched,
> +				  struct perf_evsel *evsel,
>  				  struct perf_sample *sample,
>  				  struct addr_location *al,
>  				  struct thread *thread,
>  				  u64 t, int state)
>  {
>  	struct thread_runtime *tr = thread__priv(thread);
> +	const char *next_comm = perf_evsel__strval(evsel, sample, "next_comm");
> +	const u32 next_pid = perf_evsel__intval(evsel, sample, "next_pid");
>  	u32 max_cpus = sched->max_cpu + 1;
>  	char tstr[64];
> +	char nstr[30];
>  	u64 wait_time;
>  
>  	timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
> @@ -1937,7 +1942,13 @@ static void timehist_print_sample(struct perf_sched *sched,
>  	if (sched->show_state)
>  		printf(" %5c ", task_state_char(thread, state));
>  
> -	if (sched->show_wakeups)
> +	if (sched->show_next) {
> +		snprintf(nstr, sizeof(nstr), "next: %s[%d]", next_comm,
> +			next_pid);
> +		printf(" %-*s", comm_width, nstr);
> +	}
> +
> +	if (sched->show_wakeups && !sched->show_next)
>  		printf("  %-*s", comm_width, "");
>  
>  	if (thread->tid == 0)
> @@ -2531,7 +2542,8 @@ static int timehist_sched_change_event(struct perf_tool *tool,
>  	}
>  
>  	if (!sched->summary_only)
> -		timehist_print_sample(sched, sample, &al, thread, t, state);
> +		timehist_print_sample(sched, evsel, sample, &al, thread, t,
> +				      state);
>  
>  out:
>  	if (sched->hist_time.start == 0 && t >= ptime->start)
> @@ -3340,6 +3352,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
>  	OPT_BOOLEAN('S', "with-summary", &sched.summary,
>  		    "Show all syscalls and summary with statistics"),
>  	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
> +	OPT_BOOLEAN('n', "next", &sched.show_next, "Show next task"),
>  	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"),
> @@ -3437,10 +3450,16 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
>  			if (argc)
>  				usage_with_options(timehist_usage, timehist_options);
>  		}
> -		if (sched.show_wakeups && sched.summary_only) {
> -			pr_err(" Error: -s and -w are mutually exclusive.\n");
> +		if ((sched.show_wakeups || sched.show_next) &&
> +		    sched.summary_only) {
> +			pr_err(" Error: -s and -[n|w] are mutually exclusive.\n");
>  			parse_options_usage(timehist_usage, timehist_options, "s", true);
> -			parse_options_usage(NULL, timehist_options, "w", true);
> +			if (sched.show_wakeups)
> +				parse_options_usage(NULL, timehist_options, "w",
> +						    true);
> +			if (sched.show_next)
> +				parse_options_usage(NULL, timehist_options, "n",
> +						    true);
>  			return -EINVAL;
>  		}
>  
> -- 
> 2.7.4

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

* Re: [PATCH] perf sched timehist: Add --next option
  2017-03-14 13:12 ` Arnaldo Carvalho de Melo
@ 2017-03-15  0:39   ` Brendan Gregg
  0 siblings, 0 replies; 4+ messages in thread
From: Brendan Gregg @ 2017-03-15  0:39 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: Peter Zijlstra, Ingo Molnar, Alexander Shishkin, linux-kernel,
	Namhyung Kim

On Tue, Mar 14, 2017 at 6:12 AM, Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
> Em Tue, Mar 14, 2017 at 01:56:29AM +0000, Brendan Gregg escreveu:
>> The --next option shows the next task for each context switch, providing
>> more context for the sequence of scheduler events.
>>
>> $ perf sched timehist --next | head
>> Samples do not have callchains.
>>            time    cpu  task name                       wait time  sch delay   run time
>>                         [tid/pid]                          (msec)     (msec)     (msec)
>> --------------- ------  ------------------------------  ---------  ---------  ---------
>
> Thanks, applied.
>
> Minor request: when printing tool output in the cset comment, please add
> two spaces before all lines, my git-am scripts get confused with that
> --- thinking its a separator.

Ok, will do in the future, thanks Arnaldo!

Brendan

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

* [tip:perf/core] perf sched timehist: Add --next option
  2017-03-14  1:56 [PATCH] perf sched timehist: Add --next option Brendan Gregg
  2017-03-14 13:12 ` Arnaldo Carvalho de Melo
@ 2017-03-15 18:41 ` tip-bot for Brendan Gregg
  1 sibling, 0 replies; 4+ messages in thread
From: tip-bot for Brendan Gregg @ 2017-03-15 18:41 UTC (permalink / raw)
  To: linux-tip-commits
  Cc: acme, linux-kernel, mingo, peterz, namhyung, alexander.shishkin,
	hpa, tglx, bgregg

Commit-ID:  292c4a8f985b35b3738d5900fe256c4fed4cd3f5
Gitweb:     http://git.kernel.org/tip/292c4a8f985b35b3738d5900fe256c4fed4cd3f5
Author:     Brendan Gregg <bgregg@netflix.com>
AuthorDate: Tue, 14 Mar 2017 01:56:29 +0000
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 14 Mar 2017 15:17:38 -0300

perf sched timehist: Add --next option

The --next option shows the next task for each context switch, providing
more context for the sequence of scheduler events.

  $ perf sched timehist --next | head
  Samples do not have callchains.
       time  cpu task name  waittime schdelay run time
                 [tid/pid]     (msec) (msec) (msec)
  ---------- --- ---------- --------- ------ -----
  374.793792 [0] <idle>         0.000  0.000 0.000 next: rngd[1524]
  374.793801 [0] rngd[1524]     0.000  0.000 0.009 next: swapper/0[0]
  374.794048 [7] <idle>         0.000  0.000 0.000 next: yes[30884]
  374.794066 [7] yes[30884]     0.000  0.000 0.018 next: swapper/7[0]
  374.794126 [2] <idle>         0.000  0.000 0.000 next: rngd[1524]
  374.794140 [2] rngd[1524]     0.325  0.006 0.013 next: swapper/2[0]
  374.794281 [3] <idle>         0.000  0.000 0.000 next: perf[31070]

Signed-off-by: Brendan Gregg <bgregg@netflix.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1489456589-32555-1-git-send-email-bgregg@netflix.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/Documentation/perf-sched.txt |  4 ++++
 tools/perf/builtin-sched.c              | 25 ++++++++++++++++++++-----
 2 files changed, 24 insertions(+), 5 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index d33dedd..a092a24 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.
 
+-n::
+--next::
+	Show next task.
+
 -I::
 --idle-hist::
 	Show idle-related events only.
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 16170e9..b92c4d9 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -221,6 +221,7 @@ struct perf_sched {
 	unsigned int	max_stack;
 	bool		show_cpu_visual;
 	bool		show_wakeups;
+	bool		show_next;
 	bool		show_migrations;
 	bool		show_state;
 	u64		skipped_samples;
@@ -1897,14 +1898,18 @@ static char task_state_char(struct thread *thread, int state)
 }
 
 static void timehist_print_sample(struct perf_sched *sched,
+				  struct perf_evsel *evsel,
 				  struct perf_sample *sample,
 				  struct addr_location *al,
 				  struct thread *thread,
 				  u64 t, int state)
 {
 	struct thread_runtime *tr = thread__priv(thread);
+	const char *next_comm = perf_evsel__strval(evsel, sample, "next_comm");
+	const u32 next_pid = perf_evsel__intval(evsel, sample, "next_pid");
 	u32 max_cpus = sched->max_cpu + 1;
 	char tstr[64];
+	char nstr[30];
 	u64 wait_time;
 
 	timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
@@ -1937,7 +1942,12 @@ static void timehist_print_sample(struct perf_sched *sched,
 	if (sched->show_state)
 		printf(" %5c ", task_state_char(thread, state));
 
-	if (sched->show_wakeups)
+	if (sched->show_next) {
+		snprintf(nstr, sizeof(nstr), "next: %s[%d]", next_comm, next_pid);
+		printf(" %-*s", comm_width, nstr);
+	}
+
+	if (sched->show_wakeups && !sched->show_next)
 		printf("  %-*s", comm_width, "");
 
 	if (thread->tid == 0)
@@ -2531,7 +2541,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
 	}
 
 	if (!sched->summary_only)
-		timehist_print_sample(sched, sample, &al, thread, t, state);
+		timehist_print_sample(sched, evsel, sample, &al, thread, t, state);
 
 out:
 	if (sched->hist_time.start == 0 && t >= ptime->start)
@@ -3341,6 +3351,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 	OPT_BOOLEAN('S', "with-summary", &sched.summary,
 		    "Show all syscalls and summary with statistics"),
 	OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
+	OPT_BOOLEAN('n', "next", &sched.show_next, "Show next task"),
 	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"),
@@ -3438,10 +3449,14 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
 			if (argc)
 				usage_with_options(timehist_usage, timehist_options);
 		}
-		if (sched.show_wakeups && sched.summary_only) {
-			pr_err(" Error: -s and -w are mutually exclusive.\n");
+		if ((sched.show_wakeups || sched.show_next) &&
+		    sched.summary_only) {
+			pr_err(" Error: -s and -[n|w] are mutually exclusive.\n");
 			parse_options_usage(timehist_usage, timehist_options, "s", true);
-			parse_options_usage(NULL, timehist_options, "w", true);
+			if (sched.show_wakeups)
+				parse_options_usage(NULL, timehist_options, "w", true);
+			if (sched.show_next)
+				parse_options_usage(NULL, timehist_options, "n", true);
 			return -EINVAL;
 		}
 

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

end of thread, other threads:[~2017-03-15 18:43 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-03-14  1:56 [PATCH] perf sched timehist: Add --next option Brendan Gregg
2017-03-14 13:12 ` Arnaldo Carvalho de Melo
2017-03-15  0:39   ` Brendan Gregg
2017-03-15 18:41 ` [tip:perf/core] " tip-bot for Brendan Gregg

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