From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756904AbcKXEUM (ORCPT ); Wed, 23 Nov 2016 23:20:12 -0500 Received: from terminus.zytor.com ([198.137.202.10]:49896 "EHLO terminus.zytor.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750749AbcKXEUK (ORCPT ); Wed, 23 Nov 2016 23:20:10 -0500 Date: Wed, 23 Nov 2016 20:19:55 -0800 From: tip-bot for David Ahern Message-ID: Cc: hpa@zytor.com, andi@firstfloor.org, acme@redhat.com, a.p.zijlstra@chello.nl, dsahern@gmail.com, mingo@kernel.org, jolsa@kernel.org, namhyung@kernel.org, linux-kernel@vger.kernel.org, eranian@google.com, tglx@linutronix.de Reply-To: hpa@zytor.com, acme@redhat.com, andi@firstfloor.org, a.p.zijlstra@chello.nl, dsahern@gmail.com, namhyung@kernel.org, jolsa@kernel.org, mingo@kernel.org, linux-kernel@vger.kernel.org, tglx@linutronix.de, eranian@google.com In-Reply-To: <20161116060634.28477-5-namhyung@kernel.org> References: <20161116060634.28477-5-namhyung@kernel.org> To: linux-tip-commits@vger.kernel.org Subject: [tip:perf/core] perf sched timehist: Add summary options Git-Commit-ID: 52df138caaa8daaaf4e0dc64428ef06f303a8dbf X-Mailer: tip-git-log-daemon Robot-ID: Robot-Unsubscribe: Contact to get blacklisted from these emails MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Content-Type: text/plain; charset=UTF-8 Content-Disposition: inline Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Commit-ID: 52df138caaa8daaaf4e0dc64428ef06f303a8dbf Gitweb: http://git.kernel.org/tip/52df138caaa8daaaf4e0dc64428ef06f303a8dbf Author: David Ahern AuthorDate: Wed, 16 Nov 2016 15:06:30 +0900 Committer: Arnaldo Carvalho de Melo CommitDate: Wed, 23 Nov 2016 10:44:08 -0300 perf sched timehist: Add summary options The -s/--summary option is to show process runtime statistics. And the -S/--with-summary option is to show the stats with the normal output. $ perf sched timehist -s Runtime summary comm parent sched-in run-time min-run avg-run max-run stddev (count) (msec) (msec) (msec) (msec) % --------------------------------------------------------------------------------------------------------- ksoftirqd/0[3] 2 2 0.011 0.004 0.005 0.006 14.87 rcu_preempt[7] 2 11 0.071 0.002 0.006 0.017 20.23 watchdog/0[11] 2 1 0.002 0.002 0.002 0.002 0.00 watchdog/1[12] 2 1 0.004 0.004 0.004 0.004 0.00 ... Terminated tasks: sleep[7220] 7219 3 0.770 0.087 0.256 0.576 62.28 Idle stats: CPU 0 idle for 2352.006 msec CPU 1 idle for 2764.497 msec CPU 2 idle for 2998.229 msec CPU 3 idle for 2967.800 msec Total number of unique tasks: 52 Total number of context switches: 2532 Total run time (msec): 218.036 Signed-off-by: David Ahern Signed-off-by: Namhyung Kim Acked-by: Ingo Molnar Acked-by: Jiri Olsa Tested-by: Arnaldo Carvalho de Melo Cc: Andi Kleen Cc: Peter Zijlstra Cc: Stephane Eranian Link: http://lkml.kernel.org/r/20161116060634.28477-5-namhyung@kernel.org [ Add documentation from last commit, so that docs comes with the cset that introduces the feature ] Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-sched.c | 166 +++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 160 insertions(+), 6 deletions(-) diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c index c0ac0c9..1e7d81a 100644 --- a/tools/perf/builtin-sched.c +++ b/tools/perf/builtin-sched.c @@ -194,6 +194,11 @@ struct perf_sched { bool force; bool skip_merge; struct perf_sched_map map; + + /* options for timehist command */ + bool summary; + bool summary_only; + u64 skipped_samples; }; /* per thread run time data */ @@ -2010,12 +2015,15 @@ static struct thread *timehist_get_thread(struct perf_sample *sample, return thread; } -static bool timehist_skip_sample(struct thread *thread) +static bool timehist_skip_sample(struct perf_sched *sched, + struct thread *thread) { bool rc = false; - if (thread__is_filtered(thread)) + if (thread__is_filtered(thread)) { rc = true; + sched->skipped_samples++; + } return rc; } @@ -2045,7 +2053,7 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused, return 0; } -static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused, +static int timehist_sched_change_event(struct perf_tool *tool, union perf_event *event, struct perf_evsel *evsel, struct perf_sample *sample, @@ -2056,6 +2064,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused, struct thread_runtime *tr = NULL; u64 tprev; int rc = 0; + struct perf_sched *sched = container_of(tool, struct perf_sched, tool); if (machine__resolve(machine, &al, sample) < 0) { pr_err("problem processing %d event. skipping it\n", @@ -2070,7 +2079,7 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused, goto out; } - if (timehist_skip_sample(thread)) + if (timehist_skip_sample(sched, thread)) goto out; tr = thread__get_runtime(thread); @@ -2082,7 +2091,8 @@ static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused, tprev = perf_evsel__get_time(evsel, sample->cpu); timehist_update_runtime_stats(tr, sample->time, tprev); - timehist_print_sample(sample, thread); + if (!sched->summary_only) + timehist_print_sample(sample, thread); out: if (tr) { @@ -2122,6 +2132,131 @@ static int process_lost(struct perf_tool *tool __maybe_unused, } +static void print_thread_runtime(struct thread *t, + struct thread_runtime *r) +{ + double mean = avg_stats(&r->run_stats); + float stddev; + + 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); + stddev = rel_stddev_stats(stddev_stats(&r->run_stats), mean); + print_sched_time(r->run_stats.min, 6); + printf(" "); + print_sched_time((u64) mean, 6); + printf(" "); + print_sched_time(r->run_stats.max, 6); + printf(" "); + printf("%5.2f", stddev); + printf("\n"); +} + +struct total_run_stats { + u64 sched_count; + u64 task_count; + u64 total_run_time; +}; + +static int __show_thread_runtime(struct thread *t, void *priv) +{ + struct total_run_stats *stats = priv; + struct thread_runtime *r; + + if (thread__is_filtered(t)) + return 0; + + r = thread__priv(t); + if (r && r->run_stats.n) { + stats->task_count++; + stats->sched_count += r->run_stats.n; + stats->total_run_time += r->total_run_time; + print_thread_runtime(t, r); + } + + return 0; +} + +static int show_thread_runtime(struct thread *t, void *priv) +{ + if (t->dead) + return 0; + + return __show_thread_runtime(t, priv); +} + +static int show_deadthread_runtime(struct thread *t, void *priv) +{ + if (!t->dead) + return 0; + + return __show_thread_runtime(t, priv); +} + +static void timehist_print_summary(struct perf_sched *sched, + struct perf_session *session) +{ + struct machine *m = &session->machines.host; + struct total_run_stats totals; + u64 task_count; + struct thread *t; + struct thread_runtime *r; + int i; + + memset(&totals, 0, sizeof(totals)); + + if (comm_width < 30) + comm_width = 30; + + printf("\nRuntime summary\n"); + printf("%*s parent sched-in ", comm_width, "comm"); + printf(" run-time min-run avg-run max-run stddev\n"); + printf("%*s (count) ", comm_width, ""); + printf(" (msec) (msec) (msec) (msec) %%\n"); + printf("%.105s\n", graph_dotted_line); + + machine__for_each_thread(m, show_thread_runtime, &totals); + task_count = totals.task_count; + if (!task_count) + printf("\n"); + + printf("\nTerminated tasks:\n"); + machine__for_each_thread(m, show_deadthread_runtime, &totals); + if (task_count == totals.task_count) + printf("\n"); + + /* CPU idle stats not tracked when samples were skipped */ + if (sched->skipped_samples) + return; + + printf("\nIdle stats:\n"); + for (i = 0; i <= idle_max_cpu; ++i) { + t = idle_threads[i]; + if (!t) + continue; + + r = thread__priv(t); + if (r && r->run_stats.n) { + totals.sched_count += r->run_stats.n; + printf(" CPU %2d idle for ", i); + print_sched_time(r->total_run_time, 6); + printf(" msec\n"); + } else + printf(" CPU %2d idle entire time window\n", i); + } + + printf("\n" + " Total number of unique tasks: %" PRIu64 "\n" + "Total number of context switches: %" PRIu64 "\n" + " Total run time (msec): ", + totals.task_count, totals.sched_count); + + print_sched_time(totals.total_run_time, 2); + printf("\n"); +} + typedef int (*sched_handler)(struct perf_tool *tool, union perf_event *event, struct perf_evsel *evsel, @@ -2163,6 +2298,7 @@ static int perf_sched__timehist(struct perf_sched *sched) }; struct perf_session *session; + struct perf_evlist *evlist; int err = -1; /* @@ -2185,6 +2321,8 @@ static int perf_sched__timehist(struct perf_sched *sched) if (session == NULL) return -ENOMEM; + evlist = session->evlist; + symbol__init(&session->header.env); setup_pager(); @@ -2203,7 +2341,12 @@ static int perf_sched__timehist(struct perf_sched *sched) if (init_idle_threads(sched->max_cpu)) goto out; - timehist_header(); + /* summary_only implies summary option, but don't overwrite summary if set */ + if (sched->summary_only) + sched->summary = sched->summary_only; + + if (!sched->summary_only) + timehist_header(); err = perf_session__process_events(session); if (err) { @@ -2211,6 +2354,13 @@ static int perf_sched__timehist(struct perf_sched *sched) goto out; } + sched->nr_events = evlist->stats.nr_events[0]; + sched->nr_lost_events = evlist->stats.total_lost; + sched->nr_lost_chunks = evlist->stats.nr_events[PERF_RECORD_LOST]; + + if (sched->summary) + timehist_print_summary(sched, session); + out: free_idle_threads(); perf_session__delete(session); @@ -2569,6 +2719,10 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused) "file", "kallsyms pathname"), OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory", "Look for files with symbols relative to this directory"), + OPT_BOOLEAN('s', "summary", &sched.summary_only, + "Show only syscall summary with statistics"), + OPT_BOOLEAN('S', "with-summary", &sched.summary, + "Show all syscalls and summary with statistics"), OPT_PARENT(sched_options) };