summaryrefslogtreecommitdiff
path: root/tools
diff options
context:
space:
mode:
authorNamhyung Kim <namhyung@kernel.org>2016-12-08 17:47:55 +0300
committerArnaldo Carvalho de Melo <acme@redhat.com>2016-12-15 22:25:45 +0300
commitba957ebb54893acaf3dc846031073a63f021cee1 (patch)
treee72750d32823abe28e86db5c58eb6f3ecb3b46a9 /tools
parent07235f84ece6b66f43334881806aad3467cf3d84 (diff)
downloadlinux-ba957ebb54893acaf3dc846031073a63f021cee1.tar.xz
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>
Diffstat (limited to 'tools')
-rw-r--r--tools/perf/builtin-sched.c86
1 files changed, 86 insertions, 0 deletions
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 0b14265432df..c1c07bfe132c 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"