From 587782c52a83b35673201fd9a54364fa2b189b33 Mon Sep 17 00:00:00 2001 From: Namhyung Kim Date: Fri, 13 Jan 2017 19:45:23 +0900 Subject: [PATCH] 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 Signed-off-by: Namhyung Kim Tested-by: Arnaldo Carvalho de Melo Cc: David Ahern Cc: Jiri Olsa Cc: Minchan Kim Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/20170113104523.31212-3-namhyung@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- 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 a8ac76602187..daceb3202200 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.45.2