From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1761107AbcLASF5 (ORCPT ); Thu, 1 Dec 2016 13:05:57 -0500 Received: from bombadil.infradead.org ([198.137.202.9]:60199 "EHLO bombadil.infradead.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1759565AbcLASDC (ORCPT ); Thu, 1 Dec 2016 13:03:02 -0500 From: Arnaldo Carvalho de Melo To: Ingo Molnar Cc: linux-kernel@vger.kernel.org, David Ahern , David Ahern , Jiri Olsa , Peter Zijlstra , Arnaldo Carvalho de Melo Subject: [PATCH 15/19] perf sched timehist: Add option to specify time window of interest Date: Thu, 1 Dec 2016 15:02:31 -0300 Message-Id: <20161201180235.18392-16-acme@kernel.org> X-Mailer: git-send-email 2.9.3 In-Reply-To: <20161201180235.18392-1-acme@kernel.org> References: <20161201180235.18392-1-acme@kernel.org> X-SRS-Rewrite: SMTP reverse-path rewritten from by bombadil.infradead.org. See http://www.infradead.org/rpr.html Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org From: David Ahern Add option to allow user to control analysis window. e.g., collect data for time window and analyze a segment of interest within that window. Committer notes: Testing it: # perf sched record -a usleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 1.593 MB perf.data (25 samples) ] # # perf sched timehist | head -18 Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) ------------- ------ --------------- --------- --------- -------- 19818.635579 [0002] 0.000 0.000 0.000 19818.635613 [0000] perf[9116] 0.000 0.000 0.000 19818.635676 [0000] 0.000 0.000 0.063 19818.635678 [0000] rcuos/2[29] 0.000 0.002 0.001 19818.635696 [0002] perf[9117] 0.000 0.004 0.116 19818.635702 [0000] 0.001 0.000 0.024 19818.635709 [0002] migration/2[25] 0.000 0.003 0.012 19818.636263 [0000] usleep[9117] 0.005 0.000 0.560 19818.636316 [0000] 0.560 0.000 0.053 19818.636358 [0002] 0.129 0.000 0.649 19818.636358 [0000] usleep[9117] 0.053 0.002 0.042 # # perf sched timehist --time 19818.635696, Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) ------------- ------ --------------- -------- --------- --------- 19818.635696 [0002] perf[9117] 0.000 0.120 0.000 19818.635702 [0000] 0.019 0.000 0.006 19818.635709 [0002] migration/2[25] 0.000 0.003 0.012 19818.636263 [0000] usleep[9117] 0.005 0.000 0.560 19818.636316 [0000] 0.560 0.000 0.053 19818.636358 [0002] 0.129 0.000 0.649 19818.636358 [0000] usleep[9117] 0.053 0.002 0.042 # # perf sched timehist --time 19818.635696,19818.635709 Samples do not have callchains. time cpu task name wait time sch delay run time [tid/pid] (msec) (msec) (msec) ------------- ------ --------------- --------- --------- --------- 19818.635696 [0002] perf[9117] 0.000 0.120 0.000 19818.635702 [0000] 0.019 0.000 0.006 19818.635709 [0002] migration/2[25] 0.000 0.003 0.012 19818.635709 [0000] usleep[9117] 0.005 0.000 0.006 # Signed-off-by: David Ahern Tested-by: Arnaldo Carvalho de Melo Acked-by: Namhyung Kim Cc: Jiri Olsa Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1480439746-42695-5-git-send-email-dsahern@gmail.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-sched.txt | 8 ++++++ tools/perf/builtin-sched.c | 51 +++++++++++++++++++++++++++++---- 2 files changed, 53 insertions(+), 6 deletions(-) diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt index 121c60da03e5..7775b1eb2bee 100644 --- a/tools/perf/Documentation/perf-sched.txt +++ b/tools/perf/Documentation/perf-sched.txt @@ -132,6 +132,14 @@ OPTIONS for 'perf sched timehist' --migrations:: Show migration events. +--time:: + Only analyze samples within given time window: ,. Times + have the format seconds.microseconds. If start is not given (i.e., time + string is ',x.y') then analysis starts at the beginning of the file. If + stop time is not given (i.e, time string is 'x.y,') then analysis goes + to end of file. + + SEE ALSO -------- linkperf:perf-record[1] diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c index 4f9e7cba4ebf..870d94cd20ba 100644 --- a/tools/perf/builtin-sched.c +++ b/tools/perf/builtin-sched.c @@ -15,6 +15,7 @@ #include "util/color.h" #include "util/stat.h" #include "util/callchain.h" +#include "util/time-utils.h" #include #include "util/trace-event.h" @@ -205,6 +206,8 @@ struct perf_sched { bool show_wakeups; bool show_migrations; u64 skipped_samples; + const char *time_str; + struct perf_time_interval ptime; }; /* per thread run time data */ @@ -1837,13 +1840,14 @@ static void timehist_header(struct perf_sched *sched) static void timehist_print_sample(struct perf_sched *sched, struct perf_sample *sample, struct addr_location *al, - struct thread *thread) + struct thread *thread, + u64 t) { struct thread_runtime *tr = thread__priv(thread); u32 max_cpus = sched->max_cpu + 1; char tstr[64]; - timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr)); + timestamp__scnprintf_usec(t, tstr, sizeof(tstr)); printf("%15s [%04d] ", tstr, sample->cpu); if (sched->show_cpu_visual) { @@ -2194,7 +2198,8 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool, tr->ready_to_run = sample->time; /* show wakeups if requested */ - if (sched->show_wakeups) + if (sched->show_wakeups && + !perf_time__skip_sample(&sched->ptime, sample->time)) timehist_print_wakeup_event(sched, sample, machine, thread); return 0; @@ -2288,10 +2293,11 @@ static int timehist_sched_change_event(struct perf_tool *tool, struct machine *machine) { struct perf_sched *sched = container_of(tool, struct perf_sched, tool); + struct perf_time_interval *ptime = &sched->ptime; struct addr_location al; struct thread *thread; struct thread_runtime *tr = NULL; - u64 tprev; + u64 tprev, t = sample->time; int rc = 0; if (machine__resolve(machine, &al, sample) < 0) { @@ -2318,9 +2324,35 @@ static int timehist_sched_change_event(struct perf_tool *tool, tprev = perf_evsel__get_time(evsel, sample->cpu); - timehist_update_runtime_stats(tr, sample->time, tprev); + /* + * If start time given: + * - sample time is under window user cares about - skip sample + * - tprev is under window user cares about - reset to start of window + */ + if (ptime->start && ptime->start > t) + goto out; + + if (ptime->start > tprev) + tprev = ptime->start; + + /* + * If end time given: + * - previous sched event is out of window - we are done + * - sample time is beyond window user cares about - reset it + * to close out stats for time window interest + */ + if (ptime->end) { + if (tprev > ptime->end) + goto out; + + if (t > ptime->end) + t = ptime->end; + } + + timehist_update_runtime_stats(tr, t, tprev); + if (!sched->summary_only) - timehist_print_sample(sched, sample, &al, thread); + timehist_print_sample(sched, sample, &al, thread, t); out: if (tr) { @@ -2583,6 +2615,11 @@ static int perf_sched__timehist(struct perf_sched *sched) symbol__init(&session->header.env); + if (perf_time__parse_str(&sched->ptime, sched->time_str) != 0) { + pr_err("Invalid time string\n"); + return -EINVAL; + } + if (timehist_check_attr(sched, evlist) != 0) goto out; @@ -2997,6 +3034,8 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused) OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"), OPT_BOOLEAN('M', "migrations", &sched.show_migrations, "Show migration events"), OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"), + OPT_STRING(0, "time", &sched.time_str, "str", + "Time span for analysis (start,stop)"), OPT_PARENT(sched_options) }; -- 2.9.3