From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753580AbcLHOth (ORCPT ); Thu, 8 Dec 2016 09:49:37 -0500 Received: from mail-pf0-f195.google.com ([209.85.192.195]:33388 "EHLO mail-pf0-f195.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753492AbcLHOta (ORCPT ); Thu, 8 Dec 2016 09:49:30 -0500 From: Namhyung Kim To: Arnaldo Carvalho de Melo Cc: Ingo Molnar , Peter Zijlstra , Jiri Olsa , LKML , David Ahern , Andi Kleen , Minchan Kim Subject: [PATCH v2 6/6] perf sched timehist: Show callchains for idle stat Date: Thu, 8 Dec 2016 23:47:55 +0900 Message-Id: <20161208144755.16673-7-namhyung@kernel.org> X-Mailer: git-send-email 2.10.1 In-Reply-To: <20161208144755.16673-1-namhyung@kernel.org> References: <20161208144755.16673-1-namhyung@kernel.org> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 ... Signed-off-by: Namhyung Kim --- tools/perf/builtin-sched.c | 86 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 86 insertions(+) diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c index 6dc9e00d6392..724134203632 100644 --- a/tools/perf/builtin-sched.c +++ b/tools/perf/builtin-sched.c @@ -2438,6 +2438,9 @@ static int timehist_sched_change_event(struct perf_tool *tool, goto out; timehist_update_runtime_stats(last_tr, t, tprev); + if (itr->cursor.nr) + callchain_append(&itr->callchain, &itr->cursor, + t - tprev); itr->last_thread = NULL; } @@ -2548,6 +2551,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) { @@ -2606,6 +2663,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" -- 2.10.1