* [PATCH 2/3] perf sched timehist: Add --state option
2017-01-13 10:45 [PATCH 1/3] perf sched timehist: Account thread wait time separately Namhyung Kim
@ 2017-01-13 10:45 ` Namhyung Kim
2017-01-18 9:24 ` [tip:perf/core] " tip-bot for Namhyung Kim
2017-01-13 10:45 ` [PATCH 3/3] perf sched timehist: Show total wait times for summary Namhyung Kim
` (3 subsequent siblings)
4 siblings, 1 reply; 8+ messages in thread
From: Namhyung Kim @ 2017-01-13 10:45 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Minchan Kim, David Ahern
The --state option is to show task state when switched out. The state
is printed as a single character like in the /proc but I added 'I' for
idle state rather than 'R'.
$ perf sched timehist --state | head
Samples do not have callchains.
time cpu task name wait time sch delay run time state
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------------------------ --------- --------- --------- -----
197731.753791 [0003] <idle> 0.000 0.000 0.000 I
197731.753834 [0001] perf[27469] 0.000 0.000 0.000 S
197731.753904 [0003] perf[27470] 0.000 0.006 0.112 S
197731.753914 [0001] <idle> 0.000 0.000 0.079 I
197731.753915 [0003] migration/3[23] 0.000 0.002 0.011 S
197731.754287 [0002] <idle> 0.000 0.000 0.000 I
197731.754335 [0002] transmission-gt[17773/17739] 0.000 0.004 0.047 S
Cc: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/Documentation/perf-sched.txt | 2 ++
tools/perf/builtin-sched.c | 38 +++++++++++++++++++++++++++++----
2 files changed, 36 insertions(+), 4 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 76173969ab80..d33deddb0146 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -143,6 +143,8 @@ OPTIONS for 'perf sched timehist'
stop time is not given (i.e, time string is 'x.y,') then analysis goes
to end of file.
+--state::
+ Show task state when it switched out.
SEE ALSO
--------
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 0f2fdeebfd2e..ec51494e660b 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -222,6 +222,7 @@ struct perf_sched {
bool show_cpu_visual;
bool show_wakeups;
bool show_migrations;
+ bool show_state;
u64 skipped_samples;
const char *time_str;
struct perf_time_interval ptime;
@@ -1840,6 +1841,9 @@ static void timehist_header(struct perf_sched *sched)
printf(" %-*s %9s %9s %9s", comm_width,
"task name", "wait time", "sch delay", "run time");
+ if (sched->show_state)
+ printf(" %s", "state");
+
printf("\n");
/*
@@ -1850,9 +1854,14 @@ static void timehist_header(struct perf_sched *sched)
if (sched->show_cpu_visual)
printf(" %*s ", ncpus, "");
- printf(" %-*s %9s %9s %9s\n", comm_width,
+ printf(" %-*s %9s %9s %9s", comm_width,
"[tid/pid]", "(msec)", "(msec)", "(msec)");
+ if (sched->show_state)
+ printf(" %5s", "");
+
+ printf("\n");
+
/*
* separator
*/
@@ -1865,14 +1874,29 @@ static void timehist_header(struct perf_sched *sched)
graph_dotted_line, graph_dotted_line, graph_dotted_line,
graph_dotted_line);
+ if (sched->show_state)
+ printf(" %.5s", graph_dotted_line);
+
printf("\n");
}
+static char task_state_char(struct thread *thread, int state)
+{
+ static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
+ unsigned bit = state ? ffs(state) : 0;
+
+ /* 'I' for idle */
+ if (thread->tid == 0)
+ return 'I';
+
+ return bit < sizeof(state_to_char) - 1 ? state_to_char[bit] : '?';
+}
+
static void timehist_print_sample(struct perf_sched *sched,
struct perf_sample *sample,
struct addr_location *al,
struct thread *thread,
- u64 t)
+ u64 t, int state)
{
struct thread_runtime *tr = thread__priv(thread);
u32 max_cpus = sched->max_cpu + 1;
@@ -1906,6 +1930,9 @@ static void timehist_print_sample(struct perf_sched *sched,
print_sched_time(tr->dt_delay, 6);
print_sched_time(tr->dt_run, 6);
+ if (sched->show_state)
+ printf(" %5c ", task_state_char(thread, state));
+
if (sched->show_wakeups)
printf(" %-*s", comm_width, "");
@@ -2406,6 +2433,8 @@ static int timehist_sched_change_event(struct perf_tool *tool,
struct thread_runtime *tr = NULL;
u64 tprev, t = sample->time;
int rc = 0;
+ int state = perf_evsel__intval(evsel, sample, "prev_state");
+
if (machine__resolve(machine, &al, sample) < 0) {
pr_err("problem processing %d event. skipping it\n",
@@ -2493,7 +2522,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
}
if (!sched->summary_only)
- timehist_print_sample(sched, sample, &al, thread, t);
+ timehist_print_sample(sched, sample, &al, thread, t, state);
out:
if (sched->hist_time.start == 0 && t >= ptime->start)
@@ -2506,7 +2535,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
tr->last_time = sample->time;
/* last state is used to determine where to account wait time */
- tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
+ tr->last_state = state;
/* sched out event for task so reset ready to run time */
tr->ready_to_run = 0;
@@ -3278,6 +3307,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
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_BOOLEAN(0, "state", &sched.show_state, "Show task state when sched-out"),
OPT_PARENT(sched_options)
};
--
2.11.0
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [tip:perf/core] perf sched timehist: Add --state option
2017-01-13 10:45 ` [PATCH 2/3] perf sched timehist: Add --state option Namhyung Kim
@ 2017-01-18 9:24 ` tip-bot for Namhyung Kim
0 siblings, 0 replies; 8+ messages in thread
From: tip-bot for Namhyung Kim @ 2017-01-18 9:24 UTC (permalink / raw)
To: linux-tip-commits
Cc: minchan, acme, jolsa, tglx, mingo, dsahern, peterz, linux-kernel,
hpa, namhyung
Commit-ID: 414e050c68ec2a3dd815544ea48ff6016f1a7a11
Gitweb: http://git.kernel.org/tip/414e050c68ec2a3dd815544ea48ff6016f1a7a11
Author: Namhyung Kim <namhyung@kernel.org>
AuthorDate: Fri, 13 Jan 2017 19:45:22 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 17 Jan 2017 11:36:44 -0300
perf sched timehist: Add --state option
The --state option is to show task state when switched out. The state
is printed as a single character like in the /proc but I added 'I' for
idle state rather than 'R'.
$ perf sched timehist --state | head
Samples do not have callchains.
time cpu task name wait time sch delay run time state
[tid/pid] (msec) (msec) (msec)
-------- --- ----------------------- -------- ------------------ -----
1.753791 [3] <idle> 0.000 0.000 0.000 I
1.753834 [1] perf[27469] 0.000 0.000 0.000 S
1.753904 [3] perf[27470] 0.000 0.006 0.112 S
1.753914 [1] <idle> 0.000 0.000 0.079 I
1.753915 [3] migration/3[23] 0.000 0.002 0.011 S
1.754287 [2] <idle> 0.000 0.000 0.000 I
1.754335 [2] transmission[1773/1739] 0.000 0.004 0.047 S
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Minchan Kim <minchan@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20170113104523.31212-2-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/Documentation/perf-sched.txt | 2 ++
tools/perf/builtin-sched.c | 38 +++++++++++++++++++++++++++++----
2 files changed, 36 insertions(+), 4 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 7617396..d33dedd 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -143,6 +143,8 @@ OPTIONS for 'perf sched timehist'
stop time is not given (i.e, time string is 'x.y,') then analysis goes
to end of file.
+--state::
+ Show task state when it switched out.
SEE ALSO
--------
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 6d3c3e8..a8ac766 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -222,6 +222,7 @@ struct perf_sched {
bool show_cpu_visual;
bool show_wakeups;
bool show_migrations;
+ bool show_state;
u64 skipped_samples;
const char *time_str;
struct perf_time_interval ptime;
@@ -1840,6 +1841,9 @@ static void timehist_header(struct perf_sched *sched)
printf(" %-*s %9s %9s %9s", comm_width,
"task name", "wait time", "sch delay", "run time");
+ if (sched->show_state)
+ printf(" %s", "state");
+
printf("\n");
/*
@@ -1850,9 +1854,14 @@ static void timehist_header(struct perf_sched *sched)
if (sched->show_cpu_visual)
printf(" %*s ", ncpus, "");
- printf(" %-*s %9s %9s %9s\n", comm_width,
+ printf(" %-*s %9s %9s %9s", comm_width,
"[tid/pid]", "(msec)", "(msec)", "(msec)");
+ if (sched->show_state)
+ printf(" %5s", "");
+
+ printf("\n");
+
/*
* separator
*/
@@ -1865,14 +1874,29 @@ static void timehist_header(struct perf_sched *sched)
graph_dotted_line, graph_dotted_line, graph_dotted_line,
graph_dotted_line);
+ if (sched->show_state)
+ printf(" %.5s", graph_dotted_line);
+
printf("\n");
}
+static char task_state_char(struct thread *thread, int state)
+{
+ static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;
+ unsigned bit = state ? ffs(state) : 0;
+
+ /* 'I' for idle */
+ if (thread->tid == 0)
+ return 'I';
+
+ return bit < sizeof(state_to_char) - 1 ? state_to_char[bit] : '?';
+}
+
static void timehist_print_sample(struct perf_sched *sched,
struct perf_sample *sample,
struct addr_location *al,
struct thread *thread,
- u64 t)
+ u64 t, int state)
{
struct thread_runtime *tr = thread__priv(thread);
u32 max_cpus = sched->max_cpu + 1;
@@ -1906,6 +1930,9 @@ static void timehist_print_sample(struct perf_sched *sched,
print_sched_time(tr->dt_delay, 6);
print_sched_time(tr->dt_run, 6);
+ if (sched->show_state)
+ printf(" %5c ", task_state_char(thread, state));
+
if (sched->show_wakeups)
printf(" %-*s", comm_width, "");
@@ -2406,6 +2433,8 @@ static int timehist_sched_change_event(struct perf_tool *tool,
struct thread_runtime *tr = NULL;
u64 tprev, t = sample->time;
int rc = 0;
+ int state = perf_evsel__intval(evsel, sample, "prev_state");
+
if (machine__resolve(machine, &al, sample) < 0) {
pr_err("problem processing %d event. skipping it\n",
@@ -2493,7 +2522,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
}
if (!sched->summary_only)
- timehist_print_sample(sched, sample, &al, thread, t);
+ timehist_print_sample(sched, sample, &al, thread, t, state);
out:
if (sched->hist_time.start == 0 && t >= ptime->start)
@@ -2506,7 +2535,7 @@ out:
tr->last_time = sample->time;
/* last state is used to determine where to account wait time */
- tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
+ tr->last_state = state;
/* sched out event for task so reset ready to run time */
tr->ready_to_run = 0;
@@ -3278,6 +3307,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
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_BOOLEAN(0, "state", &sched.show_state, "Show task state when sched-out"),
OPT_PARENT(sched_options)
};
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [PATCH 3/3] perf sched timehist: Show total wait times for summary
2017-01-13 10:45 [PATCH 1/3] perf sched timehist: Account thread wait time separately Namhyung Kim
2017-01-13 10:45 ` [PATCH 2/3] perf sched timehist: Add --state option Namhyung Kim
@ 2017-01-13 10:45 ` Namhyung Kim
2017-01-18 9:24 ` [tip:perf/core] " tip-bot for Namhyung Kim
2017-01-13 19:35 ` [PATCH 1/3] perf sched timehist: Account thread wait time separately Arnaldo Carvalho de Melo
` (2 subsequent siblings)
4 siblings, 1 reply; 8+ messages in thread
From: Namhyung Kim @ 2017-01-13 10:45 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Minchan Kim, David Ahern
When --state option is given, the summary will show total run, sleep,
iowait, preempt and delay time instead of statistics of runtime.
$ perf sched timehist -s --state
Wait-time summary
comm parent sched-in run-time sleep iowait preempt delay
(count) (msec) (msec) (msec) (msec) (msec)
---------------------------------------------------------------------------------------------------------------------
systemd[1] 0 3 0.497 1.685 0.000 0.000 0.061
ksoftirqd/0[3] 2 21 0.434 989.948 0.000 0.000 0.325
rcu_preempt[7] 2 28 0.386 993.211 0.000 0.000 0.712
migration/0[10] 2 12 0.126 50.174 0.000 0.000 0.044
watchdog/0[11] 2 1 0.009 0.000 0.000 0.000 0.016
migration/1[13] 2 2 0.029 11.755 0.000 0.000 0.007
<SNIP>
Cc: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 44 +++++++++++++++++++++++++++++++++++++++++---
1 file changed, 41 insertions(+), 3 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index ec51494e660b..abc58851452b 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -241,6 +241,10 @@ struct thread_runtime {
struct stats run_stats;
u64 total_run_time;
+ u64 total_sleep_time;
+ u64 total_iowait_time;
+ u64 total_preempt_time;
+ u64 total_delay_time;
int last_state;
u64 migrations;
@@ -2008,7 +2012,12 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
}
update_stats(&r->run_stats, r->dt_run);
- r->total_run_time += r->dt_run;
+
+ r->total_run_time += r->dt_run;
+ r->total_delay_time += r->dt_delay;
+ r->total_sleep_time += r->dt_sleep;
+ r->total_iowait_time += r->dt_iowait;
+ r->total_preempt_time += r->dt_preempt;
}
static bool is_idle_sample(struct perf_sample *sample,
@@ -2593,7 +2602,26 @@ static void print_thread_runtime(struct thread *t,
printf("\n");
}
+static void print_thread_waittime(struct thread *t,
+ struct thread_runtime *r)
+{
+ printf("%*s %5d %9" PRIu64 " ",
+ comm_width, timehist_get_commstr(t), t->ppid,
+ (u64) r->run_stats.n);
+
+ print_sched_time(r->total_run_time, 8);
+ print_sched_time(r->total_sleep_time, 6);
+ printf(" ");
+ print_sched_time(r->total_iowait_time, 6);
+ printf(" ");
+ print_sched_time(r->total_preempt_time, 6);
+ printf(" ");
+ print_sched_time(r->total_delay_time, 6);
+ printf("\n");
+}
+
struct total_run_stats {
+ struct perf_sched *sched;
u64 sched_count;
u64 task_count;
u64 total_run_time;
@@ -2612,7 +2640,11 @@ static int __show_thread_runtime(struct thread *t, void *priv)
stats->task_count++;
stats->sched_count += r->run_stats.n;
stats->total_run_time += r->total_run_time;
- print_thread_runtime(t, r);
+
+ if (stats->sched->show_state)
+ print_thread_waittime(t, r);
+ else
+ print_thread_runtime(t, r);
}
return 0;
@@ -2700,18 +2732,24 @@ static void timehist_print_summary(struct perf_sched *sched,
u64 hist_time = sched->hist_time.end - sched->hist_time.start;
memset(&totals, 0, sizeof(totals));
+ totals.sched = sched;
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 if (sched->show_state) {
+ printf("\nWait-time summary\n");
+ printf("%*s parent sched-in ", comm_width, "comm");
+ printf(" run-time sleep iowait preempt delay\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(" (msec) (msec) (msec) (msec) %s\n",
+ sched->show_state ? "(msec)" : "%");
printf("%.117s\n", graph_dotted_line);
machine__for_each_thread(m, show_thread_runtime, &totals);
--
2.11.0
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [tip:perf/core] perf sched timehist: Show total wait times for summary
2017-01-13 10:45 ` [PATCH 3/3] perf sched timehist: Show total wait times for summary Namhyung Kim
@ 2017-01-18 9:24 ` tip-bot for Namhyung Kim
0 siblings, 0 replies; 8+ messages in thread
From: tip-bot for Namhyung Kim @ 2017-01-18 9:24 UTC (permalink / raw)
To: linux-tip-commits
Cc: tglx, mingo, namhyung, dsahern, minchan, jolsa, linux-kernel,
acme, peterz, hpa
Commit-ID: 587782c52a83b35673201fd9a54364fa2b189b33
Gitweb: http://git.kernel.org/tip/587782c52a83b35673201fd9a54364fa2b189b33
Author: Namhyung Kim <namhyung@kernel.org>
AuthorDate: Fri, 13 Jan 2017 19:45:23 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 17 Jan 2017 11:36:44 -0300
perf sched timehist: Show total wait times for summary
When --state option is given, the summary will show total run, sleep,
iowait, preempt and delay time instead of statistics of runtime.
$ perf sched timehist -s --state
Wait-time summary
comm parent sched-in run-time sleep iowait preempt delay
(count) (msec) (msec) (msec) (msec) (msec)
---------------------------------------------------------------------
systemd[1] 0 3 0.497 1.685 0.000 0.000 0.061
ksoftirqd/0[3] 2 21 0.434 989.948 0.000 0.000 0.325
rcu_preempt[7] 2 28 0.386 993.211 0.000 0.000 0.712
migration/0[10] 2 12 0.126 50.174 0.000 0.000 0.044
watchdog/0[11] 2 1 0.009 0.000 0.000 0.000 0.016
migration/1[13] 2 2 0.029 11.755 0.000 0.000 0.007
<SNIP>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Minchan Kim <minchan@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20170113104523.31212-3-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/builtin-sched.c | 44 +++++++++++++++++++++++++++++++++++++++++---
1 file changed, 41 insertions(+), 3 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index a8ac766..daceb32 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -241,6 +241,10 @@ struct thread_runtime {
struct stats run_stats;
u64 total_run_time;
+ u64 total_sleep_time;
+ u64 total_iowait_time;
+ u64 total_preempt_time;
+ u64 total_delay_time;
int last_state;
u64 migrations;
@@ -2008,7 +2012,12 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
}
update_stats(&r->run_stats, r->dt_run);
- r->total_run_time += r->dt_run;
+
+ r->total_run_time += r->dt_run;
+ r->total_delay_time += r->dt_delay;
+ r->total_sleep_time += r->dt_sleep;
+ r->total_iowait_time += r->dt_iowait;
+ r->total_preempt_time += r->dt_preempt;
}
static bool is_idle_sample(struct perf_sample *sample,
@@ -2593,7 +2602,26 @@ static void print_thread_runtime(struct thread *t,
printf("\n");
}
+static void print_thread_waittime(struct thread *t,
+ struct thread_runtime *r)
+{
+ printf("%*s %5d %9" PRIu64 " ",
+ comm_width, timehist_get_commstr(t), t->ppid,
+ (u64) r->run_stats.n);
+
+ print_sched_time(r->total_run_time, 8);
+ print_sched_time(r->total_sleep_time, 6);
+ printf(" ");
+ print_sched_time(r->total_iowait_time, 6);
+ printf(" ");
+ print_sched_time(r->total_preempt_time, 6);
+ printf(" ");
+ print_sched_time(r->total_delay_time, 6);
+ printf("\n");
+}
+
struct total_run_stats {
+ struct perf_sched *sched;
u64 sched_count;
u64 task_count;
u64 total_run_time;
@@ -2612,7 +2640,11 @@ static int __show_thread_runtime(struct thread *t, void *priv)
stats->task_count++;
stats->sched_count += r->run_stats.n;
stats->total_run_time += r->total_run_time;
- print_thread_runtime(t, r);
+
+ if (stats->sched->show_state)
+ print_thread_waittime(t, r);
+ else
+ print_thread_runtime(t, r);
}
return 0;
@@ -2700,18 +2732,24 @@ static void timehist_print_summary(struct perf_sched *sched,
u64 hist_time = sched->hist_time.end - sched->hist_time.start;
memset(&totals, 0, sizeof(totals));
+ totals.sched = sched;
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 if (sched->show_state) {
+ printf("\nWait-time summary\n");
+ printf("%*s parent sched-in ", comm_width, "comm");
+ printf(" run-time sleep iowait preempt delay\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(" (msec) (msec) (msec) (msec) %s\n",
+ sched->show_state ? "(msec)" : "%");
printf("%.117s\n", graph_dotted_line);
machine__for_each_thread(m, show_thread_runtime, &totals);
^ permalink raw reply related [flat|nested] 8+ messages in thread
* Re: [PATCH 1/3] perf sched timehist: Account thread wait time separately
2017-01-13 10:45 [PATCH 1/3] perf sched timehist: Account thread wait time separately Namhyung Kim
2017-01-13 10:45 ` [PATCH 2/3] perf sched timehist: Add --state option Namhyung Kim
2017-01-13 10:45 ` [PATCH 3/3] perf sched timehist: Show total wait times for summary Namhyung Kim
@ 2017-01-13 19:35 ` Arnaldo Carvalho de Melo
2017-01-17 14:39 ` Arnaldo Carvalho de Melo
2017-01-18 9:23 ` [tip:perf/core] " tip-bot for Namhyung Kim
4 siblings, 0 replies; 8+ messages in thread
From: Arnaldo Carvalho de Melo @ 2017-01-13 19:35 UTC (permalink / raw)
To: Namhyung Kim
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Minchan Kim, David Ahern
Em Fri, Jan 13, 2017 at 07:45:21PM +0900, Namhyung Kim escreveu:
> Separate thread wait time into 3 parts - sleep, iowait and preempt
> based on the prev_state of the last event.
Thanks, looks good, tested and applied,
- Arnaldo
> Cc: David Ahern <dsahern@gmail.com>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
> tools/perf/builtin-sched.c | 50 ++++++++++++++++++++++++++++++++++++++++------
> 1 file changed, 44 insertions(+), 6 deletions(-)
>
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 5b134b0d1ff3..0f2fdeebfd2e 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -77,6 +77,22 @@ struct sched_atom {
>
> #define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
>
> +/* task state bitmask, copied from include/linux/sched.h */
> +#define TASK_RUNNING 0
> +#define TASK_INTERRUPTIBLE 1
> +#define TASK_UNINTERRUPTIBLE 2
> +#define __TASK_STOPPED 4
> +#define __TASK_TRACED 8
> +/* in tsk->exit_state */
> +#define EXIT_DEAD 16
> +#define EXIT_ZOMBIE 32
> +#define EXIT_TRACE (EXIT_ZOMBIE | EXIT_DEAD)
> +/* in tsk->state again */
> +#define TASK_DEAD 64
> +#define TASK_WAKEKILL 128
> +#define TASK_WAKING 256
> +#define TASK_PARKED 512
> +
> enum thread_state {
> THREAD_SLEEPING = 0,
> THREAD_WAIT_CPU,
> @@ -216,13 +232,16 @@ struct perf_sched {
> struct thread_runtime {
> u64 last_time; /* time of previous sched in/out event */
> u64 dt_run; /* run time */
> - u64 dt_wait; /* time between CPU access (off cpu) */
> + u64 dt_sleep; /* time between CPU access by sleep (off cpu) */
> + u64 dt_iowait; /* time between CPU access by iowait (off cpu) */
> + u64 dt_preempt; /* time between CPU access by preempt (off cpu) */
> u64 dt_delay; /* time between wakeup and sched-in */
> u64 ready_to_run; /* time of wakeup */
>
> struct stats run_stats;
> u64 total_run_time;
>
> + int last_state;
> u64 migrations;
> };
>
> @@ -1858,6 +1877,7 @@ static void timehist_print_sample(struct perf_sched *sched,
> struct thread_runtime *tr = thread__priv(thread);
> u32 max_cpus = sched->max_cpu + 1;
> char tstr[64];
> + u64 wait_time;
>
> timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
> printf("%15s [%04d] ", tstr, sample->cpu);
> @@ -1880,7 +1900,9 @@ static void timehist_print_sample(struct perf_sched *sched,
>
> printf(" %-*s ", comm_width, timehist_get_commstr(thread));
>
> - print_sched_time(tr->dt_wait, 6);
> + wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
> + print_sched_time(wait_time, 6);
> +
> print_sched_time(tr->dt_delay, 6);
> print_sched_time(tr->dt_run, 6);
>
> @@ -1930,8 +1952,11 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
> u64 t, u64 tprev)
> {
> r->dt_delay = 0;
> - r->dt_wait = 0;
> + r->dt_sleep = 0;
> + r->dt_iowait = 0;
> + r->dt_preempt = 0;
> r->dt_run = 0;
> +
> if (tprev) {
> r->dt_run = t - tprev;
> if (r->ready_to_run) {
> @@ -1943,8 +1968,16 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
>
> if (r->last_time > tprev)
> pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
> - else if (r->last_time)
> - r->dt_wait = tprev - r->last_time;
> + else if (r->last_time) {
> + u64 wait = tprev - r->last_time;
> +
> + if (r->last_state == TASK_RUNNING)
> + r->dt_preempt = wait;
> + else if (r->last_state == TASK_UNINTERRUPTIBLE)
> + r->dt_iowait = wait;
> + else
> + r->dt_sleep = wait;
> + }
> }
>
> update_stats(&r->run_stats, r->dt_run);
> @@ -2447,8 +2480,10 @@ static int timehist_sched_change_event(struct perf_tool *tool,
> * 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;
> + last_tr->dt_sleep = 0;
> + last_tr->dt_iowait = 0;
> + last_tr->dt_preempt = 0;
>
> if (itr->cursor.nr)
> callchain_append(&itr->callchain, &itr->cursor, t - tprev);
> @@ -2470,6 +2505,9 @@ static int timehist_sched_change_event(struct perf_tool *tool,
> /* time of this sched_switch event becomes last time task seen */
> tr->last_time = sample->time;
>
> + /* last state is used to determine where to account wait time */
> + tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
> +
> /* sched out event for task so reset ready to run time */
> tr->ready_to_run = 0;
> }
> --
> 2.11.0
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [PATCH 1/3] perf sched timehist: Account thread wait time separately
2017-01-13 10:45 [PATCH 1/3] perf sched timehist: Account thread wait time separately Namhyung Kim
` (2 preceding siblings ...)
2017-01-13 19:35 ` [PATCH 1/3] perf sched timehist: Account thread wait time separately Arnaldo Carvalho de Melo
@ 2017-01-17 14:39 ` Arnaldo Carvalho de Melo
2017-01-18 9:23 ` [tip:perf/core] " tip-bot for Namhyung Kim
4 siblings, 0 replies; 8+ messages in thread
From: Arnaldo Carvalho de Melo @ 2017-01-17 14:39 UTC (permalink / raw)
To: Namhyung Kim
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Minchan Kim, David Ahern
Em Fri, Jan 13, 2017 at 07:45:21PM +0900, Namhyung Kim escreveu:
> @@ -1943,8 +1968,16 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
>
> if (r->last_time > tprev)
> pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
> - else if (r->last_time)
> - r->dt_wait = tprev - r->last_time;
> + else if (r->last_time) {
> + u64 wait = tprev - r->last_time;
> +
> + if (r->last_state == TASK_RUNNING)
> + r->dt_preempt = wait;
> + else if (r->last_state == TASK_UNINTERRUPTIBLE)
> + r->dt_iowait = wait;
> + else
> + r->dt_sleep = wait;
> + }
s/wait/dt_wait/g to fix the build on older distros where 'wait' shadows
a global declaration.
- Arnaldo
^ permalink raw reply [flat|nested] 8+ messages in thread
* [tip:perf/core] perf sched timehist: Account thread wait time separately
2017-01-13 10:45 [PATCH 1/3] perf sched timehist: Account thread wait time separately Namhyung Kim
` (3 preceding siblings ...)
2017-01-17 14:39 ` Arnaldo Carvalho de Melo
@ 2017-01-18 9:23 ` tip-bot for Namhyung Kim
4 siblings, 0 replies; 8+ messages in thread
From: tip-bot for Namhyung Kim @ 2017-01-18 9:23 UTC (permalink / raw)
To: linux-tip-commits
Cc: dsahern, peterz, namhyung, linux-kernel, minchan, acme, tglx,
jolsa, hpa, mingo
Commit-ID: 941bdea79e194dec7e7b42780aa5620020548f8a
Gitweb: http://git.kernel.org/tip/941bdea79e194dec7e7b42780aa5620020548f8a
Author: Namhyung Kim <namhyung@kernel.org>
AuthorDate: Fri, 13 Jan 2017 19:45:21 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 17 Jan 2017 11:35:44 -0300
perf sched timehist: Account thread wait time separately
Separate thread wait time into 3 parts - sleep, iowait and preempt based
on the prev_state of the last event.
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Minchan Kim <minchan@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20170113104523.31212-1-namhyung@kernel.org
[ Fix the build on centos:5 where 'wait' shadows a global declaration ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/builtin-sched.c | 50 ++++++++++++++++++++++++++++++++++++++++------
1 file changed, 44 insertions(+), 6 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 5b134b0..6d3c3e8 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -77,6 +77,22 @@ struct sched_atom {
#define TASK_STATE_TO_CHAR_STR "RSDTtZXxKWP"
+/* task state bitmask, copied from include/linux/sched.h */
+#define TASK_RUNNING 0
+#define TASK_INTERRUPTIBLE 1
+#define TASK_UNINTERRUPTIBLE 2
+#define __TASK_STOPPED 4
+#define __TASK_TRACED 8
+/* in tsk->exit_state */
+#define EXIT_DEAD 16
+#define EXIT_ZOMBIE 32
+#define EXIT_TRACE (EXIT_ZOMBIE | EXIT_DEAD)
+/* in tsk->state again */
+#define TASK_DEAD 64
+#define TASK_WAKEKILL 128
+#define TASK_WAKING 256
+#define TASK_PARKED 512
+
enum thread_state {
THREAD_SLEEPING = 0,
THREAD_WAIT_CPU,
@@ -216,13 +232,16 @@ struct perf_sched {
struct thread_runtime {
u64 last_time; /* time of previous sched in/out event */
u64 dt_run; /* run time */
- u64 dt_wait; /* time between CPU access (off cpu) */
+ u64 dt_sleep; /* time between CPU access by sleep (off cpu) */
+ u64 dt_iowait; /* time between CPU access by iowait (off cpu) */
+ u64 dt_preempt; /* time between CPU access by preempt (off cpu) */
u64 dt_delay; /* time between wakeup and sched-in */
u64 ready_to_run; /* time of wakeup */
struct stats run_stats;
u64 total_run_time;
+ int last_state;
u64 migrations;
};
@@ -1858,6 +1877,7 @@ static void timehist_print_sample(struct perf_sched *sched,
struct thread_runtime *tr = thread__priv(thread);
u32 max_cpus = sched->max_cpu + 1;
char tstr[64];
+ u64 wait_time;
timestamp__scnprintf_usec(t, tstr, sizeof(tstr));
printf("%15s [%04d] ", tstr, sample->cpu);
@@ -1880,7 +1900,9 @@ static void timehist_print_sample(struct perf_sched *sched,
printf(" %-*s ", comm_width, timehist_get_commstr(thread));
- print_sched_time(tr->dt_wait, 6);
+ wait_time = tr->dt_sleep + tr->dt_iowait + tr->dt_preempt;
+ print_sched_time(wait_time, 6);
+
print_sched_time(tr->dt_delay, 6);
print_sched_time(tr->dt_run, 6);
@@ -1930,8 +1952,11 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
u64 t, u64 tprev)
{
r->dt_delay = 0;
- r->dt_wait = 0;
+ r->dt_sleep = 0;
+ r->dt_iowait = 0;
+ r->dt_preempt = 0;
r->dt_run = 0;
+
if (tprev) {
r->dt_run = t - tprev;
if (r->ready_to_run) {
@@ -1943,8 +1968,16 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
if (r->last_time > tprev)
pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
- else if (r->last_time)
- r->dt_wait = tprev - r->last_time;
+ else if (r->last_time) {
+ u64 dt_wait = tprev - r->last_time;
+
+ if (r->last_state == TASK_RUNNING)
+ r->dt_preempt = dt_wait;
+ else if (r->last_state == TASK_UNINTERRUPTIBLE)
+ r->dt_iowait = dt_wait;
+ else
+ r->dt_sleep = dt_wait;
+ }
}
update_stats(&r->run_stats, r->dt_run);
@@ -2447,8 +2480,10 @@ static int timehist_sched_change_event(struct perf_tool *tool,
* 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;
+ last_tr->dt_sleep = 0;
+ last_tr->dt_iowait = 0;
+ last_tr->dt_preempt = 0;
if (itr->cursor.nr)
callchain_append(&itr->callchain, &itr->cursor, t - tprev);
@@ -2470,6 +2505,9 @@ out:
/* time of this sched_switch event becomes last time task seen */
tr->last_time = sample->time;
+ /* last state is used to determine where to account wait time */
+ tr->last_state = perf_evsel__intval(evsel, sample, "prev_state");
+
/* sched out event for task so reset ready to run time */
tr->ready_to_run = 0;
}
^ permalink raw reply related [flat|nested] 8+ messages in thread