Re: [PATCH] perf sched timehist: Add --next option
On Tue, Mar 14, 2017 at 6:12 AM, Arnaldo Carvalho de Melo wrote: > Em Tue, Mar 14, 2017 at 01:56:29AM +, 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. >>timecpu 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
Re: [PATCH] perf sched timehist: Add --next option
Em Tue, Mar 14, 2017 at 01:56:29AM +, 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.
>timecpu 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 []0.000 0.000
> 0.000 next: rngd[1524]
> 1136374.793801 [] rngd[1524] 0.000 0.000
> 0.009 next: swapper/0[0]
> 1136374.794048 [0007]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]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]0.000 0.000
> 0.000 next: perf[31070]
>
> Signed-off-by: Brendan Gregg
> ---
> 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 intmax_stack;
> boolshow_cpu_visual;
> boolshow_wakeups;
> + boolshow_next;
> boolshow_migrations;
> boolshow_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-vi
[PATCH] 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.
timecpu task name wait time sch delay
run time
[tid/pid] (msec) (msec)
(msec)
--- -- -- - -
-
1136374.793792 []0.000 0.000
0.000 next: rngd[1524]
1136374.793801 [] rngd[1524] 0.000 0.000
0.009 next: swapper/0[0]
1136374.794048 [0007]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]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]0.000 0.000
0.000 next: perf[31070]
Signed-off-by: Brendan Gregg
---
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 intmax_stack;
boolshow_cpu_visual;
boolshow_wakeups;
+ boolshow_next;
boolshow_migrations;
boolshow_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_wak
