* [PATCH v2 1/8] perf symbol: Print symbol offsets conditionally
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-24 4:18 ` [tip:perf/core] perf symbols: " tip-bot for Namhyung Kim
2016-11-16 6:06 ` [PATCH v2 2/8] perf tools: Support printing callchains with arrows Namhyung Kim
` (9 subsequent siblings)
10 siblings, 1 reply; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
The __symbol__fprintf_symname_offs() always shows symbol offsets. So
there's no difference between 'perf script -F ip,sym' and 'perf script
-F ip,sym,symoff'. I don't think it's a desired behavior..
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/util/evsel_fprintf.c | 6 ++++--
tools/perf/util/symbol.h | 3 ++-
tools/perf/util/symbol_fprintf.c | 11 ++++++-----
3 files changed, 12 insertions(+), 8 deletions(-)
diff --git a/tools/perf/util/evsel_fprintf.c b/tools/perf/util/evsel_fprintf.c
index 662a0a6182e7..ccb602397b60 100644
--- a/tools/perf/util/evsel_fprintf.c
+++ b/tools/perf/util/evsel_fprintf.c
@@ -137,7 +137,8 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
if (print_symoffset) {
printed += __symbol__fprintf_symname_offs(node->sym, &node_al,
- print_unknown_as_addr, fp);
+ print_unknown_as_addr,
+ true, fp);
} else {
printed += __symbol__fprintf_symname(node->sym, &node_al,
print_unknown_as_addr, fp);
@@ -188,7 +189,8 @@ int sample__fprintf_sym(struct perf_sample *sample, struct addr_location *al,
printed += fprintf(fp, " ");
if (print_symoffset) {
printed += __symbol__fprintf_symname_offs(al->sym, al,
- print_unknown_as_addr, fp);
+ print_unknown_as_addr,
+ true, fp);
} else {
printed += __symbol__fprintf_symname(al->sym, al,
print_unknown_as_addr, fp);
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index 2d0a905c879a..dec7e2d44885 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -282,7 +282,8 @@ int symbol__annotation_init(void);
struct symbol *symbol__new(u64 start, u64 len, u8 binding, const char *name);
size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
- bool unknown_as_addr, FILE *fp);
+ bool unknown_as_addr,
+ bool print_offsets, FILE *fp);
size_t symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al, FILE *fp);
size_t __symbol__fprintf_symname(const struct symbol *sym,
diff --git a/tools/perf/util/symbol_fprintf.c b/tools/perf/util/symbol_fprintf.c
index a680bdaa65dc..7c6b33e8e2d2 100644
--- a/tools/perf/util/symbol_fprintf.c
+++ b/tools/perf/util/symbol_fprintf.c
@@ -15,14 +15,15 @@ size_t symbol__fprintf(struct symbol *sym, FILE *fp)
size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
- bool unknown_as_addr, FILE *fp)
+ bool unknown_as_addr,
+ bool print_offsets, FILE *fp)
{
unsigned long offset;
size_t length;
if (sym && sym->name) {
length = fprintf(fp, "%s", sym->name);
- if (al) {
+ if (al && print_offsets) {
if (al->addr < sym->end)
offset = al->addr - sym->start;
else
@@ -40,19 +41,19 @@ size_t symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, al, false, fp);
+ return __symbol__fprintf_symname_offs(sym, al, false, true, fp);
}
size_t __symbol__fprintf_symname(const struct symbol *sym,
const struct addr_location *al,
bool unknown_as_addr, FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, fp);
+ return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, false, fp);
}
size_t symbol__fprintf_symname(const struct symbol *sym, FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, NULL, false, fp);
+ return __symbol__fprintf_symname_offs(sym, NULL, false, false, fp);
}
size_t dso__fprintf_symbols_by_name(struct dso *dso,
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* [tip:perf/core] perf symbols: Print symbol offsets conditionally
2016-11-16 6:06 ` [PATCH v2 1/8] perf symbol: Print symbol offsets conditionally Namhyung Kim
@ 2016-11-24 4:18 ` tip-bot for Namhyung Kim
0 siblings, 0 replies; 23+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-11-24 4:18 UTC (permalink / raw)
To: linux-tip-commits
Cc: hpa, mingo, tglx, eranian, acme, dsahern, jolsa, namhyung,
a.p.zijlstra, linux-kernel, andi
Commit-ID: a8763445f6c78628bd96d51649745065c0bb2c92
Gitweb: http://git.kernel.org/tip/a8763445f6c78628bd96d51649745065c0bb2c92
Author: Namhyung Kim <namhyung@kernel.org>
AuthorDate: Wed, 16 Nov 2016 15:06:27 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:06 -0300
perf symbols: Print symbol offsets conditionally
The __symbol__fprintf_symname_offs() always shows symbol offsets. So
there's no difference between 'perf script -F ip,sym' and 'perf script
-F ip,sym,symoff'. I don't think it's a desired behavior..
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-2-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/util/evsel_fprintf.c | 6 ++++--
tools/perf/util/symbol.h | 3 ++-
tools/perf/util/symbol_fprintf.c | 11 ++++++-----
3 files changed, 12 insertions(+), 8 deletions(-)
diff --git a/tools/perf/util/evsel_fprintf.c b/tools/perf/util/evsel_fprintf.c
index 662a0a6..ccb6023 100644
--- a/tools/perf/util/evsel_fprintf.c
+++ b/tools/perf/util/evsel_fprintf.c
@@ -137,7 +137,8 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
if (print_symoffset) {
printed += __symbol__fprintf_symname_offs(node->sym, &node_al,
- print_unknown_as_addr, fp);
+ print_unknown_as_addr,
+ true, fp);
} else {
printed += __symbol__fprintf_symname(node->sym, &node_al,
print_unknown_as_addr, fp);
@@ -188,7 +189,8 @@ int sample__fprintf_sym(struct perf_sample *sample, struct addr_location *al,
printed += fprintf(fp, " ");
if (print_symoffset) {
printed += __symbol__fprintf_symname_offs(al->sym, al,
- print_unknown_as_addr, fp);
+ print_unknown_as_addr,
+ true, fp);
} else {
printed += __symbol__fprintf_symname(al->sym, al,
print_unknown_as_addr, fp);
diff --git a/tools/perf/util/symbol.h b/tools/perf/util/symbol.h
index 2d0a905..dec7e2d4 100644
--- a/tools/perf/util/symbol.h
+++ b/tools/perf/util/symbol.h
@@ -282,7 +282,8 @@ int symbol__annotation_init(void);
struct symbol *symbol__new(u64 start, u64 len, u8 binding, const char *name);
size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
- bool unknown_as_addr, FILE *fp);
+ bool unknown_as_addr,
+ bool print_offsets, FILE *fp);
size_t symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al, FILE *fp);
size_t __symbol__fprintf_symname(const struct symbol *sym,
diff --git a/tools/perf/util/symbol_fprintf.c b/tools/perf/util/symbol_fprintf.c
index a680bda..7c6b33e 100644
--- a/tools/perf/util/symbol_fprintf.c
+++ b/tools/perf/util/symbol_fprintf.c
@@ -15,14 +15,15 @@ size_t symbol__fprintf(struct symbol *sym, FILE *fp)
size_t __symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
- bool unknown_as_addr, FILE *fp)
+ bool unknown_as_addr,
+ bool print_offsets, FILE *fp)
{
unsigned long offset;
size_t length;
if (sym && sym->name) {
length = fprintf(fp, "%s", sym->name);
- if (al) {
+ if (al && print_offsets) {
if (al->addr < sym->end)
offset = al->addr - sym->start;
else
@@ -40,19 +41,19 @@ size_t symbol__fprintf_symname_offs(const struct symbol *sym,
const struct addr_location *al,
FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, al, false, fp);
+ return __symbol__fprintf_symname_offs(sym, al, false, true, fp);
}
size_t __symbol__fprintf_symname(const struct symbol *sym,
const struct addr_location *al,
bool unknown_as_addr, FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, fp);
+ return __symbol__fprintf_symname_offs(sym, al, unknown_as_addr, false, fp);
}
size_t symbol__fprintf_symname(const struct symbol *sym, FILE *fp)
{
- return __symbol__fprintf_symname_offs(sym, NULL, false, fp);
+ return __symbol__fprintf_symname_offs(sym, NULL, false, false, fp);
}
size_t dso__fprintf_symbols_by_name(struct dso *dso,
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 2/8] perf tools: Support printing callchains with arrows
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
2016-11-16 6:06 ` [PATCH v2 1/8] perf symbol: Print symbol offsets conditionally Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-24 4:18 ` [tip:perf/core] perf evsel: " tip-bot for Namhyung Kim
2016-11-16 6:06 ` [PATCH v2 3/8] perf sched timehist: Introduce timehist command Namhyung Kim
` (8 subsequent siblings)
10 siblings, 1 reply; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
The EVSEL__PRINT_CALLCHAIN_ARROW options can be used to print callchains
with arrows for readability. It will be used 'sched timehist' command
like below:
__schedule <- schedule <- schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
__schedule <- schedule <- schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
__schedule <- schedule <- worker_thread <- kthread <- ret_from_fork
Suggested-by: Ingo Molnar <mingo@kernel.org>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/util/evsel.h | 1 +
tools/perf/util/evsel_fprintf.c | 6 ++++++
2 files changed, 7 insertions(+)
diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
index 8cd7cd227483..27fa3a343577 100644
--- a/tools/perf/util/evsel.h
+++ b/tools/perf/util/evsel.h
@@ -391,6 +391,7 @@ int perf_evsel__fprintf(struct perf_evsel *evsel,
#define EVSEL__PRINT_ONELINE (1<<4)
#define EVSEL__PRINT_SRCLINE (1<<5)
#define EVSEL__PRINT_UNKNOWN_AS_ADDR (1<<6)
+#define EVSEL__PRINT_CALLCHAIN_ARROW (1<<7)
struct callchain_cursor;
diff --git a/tools/perf/util/evsel_fprintf.c b/tools/perf/util/evsel_fprintf.c
index ccb602397b60..53bb614feafb 100644
--- a/tools/perf/util/evsel_fprintf.c
+++ b/tools/perf/util/evsel_fprintf.c
@@ -108,7 +108,9 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
int print_oneline = print_opts & EVSEL__PRINT_ONELINE;
int print_srcline = print_opts & EVSEL__PRINT_SRCLINE;
int print_unknown_as_addr = print_opts & EVSEL__PRINT_UNKNOWN_AS_ADDR;
+ int print_arrow = print_opts & EVSEL__PRINT_CALLCHAIN_ARROW;
char s = print_oneline ? ' ' : '\t';
+ bool first = true;
if (sample->callchain) {
struct addr_location node_al;
@@ -124,6 +126,9 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
printed += fprintf(fp, "%-*.*s", left_alignment, left_alignment, " ");
+ if (print_arrow && !first)
+ printed += fprintf(fp, " <-");
+
if (print_ip)
printed += fprintf(fp, "%c%16" PRIx64, s, node->ip);
@@ -158,6 +163,7 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
printed += fprintf(fp, "\n");
callchain_cursor_advance(cursor);
+ first = false;
}
}
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* [tip:perf/core] perf evsel: Support printing callchains with arrows
2016-11-16 6:06 ` [PATCH v2 2/8] perf tools: Support printing callchains with arrows Namhyung Kim
@ 2016-11-24 4:18 ` tip-bot for Namhyung Kim
0 siblings, 0 replies; 23+ messages in thread
From: tip-bot for Namhyung Kim @ 2016-11-24 4:18 UTC (permalink / raw)
To: linux-tip-commits
Cc: mingo, acme, jolsa, hpa, dsahern, andi, eranian, namhyung,
a.p.zijlstra, tglx, linux-kernel
Commit-ID: 69b7e48070ca2ecee7498166259b5826b22e8b2e
Gitweb: http://git.kernel.org/tip/69b7e48070ca2ecee7498166259b5826b22e8b2e
Author: Namhyung Kim <namhyung@kernel.org>
AuthorDate: Wed, 16 Nov 2016 15:06:28 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:07 -0300
perf evsel: Support printing callchains with arrows
The EVSEL__PRINT_CALLCHAIN_ARROW options can be used to print callchains
with arrows for readability. It will be used 'sched timehist' command
like below:
__schedule <- schedule <- schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
__schedule <- schedule <- schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
__schedule <- schedule <- worker_thread <- kthread <- ret_from_fork
Suggested-and-Acked-by: Ingo Molnar <mingo@kernel.org>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-3-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/util/evsel.h | 1 +
tools/perf/util/evsel_fprintf.c | 6 ++++++
2 files changed, 7 insertions(+)
diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
index 8cd7cd2..27fa3a3 100644
--- a/tools/perf/util/evsel.h
+++ b/tools/perf/util/evsel.h
@@ -391,6 +391,7 @@ int perf_evsel__fprintf(struct perf_evsel *evsel,
#define EVSEL__PRINT_ONELINE (1<<4)
#define EVSEL__PRINT_SRCLINE (1<<5)
#define EVSEL__PRINT_UNKNOWN_AS_ADDR (1<<6)
+#define EVSEL__PRINT_CALLCHAIN_ARROW (1<<7)
struct callchain_cursor;
diff --git a/tools/perf/util/evsel_fprintf.c b/tools/perf/util/evsel_fprintf.c
index ccb6023..53bb614 100644
--- a/tools/perf/util/evsel_fprintf.c
+++ b/tools/perf/util/evsel_fprintf.c
@@ -108,7 +108,9 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
int print_oneline = print_opts & EVSEL__PRINT_ONELINE;
int print_srcline = print_opts & EVSEL__PRINT_SRCLINE;
int print_unknown_as_addr = print_opts & EVSEL__PRINT_UNKNOWN_AS_ADDR;
+ int print_arrow = print_opts & EVSEL__PRINT_CALLCHAIN_ARROW;
char s = print_oneline ? ' ' : '\t';
+ bool first = true;
if (sample->callchain) {
struct addr_location node_al;
@@ -124,6 +126,9 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
printed += fprintf(fp, "%-*.*s", left_alignment, left_alignment, " ");
+ if (print_arrow && !first)
+ printed += fprintf(fp, " <-");
+
if (print_ip)
printed += fprintf(fp, "%c%16" PRIx64, s, node->ip);
@@ -158,6 +163,7 @@ int sample__fprintf_callchain(struct perf_sample *sample, int left_alignment,
printed += fprintf(fp, "\n");
callchain_cursor_advance(cursor);
+ first = false;
}
}
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 3/8] perf sched timehist: Introduce timehist command
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
2016-11-16 6:06 ` [PATCH v2 1/8] perf symbol: Print symbol offsets conditionally Namhyung Kim
2016-11-16 6:06 ` [PATCH v2 2/8] perf tools: Support printing callchains with arrows Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-24 4:19 ` [tip:perf/core] " tip-bot for David Ahern
2016-11-16 6:06 ` [PATCH v2 4/8] perf sched timehist: Add summary options Namhyung Kim
` (7 subsequent siblings)
10 siblings, 1 reply; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
From: David Ahern <dsahern@gmail.com>
'perf sched timehist' provides an analysis of scheduling events.
Example usage:
perf sched record -- sleep 1
perf sched timehist
By default it shows the individual schedule events, including the wait
time (time between sched-out and next sched-in events for the task), the
task scheduling delay (time between wakeup and actually running) and run
time for the task:
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
-------------- ------ -------------------- --------- --------- ---------
79371.874569 [0011] gcc[31949] 0.014 0.000 1.148
79371.874591 [0010] gcc[31951] 0.000 0.000 0.024
79371.874603 [0010] migration/10[59] 3.350 0.004 0.011
79371.874604 [0011] <idle> 1.148 0.000 0.035
79371.874723 [0005] <idle> 0.016 0.000 1.383
79371.874746 [0005] gcc[31949] 0.153 0.078 0.022
...
Times are in msec.usec.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 594 ++++++++++++++++++++++++++++++++++++++++++++-
1 file changed, 589 insertions(+), 5 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index fb3441211e4b..c0ac0c9557e8 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -13,12 +13,14 @@
#include "util/cloexec.h"
#include "util/thread_map.h"
#include "util/color.h"
+#include "util/stat.h"
#include <subcmd/parse-options.h>
#include "util/trace-event.h"
#include "util/debug.h"
+#include <linux/log2.h>
#include <sys/prctl.h>
#include <sys/resource.h>
@@ -194,6 +196,29 @@ struct perf_sched {
struct perf_sched_map map;
};
+/* per thread run time data */
+struct thread_runtime {
+ u64 last_time; /* time of previous sched in/out event */
+ u64 dt_run; /* run time */
+ u64 dt_wait; /* time between CPU access (off cpu) */
+ u64 dt_delay; /* time between wakeup and sched-in */
+ u64 ready_to_run; /* time of wakeup */
+
+ struct stats run_stats;
+ u64 total_run_time;
+};
+
+/* per event run time data */
+struct evsel_runtime {
+ u64 *last_time; /* time this event was last seen per cpu */
+ u32 ncpu; /* highest cpu slot allocated */
+};
+
+/* track idle times per cpu */
+static struct thread **idle_threads;
+static int idle_max_cpu;
+static char idle_comm[] = "<idle>";
+
static u64 get_nsecs(void)
{
struct timespec ts;
@@ -1654,6 +1679,546 @@ static int perf_sched__read_events(struct perf_sched *sched)
return rc;
}
+/*
+ * scheduling times are printed as msec.usec
+ */
+static inline void print_sched_time(unsigned long long nsecs, int width)
+{
+ unsigned long msecs;
+ unsigned long usecs;
+
+ msecs = nsecs / NSEC_PER_MSEC;
+ nsecs -= msecs * NSEC_PER_MSEC;
+ usecs = nsecs / NSEC_PER_USEC;
+ printf("%*lu.%03lu ", width, msecs, usecs);
+}
+
+/*
+ * returns runtime data for event, allocating memory for it the
+ * first time it is used.
+ */
+static struct evsel_runtime *perf_evsel__get_runtime(struct perf_evsel *evsel)
+{
+ struct evsel_runtime *r = evsel->priv;
+
+ if (r == NULL) {
+ r = zalloc(sizeof(struct evsel_runtime));
+ evsel->priv = r;
+ }
+
+ return r;
+}
+
+/*
+ * save last time event was seen per cpu
+ */
+static void perf_evsel__save_time(struct perf_evsel *evsel,
+ u64 timestamp, u32 cpu)
+{
+ struct evsel_runtime *r = perf_evsel__get_runtime(evsel);
+
+ if (r == NULL)
+ return;
+
+ if ((cpu >= r->ncpu) || (r->last_time == NULL)) {
+ int i, n = __roundup_pow_of_two(cpu+1);
+ void *p = r->last_time;
+
+ p = realloc(r->last_time, n * sizeof(u64));
+ if (!p)
+ return;
+
+ r->last_time = p;
+ for (i = r->ncpu; i < n; ++i)
+ r->last_time[i] = (u64) 0;
+
+ r->ncpu = n;
+ }
+
+ r->last_time[cpu] = timestamp;
+}
+
+/* returns last time this event was seen on the given cpu */
+static u64 perf_evsel__get_time(struct perf_evsel *evsel, u32 cpu)
+{
+ struct evsel_runtime *r = perf_evsel__get_runtime(evsel);
+
+ if ((r == NULL) || (r->last_time == NULL) || (cpu >= r->ncpu))
+ return 0;
+
+ return r->last_time[cpu];
+}
+
+static int comm_width = 20;
+
+static char *timehist_get_commstr(struct thread *thread)
+{
+ static char str[32];
+ const char *comm = thread__comm_str(thread);
+ pid_t tid = thread->tid;
+ pid_t pid = thread->pid_;
+ int n;
+
+ if (pid == 0)
+ n = scnprintf(str, sizeof(str), "%s", comm);
+
+ else if (tid != pid)
+ n = scnprintf(str, sizeof(str), "%s[%d/%d]", comm, tid, pid);
+
+ else
+ n = scnprintf(str, sizeof(str), "%s[%d]", comm, tid);
+
+ if (n > comm_width)
+ comm_width = n;
+
+ return str;
+}
+
+static void timehist_header(void)
+{
+ printf("%15s %6s ", "time", "cpu");
+
+ printf(" %-20s %9s %9s %9s",
+ "task name", "wait time", "sch delay", "run time");
+
+ printf("\n");
+
+ /*
+ * units row
+ */
+ printf("%15s %-6s ", "", "");
+
+ printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
+
+ /*
+ * separator
+ */
+ printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
+
+ printf(" %.20s %.9s %.9s %.9s",
+ graph_dotted_line, graph_dotted_line, graph_dotted_line,
+ graph_dotted_line);
+
+ printf("\n");
+}
+
+static void timehist_print_sample(struct perf_sample *sample,
+ struct thread *thread)
+{
+ struct thread_runtime *tr = thread__priv(thread);
+ char tstr[64];
+
+ timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+ printf("%15s [%04d] ", tstr, sample->cpu);
+
+ printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+ print_sched_time(tr->dt_wait, 6);
+ print_sched_time(tr->dt_delay, 6);
+ print_sched_time(tr->dt_run, 6);
+ printf("\n");
+}
+
+/*
+ * Explanation of delta-time stats:
+ *
+ * t = time of current schedule out event
+ * tprev = time of previous sched out event
+ * also time of schedule-in event for current task
+ * last_time = time of last sched change event for current task
+ * (i.e, time process was last scheduled out)
+ * ready_to_run = time of wakeup for current task
+ *
+ * -----|------------|------------|------------|------
+ * last ready tprev t
+ * time to run
+ *
+ * |-------- dt_wait --------|
+ * |- dt_delay -|-- dt_run --|
+ *
+ * dt_run = run time of current task
+ * dt_wait = time between last schedule out event for task and tprev
+ * represents time spent off the cpu
+ * dt_delay = time between wakeup and schedule-in of task
+ */
+
+static void timehist_update_runtime_stats(struct thread_runtime *r,
+ u64 t, u64 tprev)
+{
+ r->dt_delay = 0;
+ r->dt_wait = 0;
+ r->dt_run = 0;
+ if (tprev) {
+ r->dt_run = t - tprev;
+ if (r->ready_to_run) {
+ if (r->ready_to_run > tprev)
+ pr_debug("time travel: wakeup time for task > previous sched_switch event\n");
+ else
+ r->dt_delay = tprev - r->ready_to_run;
+ }
+
+ if (r->last_time > tprev)
+ pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
+ else if (r->last_time)
+ r->dt_wait = tprev - r->last_time;
+ }
+
+ update_stats(&r->run_stats, r->dt_run);
+ r->total_run_time += r->dt_run;
+}
+
+static bool is_idle_sample(struct perf_sample *sample,
+ struct perf_evsel *evsel)
+{
+ /* pid 0 == swapper == idle task */
+ if (sample->pid == 0)
+ return true;
+
+ if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0) {
+ if (perf_evsel__intval(evsel, sample, "prev_pid") == 0)
+ return true;
+ }
+ return false;
+}
+
+/*
+ * Track idle stats per cpu by maintaining a local thread
+ * struct for the idle task on each cpu.
+ */
+static int init_idle_threads(int ncpu)
+{
+ int i;
+
+ idle_threads = zalloc(ncpu * sizeof(struct thread *));
+ if (!idle_threads)
+ return -ENOMEM;
+
+ idle_max_cpu = ncpu - 1;
+
+ /* allocate the actual thread struct if needed */
+ for (i = 0; i < ncpu; ++i) {
+ idle_threads[i] = thread__new(0, 0);
+ if (idle_threads[i] == NULL)
+ return -ENOMEM;
+
+ thread__set_comm(idle_threads[i], idle_comm, 0);
+ }
+
+ return 0;
+}
+
+static void free_idle_threads(void)
+{
+ int i;
+
+ if (idle_threads == NULL)
+ return;
+
+ for (i = 0; i <= idle_max_cpu; ++i) {
+ if ((idle_threads[i]))
+ thread__delete(idle_threads[i]);
+ }
+
+ free(idle_threads);
+}
+
+static struct thread *get_idle_thread(int cpu)
+{
+ /*
+ * expand/allocate array of pointers to local thread
+ * structs if needed
+ */
+ if ((cpu >= idle_max_cpu) || (idle_threads == NULL)) {
+ int i, j = __roundup_pow_of_two(cpu+1);
+ void *p;
+
+ p = realloc(idle_threads, j * sizeof(struct thread *));
+ if (!p)
+ return NULL;
+
+ idle_threads = (struct thread **) p;
+ i = idle_max_cpu ? idle_max_cpu + 1 : 0;
+ for (; i < j; ++i)
+ idle_threads[i] = NULL;
+
+ idle_max_cpu = j;
+ }
+
+ /* allocate a new thread struct if needed */
+ if (idle_threads[cpu] == NULL) {
+ idle_threads[cpu] = thread__new(0, 0);
+
+ if (idle_threads[cpu]) {
+ idle_threads[cpu]->tid = 0;
+ thread__set_comm(idle_threads[cpu], idle_comm, 0);
+ }
+ }
+
+ return idle_threads[cpu];
+}
+
+/*
+ * handle runtime stats saved per thread
+ */
+static struct thread_runtime *thread__init_runtime(struct thread *thread)
+{
+ struct thread_runtime *r;
+
+ r = zalloc(sizeof(struct thread_runtime));
+ if (!r)
+ return NULL;
+
+ init_stats(&r->run_stats);
+ thread__set_priv(thread, r);
+
+ return r;
+}
+
+static struct thread_runtime *thread__get_runtime(struct thread *thread)
+{
+ struct thread_runtime *tr;
+
+ tr = thread__priv(thread);
+ if (tr == NULL) {
+ tr = thread__init_runtime(thread);
+ if (tr == NULL)
+ pr_debug("Failed to malloc memory for runtime data.\n");
+ }
+
+ return tr;
+}
+
+static struct thread *timehist_get_thread(struct perf_sample *sample,
+ struct machine *machine,
+ struct perf_evsel *evsel)
+{
+ struct thread *thread;
+
+ if (is_idle_sample(sample, evsel)) {
+ thread = get_idle_thread(sample->cpu);
+ if (thread == NULL)
+ pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
+
+ } else {
+ thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+ if (thread == NULL) {
+ pr_debug("Failed to get thread for tid %d. skipping sample.\n",
+ sample->tid);
+ }
+ }
+
+ return thread;
+}
+
+static bool timehist_skip_sample(struct thread *thread)
+{
+ bool rc = false;
+
+ if (thread__is_filtered(thread))
+ rc = true;
+
+ return rc;
+}
+
+static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
+ union perf_event *event __maybe_unused,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct thread *thread;
+ struct thread_runtime *tr = NULL;
+ /* want pid of awakened task not pid in sample */
+ const u32 pid = perf_evsel__intval(evsel, sample, "pid");
+
+ thread = machine__findnew_thread(machine, 0, pid);
+ if (thread == NULL)
+ return -1;
+
+ tr = thread__get_runtime(thread);
+ if (tr == NULL)
+ return -1;
+
+ if (tr->ready_to_run == 0)
+ tr->ready_to_run = sample->time;
+
+ return 0;
+}
+
+static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
+ union perf_event *event,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct addr_location al;
+ struct thread *thread;
+ struct thread_runtime *tr = NULL;
+ u64 tprev;
+ int rc = 0;
+
+ if (machine__resolve(machine, &al, sample) < 0) {
+ pr_err("problem processing %d event. skipping it\n",
+ event->header.type);
+ rc = -1;
+ goto out;
+ }
+
+ thread = timehist_get_thread(sample, machine, evsel);
+ if (thread == NULL) {
+ rc = -1;
+ goto out;
+ }
+
+ if (timehist_skip_sample(thread))
+ goto out;
+
+ tr = thread__get_runtime(thread);
+ if (tr == NULL) {
+ rc = -1;
+ goto out;
+ }
+
+ tprev = perf_evsel__get_time(evsel, sample->cpu);
+
+ timehist_update_runtime_stats(tr, sample->time, tprev);
+ timehist_print_sample(sample, thread);
+
+out:
+ if (tr) {
+ /* time of this sched_switch event becomes last time task seen */
+ tr->last_time = sample->time;
+
+ /* sched out event for task so reset ready to run time */
+ tr->ready_to_run = 0;
+ }
+
+ perf_evsel__save_time(evsel, sample->time, sample->cpu);
+
+ return rc;
+}
+
+static int timehist_sched_switch_event(struct perf_tool *tool,
+ union perf_event *event,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ return timehist_sched_change_event(tool, event, evsel, sample, machine);
+}
+
+static int process_lost(struct perf_tool *tool __maybe_unused,
+ union perf_event *event,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ char tstr[64];
+
+ timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+ printf("%15s ", tstr);
+ printf("lost %" PRIu64 " events on cpu %d\n", event->lost.lost, sample->cpu);
+
+ return 0;
+}
+
+
+typedef int (*sched_handler)(struct perf_tool *tool,
+ union perf_event *event,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine);
+
+static int perf_timehist__process_sample(struct perf_tool *tool,
+ union perf_event *event,
+ struct perf_sample *sample,
+ struct perf_evsel *evsel,
+ struct machine *machine)
+{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
+ int err = 0;
+ int this_cpu = sample->cpu;
+
+ if (this_cpu > sched->max_cpu)
+ sched->max_cpu = this_cpu;
+
+ if (evsel->handler != NULL) {
+ sched_handler f = evsel->handler;
+
+ err = f(tool, event, evsel, sample, machine);
+ }
+
+ return err;
+}
+
+static int perf_sched__timehist(struct perf_sched *sched)
+{
+ const struct perf_evsel_str_handler handlers[] = {
+ { "sched:sched_switch", timehist_sched_switch_event, },
+ { "sched:sched_wakeup", timehist_sched_wakeup_event, },
+ { "sched:sched_wakeup_new", timehist_sched_wakeup_event, },
+ };
+ struct perf_data_file file = {
+ .path = input_name,
+ .mode = PERF_DATA_MODE_READ,
+ };
+
+ struct perf_session *session;
+ int err = -1;
+
+ /*
+ * event handlers for timehist option
+ */
+ sched->tool.sample = perf_timehist__process_sample;
+ sched->tool.mmap = perf_event__process_mmap;
+ sched->tool.comm = perf_event__process_comm;
+ sched->tool.exit = perf_event__process_exit;
+ sched->tool.fork = perf_event__process_fork;
+ sched->tool.lost = process_lost;
+ sched->tool.attr = perf_event__process_attr;
+ sched->tool.tracing_data = perf_event__process_tracing_data;
+ sched->tool.build_id = perf_event__process_build_id;
+
+ sched->tool.ordered_events = true;
+ sched->tool.ordering_requires_timestamps = true;
+
+ session = perf_session__new(&file, false, &sched->tool);
+ if (session == NULL)
+ return -ENOMEM;
+
+ symbol__init(&session->header.env);
+
+ setup_pager();
+
+ /* setup per-evsel handlers */
+ if (perf_session__set_tracepoints_handlers(session, handlers))
+ goto out;
+
+ if (!perf_session__has_traces(session, "record -R"))
+ goto out;
+
+ /* pre-allocate struct for per-CPU idle stats */
+ sched->max_cpu = session->header.env.nr_cpus_online;
+ if (sched->max_cpu == 0)
+ sched->max_cpu = 4;
+ if (init_idle_threads(sched->max_cpu))
+ goto out;
+
+ timehist_header();
+
+ err = perf_session__process_events(session);
+ if (err) {
+ pr_err("Failed to process events, error %d", err);
+ goto out;
+ }
+
+out:
+ free_idle_threads();
+ perf_session__delete(session);
+
+ return err;
+}
+
+
static void print_bad_events(struct perf_sched *sched)
{
if (sched->nr_unordered_timestamps && sched->nr_timestamps) {
@@ -1970,8 +2535,6 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
const struct option latency_options[] = {
OPT_STRING('s', "sort", &sched.sort_order, "key[,key2...]",
"sort by key(s): runtime, switch, avg, max"),
- OPT_INCR('v', "verbose", &verbose,
- "be more verbose (show symbol address, etc)"),
OPT_INTEGER('C', "CPU", &sched.profile_cpu,
"CPU to profile on"),
OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
@@ -1983,8 +2546,6 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
const struct option replay_options[] = {
OPT_UINTEGER('r', "repeat", &sched.replay_repeat,
"repeat the workload replay N times (-1: infinite)"),
- OPT_INCR('v', "verbose", &verbose,
- "be more verbose (show symbol address, etc)"),
OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
"dump raw trace in ASCII"),
OPT_BOOLEAN('f', "force", &sched.force, "don't complain, do it"),
@@ -2001,6 +2562,16 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"display given CPUs in map"),
OPT_PARENT(sched_options)
};
+ const struct option timehist_options[] = {
+ OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name,
+ "file", "vmlinux pathname"),
+ OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
+ "file", "kallsyms pathname"),
+ OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
+ "Look for files with symbols relative to this directory"),
+ OPT_PARENT(sched_options)
+ };
+
const char * const latency_usage[] = {
"perf sched latency [<options>]",
NULL
@@ -2013,8 +2584,13 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"perf sched map [<options>]",
NULL
};
+ const char * const timehist_usage[] = {
+ "perf sched timehist [<options>]",
+ NULL
+ };
const char *const sched_subcommands[] = { "record", "latency", "map",
- "replay", "script", NULL };
+ "replay", "script",
+ "timehist", NULL };
const char *sched_usage[] = {
NULL,
NULL
@@ -2077,6 +2653,14 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
usage_with_options(replay_usage, replay_options);
}
return perf_sched__replay(&sched);
+ } else if (!strcmp(argv[0], "timehist")) {
+ if (argc) {
+ argc = parse_options(argc, argv, timehist_options,
+ timehist_usage, 0);
+ if (argc)
+ usage_with_options(timehist_usage, timehist_options);
+ }
+ return perf_sched__timehist(&sched);
} else {
usage_with_options(sched_usage, sched_options);
}
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* [tip:perf/core] perf sched timehist: Introduce timehist command
2016-11-16 6:06 ` [PATCH v2 3/8] perf sched timehist: Introduce timehist command Namhyung Kim
@ 2016-11-24 4:19 ` tip-bot for David Ahern
0 siblings, 0 replies; 23+ messages in thread
From: tip-bot for David Ahern @ 2016-11-24 4:19 UTC (permalink / raw)
To: linux-tip-commits
Cc: jolsa, acme, tglx, dsahern, andi, mingo, eranian, namhyung,
linux-kernel, a.p.zijlstra, hpa
Commit-ID: 49394a2a24c78ce034fe0e732b1b54922c23fd92
Gitweb: http://git.kernel.org/tip/49394a2a24c78ce034fe0e732b1b54922c23fd92
Author: David Ahern <dsahern@gmail.com>
AuthorDate: Wed, 16 Nov 2016 15:06:29 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:07 -0300
perf sched timehist: Introduce timehist command
'perf sched timehist' provides an analysis of scheduling events.
Example usage:
perf sched record -- sleep 1
perf sched timehist
By default it shows the individual schedule events, including the wait
time (time between sched-out and next sched-in events for the task), the
task scheduling delay (time between wakeup and actually running) and run
time for the task:
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
-------------- ------ -------------------- --------- --------- ---------
79371.874569 [0011] gcc[31949] 0.014 0.000 1.148
79371.874591 [0010] gcc[31951] 0.000 0.000 0.024
79371.874603 [0010] migration/10[59] 3.350 0.004 0.011
79371.874604 [0011] <idle> 1.148 0.000 0.035
79371.874723 [0005] <idle> 0.016 0.000 1.383
79371.874746 [0005] gcc[31949] 0.153 0.078 0.022
...
Times are in msec.usec.
Committer note:
Add above explanation as the 'perf sched timehist' entry for 'man
perf-sched'.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-4-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/Documentation/perf-sched.txt | 50 ++-
tools/perf/builtin-sched.c | 594 +++++++++++++++++++++++++++++++-
2 files changed, 637 insertions(+), 7 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 1cc08cc..72730da 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -8,11 +8,11 @@ perf-sched - Tool to trace/measure scheduler properties (latencies)
SYNOPSIS
--------
[verse]
-'perf sched' {record|latency|map|replay|script}
+'perf sched' {record|latency|map|replay|script|timehist}
DESCRIPTION
-----------
-There are five variants of perf sched:
+There are several variants of 'perf sched':
'perf sched record <command>' to record the scheduling events
of an arbitrary workload.
@@ -36,6 +36,30 @@ There are five variants of perf sched:
are running on a CPU. A '*' denotes the CPU that had the event, and
a dot signals an idle CPU.
+ 'perf sched timehist' provides an analysis of scheduling events.
+
+ Example usage:
+ perf sched record -- sleep 1
+ perf sched timehist
+
+ By default it shows the individual schedule events, including the wait
+ time (time between sched-out and next sched-in events for the task), the
+ task scheduling delay (time between wakeup and actually running) and run
+ time for the task:
+
+ time cpu task name wait time sch delay run time
+ [tid/pid] (msec) (msec) (msec)
+ -------------- ------ -------------------- --------- --------- ---------
+ 79371.874569 [0011] gcc[31949] 0.014 0.000 1.148
+ 79371.874591 [0010] gcc[31951] 0.000 0.000 0.024
+ 79371.874603 [0010] migration/10[59] 3.350 0.004 0.011
+ 79371.874604 [0011] <idle> 1.148 0.000 0.035
+ 79371.874723 [0005] <idle> 0.016 0.000 1.383
+ 79371.874746 [0005] gcc[31949] 0.153 0.078 0.022
+ ...
+
+ Times are in msec.usec.
+
OPTIONS
-------
-i::
@@ -66,6 +90,28 @@ OPTIONS for 'perf sched map'
--color-pids::
Highlight the given pids.
+OPTIONS for 'perf sched timehist'
+---------------------------------
+-k::
+--vmlinux=<file>::
+ vmlinux pathname
+
+--kallsyms=<file>::
+ kallsyms pathname
+
+-s::
+--summary::
+ Show only a summary of scheduling by thread with min, max, and average
+ run times (in sec) and relative stddev.
+
+-S::
+--with-summary::
+ Show all scheduling events followed by a summary by thread with min,
+ max, and average run times (in sec) and relative stddev.
+
+--symfs=<directory>::
+ Look for files with symbols relative to this directory.
+
SEE ALSO
--------
linkperf:perf-record[1]
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index fb34412..c0ac0c9 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -13,12 +13,14 @@
#include "util/cloexec.h"
#include "util/thread_map.h"
#include "util/color.h"
+#include "util/stat.h"
#include <subcmd/parse-options.h>
#include "util/trace-event.h"
#include "util/debug.h"
+#include <linux/log2.h>
#include <sys/prctl.h>
#include <sys/resource.h>
@@ -194,6 +196,29 @@ struct perf_sched {
struct perf_sched_map map;
};
+/* per thread run time data */
+struct thread_runtime {
+ u64 last_time; /* time of previous sched in/out event */
+ u64 dt_run; /* run time */
+ u64 dt_wait; /* time between CPU access (off cpu) */
+ u64 dt_delay; /* time between wakeup and sched-in */
+ u64 ready_to_run; /* time of wakeup */
+
+ struct stats run_stats;
+ u64 total_run_time;
+};
+
+/* per event run time data */
+struct evsel_runtime {
+ u64 *last_time; /* time this event was last seen per cpu */
+ u32 ncpu; /* highest cpu slot allocated */
+};
+
+/* track idle times per cpu */
+static struct thread **idle_threads;
+static int idle_max_cpu;
+static char idle_comm[] = "<idle>";
+
static u64 get_nsecs(void)
{
struct timespec ts;
@@ -1654,6 +1679,546 @@ out_delete:
return rc;
}
+/*
+ * scheduling times are printed as msec.usec
+ */
+static inline void print_sched_time(unsigned long long nsecs, int width)
+{
+ unsigned long msecs;
+ unsigned long usecs;
+
+ msecs = nsecs / NSEC_PER_MSEC;
+ nsecs -= msecs * NSEC_PER_MSEC;
+ usecs = nsecs / NSEC_PER_USEC;
+ printf("%*lu.%03lu ", width, msecs, usecs);
+}
+
+/*
+ * returns runtime data for event, allocating memory for it the
+ * first time it is used.
+ */
+static struct evsel_runtime *perf_evsel__get_runtime(struct perf_evsel *evsel)
+{
+ struct evsel_runtime *r = evsel->priv;
+
+ if (r == NULL) {
+ r = zalloc(sizeof(struct evsel_runtime));
+ evsel->priv = r;
+ }
+
+ return r;
+}
+
+/*
+ * save last time event was seen per cpu
+ */
+static void perf_evsel__save_time(struct perf_evsel *evsel,
+ u64 timestamp, u32 cpu)
+{
+ struct evsel_runtime *r = perf_evsel__get_runtime(evsel);
+
+ if (r == NULL)
+ return;
+
+ if ((cpu >= r->ncpu) || (r->last_time == NULL)) {
+ int i, n = __roundup_pow_of_two(cpu+1);
+ void *p = r->last_time;
+
+ p = realloc(r->last_time, n * sizeof(u64));
+ if (!p)
+ return;
+
+ r->last_time = p;
+ for (i = r->ncpu; i < n; ++i)
+ r->last_time[i] = (u64) 0;
+
+ r->ncpu = n;
+ }
+
+ r->last_time[cpu] = timestamp;
+}
+
+/* returns last time this event was seen on the given cpu */
+static u64 perf_evsel__get_time(struct perf_evsel *evsel, u32 cpu)
+{
+ struct evsel_runtime *r = perf_evsel__get_runtime(evsel);
+
+ if ((r == NULL) || (r->last_time == NULL) || (cpu >= r->ncpu))
+ return 0;
+
+ return r->last_time[cpu];
+}
+
+static int comm_width = 20;
+
+static char *timehist_get_commstr(struct thread *thread)
+{
+ static char str[32];
+ const char *comm = thread__comm_str(thread);
+ pid_t tid = thread->tid;
+ pid_t pid = thread->pid_;
+ int n;
+
+ if (pid == 0)
+ n = scnprintf(str, sizeof(str), "%s", comm);
+
+ else if (tid != pid)
+ n = scnprintf(str, sizeof(str), "%s[%d/%d]", comm, tid, pid);
+
+ else
+ n = scnprintf(str, sizeof(str), "%s[%d]", comm, tid);
+
+ if (n > comm_width)
+ comm_width = n;
+
+ return str;
+}
+
+static void timehist_header(void)
+{
+ printf("%15s %6s ", "time", "cpu");
+
+ printf(" %-20s %9s %9s %9s",
+ "task name", "wait time", "sch delay", "run time");
+
+ printf("\n");
+
+ /*
+ * units row
+ */
+ printf("%15s %-6s ", "", "");
+
+ printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
+
+ /*
+ * separator
+ */
+ printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
+
+ printf(" %.20s %.9s %.9s %.9s",
+ graph_dotted_line, graph_dotted_line, graph_dotted_line,
+ graph_dotted_line);
+
+ printf("\n");
+}
+
+static void timehist_print_sample(struct perf_sample *sample,
+ struct thread *thread)
+{
+ struct thread_runtime *tr = thread__priv(thread);
+ char tstr[64];
+
+ timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+ printf("%15s [%04d] ", tstr, sample->cpu);
+
+ printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+ print_sched_time(tr->dt_wait, 6);
+ print_sched_time(tr->dt_delay, 6);
+ print_sched_time(tr->dt_run, 6);
+ printf("\n");
+}
+
+/*
+ * Explanation of delta-time stats:
+ *
+ * t = time of current schedule out event
+ * tprev = time of previous sched out event
+ * also time of schedule-in event for current task
+ * last_time = time of last sched change event for current task
+ * (i.e, time process was last scheduled out)
+ * ready_to_run = time of wakeup for current task
+ *
+ * -----|------------|------------|------------|------
+ * last ready tprev t
+ * time to run
+ *
+ * |-------- dt_wait --------|
+ * |- dt_delay -|-- dt_run --|
+ *
+ * dt_run = run time of current task
+ * dt_wait = time between last schedule out event for task and tprev
+ * represents time spent off the cpu
+ * dt_delay = time between wakeup and schedule-in of task
+ */
+
+static void timehist_update_runtime_stats(struct thread_runtime *r,
+ u64 t, u64 tprev)
+{
+ r->dt_delay = 0;
+ r->dt_wait = 0;
+ r->dt_run = 0;
+ if (tprev) {
+ r->dt_run = t - tprev;
+ if (r->ready_to_run) {
+ if (r->ready_to_run > tprev)
+ pr_debug("time travel: wakeup time for task > previous sched_switch event\n");
+ else
+ r->dt_delay = tprev - r->ready_to_run;
+ }
+
+ if (r->last_time > tprev)
+ pr_debug("time travel: last sched out time for task > previous sched_switch event\n");
+ else if (r->last_time)
+ r->dt_wait = tprev - r->last_time;
+ }
+
+ update_stats(&r->run_stats, r->dt_run);
+ r->total_run_time += r->dt_run;
+}
+
+static bool is_idle_sample(struct perf_sample *sample,
+ struct perf_evsel *evsel)
+{
+ /* pid 0 == swapper == idle task */
+ if (sample->pid == 0)
+ return true;
+
+ if (strcmp(perf_evsel__name(evsel), "sched:sched_switch") == 0) {
+ if (perf_evsel__intval(evsel, sample, "prev_pid") == 0)
+ return true;
+ }
+ return false;
+}
+
+/*
+ * Track idle stats per cpu by maintaining a local thread
+ * struct for the idle task on each cpu.
+ */
+static int init_idle_threads(int ncpu)
+{
+ int i;
+
+ idle_threads = zalloc(ncpu * sizeof(struct thread *));
+ if (!idle_threads)
+ return -ENOMEM;
+
+ idle_max_cpu = ncpu - 1;
+
+ /* allocate the actual thread struct if needed */
+ for (i = 0; i < ncpu; ++i) {
+ idle_threads[i] = thread__new(0, 0);
+ if (idle_threads[i] == NULL)
+ return -ENOMEM;
+
+ thread__set_comm(idle_threads[i], idle_comm, 0);
+ }
+
+ return 0;
+}
+
+static void free_idle_threads(void)
+{
+ int i;
+
+ if (idle_threads == NULL)
+ return;
+
+ for (i = 0; i <= idle_max_cpu; ++i) {
+ if ((idle_threads[i]))
+ thread__delete(idle_threads[i]);
+ }
+
+ free(idle_threads);
+}
+
+static struct thread *get_idle_thread(int cpu)
+{
+ /*
+ * expand/allocate array of pointers to local thread
+ * structs if needed
+ */
+ if ((cpu >= idle_max_cpu) || (idle_threads == NULL)) {
+ int i, j = __roundup_pow_of_two(cpu+1);
+ void *p;
+
+ p = realloc(idle_threads, j * sizeof(struct thread *));
+ if (!p)
+ return NULL;
+
+ idle_threads = (struct thread **) p;
+ i = idle_max_cpu ? idle_max_cpu + 1 : 0;
+ for (; i < j; ++i)
+ idle_threads[i] = NULL;
+
+ idle_max_cpu = j;
+ }
+
+ /* allocate a new thread struct if needed */
+ if (idle_threads[cpu] == NULL) {
+ idle_threads[cpu] = thread__new(0, 0);
+
+ if (idle_threads[cpu]) {
+ idle_threads[cpu]->tid = 0;
+ thread__set_comm(idle_threads[cpu], idle_comm, 0);
+ }
+ }
+
+ return idle_threads[cpu];
+}
+
+/*
+ * handle runtime stats saved per thread
+ */
+static struct thread_runtime *thread__init_runtime(struct thread *thread)
+{
+ struct thread_runtime *r;
+
+ r = zalloc(sizeof(struct thread_runtime));
+ if (!r)
+ return NULL;
+
+ init_stats(&r->run_stats);
+ thread__set_priv(thread, r);
+
+ return r;
+}
+
+static struct thread_runtime *thread__get_runtime(struct thread *thread)
+{
+ struct thread_runtime *tr;
+
+ tr = thread__priv(thread);
+ if (tr == NULL) {
+ tr = thread__init_runtime(thread);
+ if (tr == NULL)
+ pr_debug("Failed to malloc memory for runtime data.\n");
+ }
+
+ return tr;
+}
+
+static struct thread *timehist_get_thread(struct perf_sample *sample,
+ struct machine *machine,
+ struct perf_evsel *evsel)
+{
+ struct thread *thread;
+
+ if (is_idle_sample(sample, evsel)) {
+ thread = get_idle_thread(sample->cpu);
+ if (thread == NULL)
+ pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
+
+ } else {
+ thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+ if (thread == NULL) {
+ pr_debug("Failed to get thread for tid %d. skipping sample.\n",
+ sample->tid);
+ }
+ }
+
+ return thread;
+}
+
+static bool timehist_skip_sample(struct thread *thread)
+{
+ bool rc = false;
+
+ if (thread__is_filtered(thread))
+ rc = true;
+
+ return rc;
+}
+
+static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
+ union perf_event *event __maybe_unused,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct thread *thread;
+ struct thread_runtime *tr = NULL;
+ /* want pid of awakened task not pid in sample */
+ const u32 pid = perf_evsel__intval(evsel, sample, "pid");
+
+ thread = machine__findnew_thread(machine, 0, pid);
+ if (thread == NULL)
+ return -1;
+
+ tr = thread__get_runtime(thread);
+ if (tr == NULL)
+ return -1;
+
+ if (tr->ready_to_run == 0)
+ tr->ready_to_run = sample->time;
+
+ return 0;
+}
+
+static int timehist_sched_change_event(struct perf_tool *tool __maybe_unused,
+ union perf_event *event,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct addr_location al;
+ struct thread *thread;
+ struct thread_runtime *tr = NULL;
+ u64 tprev;
+ int rc = 0;
+
+ if (machine__resolve(machine, &al, sample) < 0) {
+ pr_err("problem processing %d event. skipping it\n",
+ event->header.type);
+ rc = -1;
+ goto out;
+ }
+
+ thread = timehist_get_thread(sample, machine, evsel);
+ if (thread == NULL) {
+ rc = -1;
+ goto out;
+ }
+
+ if (timehist_skip_sample(thread))
+ goto out;
+
+ tr = thread__get_runtime(thread);
+ if (tr == NULL) {
+ rc = -1;
+ goto out;
+ }
+
+ tprev = perf_evsel__get_time(evsel, sample->cpu);
+
+ timehist_update_runtime_stats(tr, sample->time, tprev);
+ timehist_print_sample(sample, thread);
+
+out:
+ if (tr) {
+ /* time of this sched_switch event becomes last time task seen */
+ tr->last_time = sample->time;
+
+ /* sched out event for task so reset ready to run time */
+ tr->ready_to_run = 0;
+ }
+
+ perf_evsel__save_time(evsel, sample->time, sample->cpu);
+
+ return rc;
+}
+
+static int timehist_sched_switch_event(struct perf_tool *tool,
+ union perf_event *event,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ return timehist_sched_change_event(tool, event, evsel, sample, machine);
+}
+
+static int process_lost(struct perf_tool *tool __maybe_unused,
+ union perf_event *event,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ char tstr[64];
+
+ timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+ printf("%15s ", tstr);
+ printf("lost %" PRIu64 " events on cpu %d\n", event->lost.lost, sample->cpu);
+
+ return 0;
+}
+
+
+typedef int (*sched_handler)(struct perf_tool *tool,
+ union perf_event *event,
+ struct perf_evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine);
+
+static int perf_timehist__process_sample(struct perf_tool *tool,
+ union perf_event *event,
+ struct perf_sample *sample,
+ struct perf_evsel *evsel,
+ struct machine *machine)
+{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
+ int err = 0;
+ int this_cpu = sample->cpu;
+
+ if (this_cpu > sched->max_cpu)
+ sched->max_cpu = this_cpu;
+
+ if (evsel->handler != NULL) {
+ sched_handler f = evsel->handler;
+
+ err = f(tool, event, evsel, sample, machine);
+ }
+
+ return err;
+}
+
+static int perf_sched__timehist(struct perf_sched *sched)
+{
+ const struct perf_evsel_str_handler handlers[] = {
+ { "sched:sched_switch", timehist_sched_switch_event, },
+ { "sched:sched_wakeup", timehist_sched_wakeup_event, },
+ { "sched:sched_wakeup_new", timehist_sched_wakeup_event, },
+ };
+ struct perf_data_file file = {
+ .path = input_name,
+ .mode = PERF_DATA_MODE_READ,
+ };
+
+ struct perf_session *session;
+ int err = -1;
+
+ /*
+ * event handlers for timehist option
+ */
+ sched->tool.sample = perf_timehist__process_sample;
+ sched->tool.mmap = perf_event__process_mmap;
+ sched->tool.comm = perf_event__process_comm;
+ sched->tool.exit = perf_event__process_exit;
+ sched->tool.fork = perf_event__process_fork;
+ sched->tool.lost = process_lost;
+ sched->tool.attr = perf_event__process_attr;
+ sched->tool.tracing_data = perf_event__process_tracing_data;
+ sched->tool.build_id = perf_event__process_build_id;
+
+ sched->tool.ordered_events = true;
+ sched->tool.ordering_requires_timestamps = true;
+
+ session = perf_session__new(&file, false, &sched->tool);
+ if (session == NULL)
+ return -ENOMEM;
+
+ symbol__init(&session->header.env);
+
+ setup_pager();
+
+ /* setup per-evsel handlers */
+ if (perf_session__set_tracepoints_handlers(session, handlers))
+ goto out;
+
+ if (!perf_session__has_traces(session, "record -R"))
+ goto out;
+
+ /* pre-allocate struct for per-CPU idle stats */
+ sched->max_cpu = session->header.env.nr_cpus_online;
+ if (sched->max_cpu == 0)
+ sched->max_cpu = 4;
+ if (init_idle_threads(sched->max_cpu))
+ goto out;
+
+ timehist_header();
+
+ err = perf_session__process_events(session);
+ if (err) {
+ pr_err("Failed to process events, error %d", err);
+ goto out;
+ }
+
+out:
+ free_idle_threads();
+ perf_session__delete(session);
+
+ return err;
+}
+
+
static void print_bad_events(struct perf_sched *sched)
{
if (sched->nr_unordered_timestamps && sched->nr_timestamps) {
@@ -1970,8 +2535,6 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
const struct option latency_options[] = {
OPT_STRING('s', "sort", &sched.sort_order, "key[,key2...]",
"sort by key(s): runtime, switch, avg, max"),
- OPT_INCR('v', "verbose", &verbose,
- "be more verbose (show symbol address, etc)"),
OPT_INTEGER('C', "CPU", &sched.profile_cpu,
"CPU to profile on"),
OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
@@ -1983,8 +2546,6 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
const struct option replay_options[] = {
OPT_UINTEGER('r', "repeat", &sched.replay_repeat,
"repeat the workload replay N times (-1: infinite)"),
- OPT_INCR('v', "verbose", &verbose,
- "be more verbose (show symbol address, etc)"),
OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
"dump raw trace in ASCII"),
OPT_BOOLEAN('f', "force", &sched.force, "don't complain, do it"),
@@ -2001,6 +2562,16 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"display given CPUs in map"),
OPT_PARENT(sched_options)
};
+ const struct option timehist_options[] = {
+ OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name,
+ "file", "vmlinux pathname"),
+ OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
+ "file", "kallsyms pathname"),
+ OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
+ "Look for files with symbols relative to this directory"),
+ OPT_PARENT(sched_options)
+ };
+
const char * const latency_usage[] = {
"perf sched latency [<options>]",
NULL
@@ -2013,8 +2584,13 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"perf sched map [<options>]",
NULL
};
+ const char * const timehist_usage[] = {
+ "perf sched timehist [<options>]",
+ NULL
+ };
const char *const sched_subcommands[] = { "record", "latency", "map",
- "replay", "script", NULL };
+ "replay", "script",
+ "timehist", NULL };
const char *sched_usage[] = {
NULL,
NULL
@@ -2077,6 +2653,14 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
usage_with_options(replay_usage, replay_options);
}
return perf_sched__replay(&sched);
+ } else if (!strcmp(argv[0], "timehist")) {
+ if (argc) {
+ argc = parse_options(argc, argv, timehist_options,
+ timehist_usage, 0);
+ if (argc)
+ usage_with_options(timehist_usage, timehist_options);
+ }
+ return perf_sched__timehist(&sched);
} else {
usage_with_options(sched_usage, sched_options);
}
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 4/8] perf sched timehist: Add summary options
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (2 preceding siblings ...)
2016-11-16 6:06 ` [PATCH v2 3/8] perf sched timehist: Introduce timehist command Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-24 4:19 ` [tip:perf/core] " tip-bot for David Ahern
2016-11-16 6:06 ` [PATCH v2 5/8] perf sched timehist: Add -w/--wakeups option Namhyung Kim
` (6 subsequent siblings)
10 siblings, 1 reply; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
From: David Ahern <dsahern@gmail.com>
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 <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
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 c0ac0c9557e8..1e7d81ad5ec6 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("<no still running tasks>\n");
+
+ printf("\nTerminated tasks:\n");
+ machine__for_each_thread(m, show_deadthread_runtime, &totals);
+ if (task_count == totals.task_count)
+ printf("<no terminated tasks>\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)
};
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* [tip:perf/core] perf sched timehist: Add summary options
2016-11-16 6:06 ` [PATCH v2 4/8] perf sched timehist: Add summary options Namhyung Kim
@ 2016-11-24 4:19 ` tip-bot for David Ahern
0 siblings, 0 replies; 23+ messages in thread
From: tip-bot for David Ahern @ 2016-11-24 4:19 UTC (permalink / raw)
To: linux-tip-commits
Cc: hpa, andi, acme, a.p.zijlstra, dsahern, mingo, jolsa, namhyung,
linux-kernel, eranian, tglx
Commit-ID: 52df138caaa8daaaf4e0dc64428ef06f303a8dbf
Gitweb: http://git.kernel.org/tip/52df138caaa8daaaf4e0dc64428ef06f303a8dbf
Author: David Ahern <dsahern@gmail.com>
AuthorDate: Wed, 16 Nov 2016 15:06:30 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
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 <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
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 <acme@redhat.com>
---
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("<no still running tasks>\n");
+
+ printf("\nTerminated tasks:\n");
+ machine__for_each_thread(m, show_deadthread_runtime, &totals);
+ if (task_count == totals.task_count)
+ printf("<no terminated tasks>\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)
};
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 5/8] perf sched timehist: Add -w/--wakeups option
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (3 preceding siblings ...)
2016-11-16 6:06 ` [PATCH v2 4/8] perf sched timehist: Add summary options Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-24 4:20 ` [tip:perf/core] " tip-bot for David Ahern
2016-11-16 6:06 ` [PATCH v2 6/8] perf sched timehist: Add call graph options Namhyung Kim
` (5 subsequent siblings)
10 siblings, 1 reply; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
From: David Ahern <dsahern@gmail.com>
The -w option is to show wakeup events with timehist.
$ perf sched timehist -w
time cpu task name b/n time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ -------------------- --------- --------- ---------
2412598.429689 [0002] perf[7219] awakened: perf[7220]
2412598.429696 [0009] <idle> 0.000 0.000 0.000
2412598.429767 [0002] perf[7219] 0.000 0.000 0.000
2412598.429780 [0009] perf[7220] awakened: migration/9[53]
...
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 58 ++++++++++++++++++++++++++++++++++++++++++----
1 file changed, 54 insertions(+), 4 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1e7d81ad5ec6..8fb7bcc2cb76 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -198,6 +198,7 @@ struct perf_sched {
/* options for timehist command */
bool summary;
bool summary_only;
+ bool show_wakeups;
u64 skipped_samples;
};
@@ -1807,7 +1808,8 @@ static void timehist_header(void)
printf("\n");
}
-static void timehist_print_sample(struct perf_sample *sample,
+static void timehist_print_sample(struct perf_sched *sched,
+ struct perf_sample *sample,
struct thread *thread)
{
struct thread_runtime *tr = thread__priv(thread);
@@ -1821,6 +1823,10 @@ static void timehist_print_sample(struct perf_sample *sample,
print_sched_time(tr->dt_wait, 6);
print_sched_time(tr->dt_delay, 6);
print_sched_time(tr->dt_run, 6);
+
+ if (sched->show_wakeups)
+ printf(" %-*s", comm_width, "");
+
printf("\n");
}
@@ -2028,12 +2034,44 @@ static bool timehist_skip_sample(struct perf_sched *sched,
return rc;
}
-static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
+static void timehist_print_wakeup_event(struct perf_sched *sched,
+ struct perf_sample *sample,
+ struct machine *machine,
+ struct thread *awakened)
+{
+ struct thread *thread;
+ char tstr[64];
+
+ thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+ if (thread == NULL)
+ return;
+
+ /* show wakeup unless both awakee and awaker are filtered */
+ if (timehist_skip_sample(sched, thread) &&
+ timehist_skip_sample(sched, awakened)) {
+ return;
+ }
+
+ timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+ printf("%15s [%04d] ", tstr, sample->cpu);
+
+ printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+ /* dt spacer */
+ printf(" %9s %9s %9s ", "", "", "");
+
+ printf("awakened: %s", timehist_get_commstr(awakened));
+
+ printf("\n");
+}
+
+static int timehist_sched_wakeup_event(struct perf_tool *tool,
union perf_event *event __maybe_unused,
struct perf_evsel *evsel,
struct perf_sample *sample,
struct machine *machine)
{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
struct thread *thread;
struct thread_runtime *tr = NULL;
/* want pid of awakened task not pid in sample */
@@ -2050,6 +2088,10 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
if (tr->ready_to_run == 0)
tr->ready_to_run = sample->time;
+ /* show wakeups if requested */
+ if (sched->show_wakeups)
+ timehist_print_wakeup_event(sched, sample, machine, thread);
+
return 0;
}
@@ -2059,12 +2101,12 @@ static int timehist_sched_change_event(struct perf_tool *tool,
struct perf_sample *sample,
struct machine *machine)
{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
struct addr_location al;
struct thread *thread;
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",
@@ -2092,7 +2134,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
timehist_update_runtime_stats(tr, sample->time, tprev);
if (!sched->summary_only)
- timehist_print_sample(sample, thread);
+ timehist_print_sample(sched, sample, thread);
out:
if (tr) {
@@ -2723,6 +2765,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"Show only syscall summary with statistics"),
OPT_BOOLEAN('S', "with-summary", &sched.summary,
"Show all syscalls and summary with statistics"),
+ OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
OPT_PARENT(sched_options)
};
@@ -2814,6 +2857,13 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
if (argc)
usage_with_options(timehist_usage, timehist_options);
}
+ if (sched.show_wakeups && sched.summary_only) {
+ pr_err(" Error: -s and -w are mutually exclusive.\n");
+ parse_options_usage(timehist_usage, timehist_options, "s", true);
+ parse_options_usage(NULL, timehist_options, "w", true);
+ return -EINVAL;
+ }
+
return perf_sched__timehist(&sched);
} else {
usage_with_options(sched_usage, sched_options);
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* [tip:perf/core] perf sched timehist: Add -w/--wakeups option
2016-11-16 6:06 ` [PATCH v2 5/8] perf sched timehist: Add -w/--wakeups option Namhyung Kim
@ 2016-11-24 4:20 ` tip-bot for David Ahern
0 siblings, 0 replies; 23+ messages in thread
From: tip-bot for David Ahern @ 2016-11-24 4:20 UTC (permalink / raw)
To: linux-tip-commits
Cc: tglx, andi, eranian, linux-kernel, namhyung, acme, hpa, dsahern,
a.p.zijlstra, jolsa, mingo
Commit-ID: fc1469f1b20777929a47f6f8e55bca12c6f142ac
Gitweb: http://git.kernel.org/tip/fc1469f1b20777929a47f6f8e55bca12c6f142ac
Author: David Ahern <dsahern@gmail.com>
AuthorDate: Wed, 16 Nov 2016 15:06:31 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:08 -0300
perf sched timehist: Add -w/--wakeups option
The -w option is to show wakeup events with timehist.
$ perf sched timehist -w
time cpu task name b/n time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ -------------------- --------- --------- ---------
2412598.429689 [0002] perf[7219] awakened: perf[7220]
2412598.429696 [0009] <idle> 0.000 0.000 0.000
2412598.429767 [0002] perf[7219] 0.000 0.000 0.000
2412598.429780 [0009] perf[7220] awakened: migration/9[53]
...
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-6-namhyung@kernel.org
[ Add documentation based on above commit message ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/Documentation/perf-sched.txt | 4 +++
tools/perf/builtin-sched.c | 58 ++++++++++++++++++++++++++++++---
2 files changed, 58 insertions(+), 4 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 72730da..9a77bc7 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -112,6 +112,10 @@ OPTIONS for 'perf sched timehist'
--symfs=<directory>::
Look for files with symbols relative to this directory.
+-w::
+--wakeups::
+ Show wakeup events.
+
SEE ALSO
--------
linkperf:perf-record[1]
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1e7d81a..8fb7bcc 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -198,6 +198,7 @@ struct perf_sched {
/* options for timehist command */
bool summary;
bool summary_only;
+ bool show_wakeups;
u64 skipped_samples;
};
@@ -1807,7 +1808,8 @@ static void timehist_header(void)
printf("\n");
}
-static void timehist_print_sample(struct perf_sample *sample,
+static void timehist_print_sample(struct perf_sched *sched,
+ struct perf_sample *sample,
struct thread *thread)
{
struct thread_runtime *tr = thread__priv(thread);
@@ -1821,6 +1823,10 @@ static void timehist_print_sample(struct perf_sample *sample,
print_sched_time(tr->dt_wait, 6);
print_sched_time(tr->dt_delay, 6);
print_sched_time(tr->dt_run, 6);
+
+ if (sched->show_wakeups)
+ printf(" %-*s", comm_width, "");
+
printf("\n");
}
@@ -2028,12 +2034,44 @@ static bool timehist_skip_sample(struct perf_sched *sched,
return rc;
}
-static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
+static void timehist_print_wakeup_event(struct perf_sched *sched,
+ struct perf_sample *sample,
+ struct machine *machine,
+ struct thread *awakened)
+{
+ struct thread *thread;
+ char tstr[64];
+
+ thread = machine__findnew_thread(machine, sample->pid, sample->tid);
+ if (thread == NULL)
+ return;
+
+ /* show wakeup unless both awakee and awaker are filtered */
+ if (timehist_skip_sample(sched, thread) &&
+ timehist_skip_sample(sched, awakened)) {
+ return;
+ }
+
+ timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
+ printf("%15s [%04d] ", tstr, sample->cpu);
+
+ printf(" %-*s ", comm_width, timehist_get_commstr(thread));
+
+ /* dt spacer */
+ printf(" %9s %9s %9s ", "", "", "");
+
+ printf("awakened: %s", timehist_get_commstr(awakened));
+
+ printf("\n");
+}
+
+static int timehist_sched_wakeup_event(struct perf_tool *tool,
union perf_event *event __maybe_unused,
struct perf_evsel *evsel,
struct perf_sample *sample,
struct machine *machine)
{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
struct thread *thread;
struct thread_runtime *tr = NULL;
/* want pid of awakened task not pid in sample */
@@ -2050,6 +2088,10 @@ static int timehist_sched_wakeup_event(struct perf_tool *tool __maybe_unused,
if (tr->ready_to_run == 0)
tr->ready_to_run = sample->time;
+ /* show wakeups if requested */
+ if (sched->show_wakeups)
+ timehist_print_wakeup_event(sched, sample, machine, thread);
+
return 0;
}
@@ -2059,12 +2101,12 @@ static int timehist_sched_change_event(struct perf_tool *tool,
struct perf_sample *sample,
struct machine *machine)
{
+ struct perf_sched *sched = container_of(tool, struct perf_sched, tool);
struct addr_location al;
struct thread *thread;
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",
@@ -2092,7 +2134,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
timehist_update_runtime_stats(tr, sample->time, tprev);
if (!sched->summary_only)
- timehist_print_sample(sample, thread);
+ timehist_print_sample(sched, sample, thread);
out:
if (tr) {
@@ -2723,6 +2765,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"Show only syscall summary with statistics"),
OPT_BOOLEAN('S', "with-summary", &sched.summary,
"Show all syscalls and summary with statistics"),
+ OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
OPT_PARENT(sched_options)
};
@@ -2814,6 +2857,13 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
if (argc)
usage_with_options(timehist_usage, timehist_options);
}
+ if (sched.show_wakeups && sched.summary_only) {
+ pr_err(" Error: -s and -w are mutually exclusive.\n");
+ parse_options_usage(timehist_usage, timehist_options, "s", true);
+ parse_options_usage(NULL, timehist_options, "w", true);
+ return -EINVAL;
+ }
+
return perf_sched__timehist(&sched);
} else {
usage_with_options(sched_usage, sched_options);
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 6/8] perf sched timehist: Add call graph options
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (4 preceding siblings ...)
2016-11-16 6:06 ` [PATCH v2 5/8] perf sched timehist: Add -w/--wakeups option Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-24 4:20 ` [tip:perf/core] " tip-bot for David Ahern
2016-11-16 6:06 ` [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option Namhyung Kim
` (4 subsequent siblings)
10 siblings, 1 reply; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
From: David Ahern <dsahern@gmail.com>
If callchains were recorded they are appended to the line with a default stack depth of 5:
79371.874569 [0011] gcc[31949] 0.014 0.000 1.148 wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
79371.874591 [0010] gcc[31951] 0.000 0.000 0.024 __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
79371.874603 [0010] migration/10[59] 3.350 0.004 0.011 smpboot_thread_fn <- kthread <- ret_from_fork
79371.874604 [0011] <idle> 1.148 0.000 0.035 cpu_startup_entry <- start_secondary
79371.874723 [0005] <idle> 0.016 0.000 1.383 cpu_startup_entry <- start_secondary
79371.874746 [0005] gcc[31949] 0.153 0.078 0.022 do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid
--no-call-graph can be used to not show the callchains. --max-stack is used
to control the number of frames shown (default of 5). -x/--excl options can
be used to collapse redundant callchains to get more relevant data on screen.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 88 ++++++++++++++++++++++++++++++++++++++++++----
1 file changed, 82 insertions(+), 6 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 8fb7bcc2cb76..1f8731640809 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -14,6 +14,7 @@
#include "util/thread_map.h"
#include "util/color.h"
#include "util/stat.h"
+#include "util/callchain.h"
#include <subcmd/parse-options.h>
#include "util/trace-event.h"
@@ -198,6 +199,8 @@ struct perf_sched {
/* options for timehist command */
bool summary;
bool summary_only;
+ bool show_callchain;
+ unsigned int max_stack;
bool show_wakeups;
u64 skipped_samples;
};
@@ -1810,6 +1813,7 @@ static void timehist_header(void)
static void timehist_print_sample(struct perf_sched *sched,
struct perf_sample *sample,
+ struct addr_location *al,
struct thread *thread)
{
struct thread_runtime *tr = thread__priv(thread);
@@ -1827,6 +1831,18 @@ static void timehist_print_sample(struct perf_sched *sched,
if (sched->show_wakeups)
printf(" %-*s", comm_width, "");
+ if (thread->tid == 0)
+ goto out;
+
+ if (sched->show_callchain)
+ printf(" ");
+
+ sample__fprintf_sym(sample, al, 0,
+ EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
+ EVSEL__PRINT_CALLCHAIN_ARROW,
+ &callchain_cursor, stdout);
+
+out:
printf("\n");
}
@@ -1878,9 +1894,14 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
r->total_run_time += r->dt_run;
}
-static bool is_idle_sample(struct perf_sample *sample,
- struct perf_evsel *evsel)
+static bool is_idle_sample(struct perf_sched *sched,
+ struct perf_sample *sample,
+ struct perf_evsel *evsel,
+ struct machine *machine)
{
+ struct thread *thread;
+ struct callchain_cursor *cursor = &callchain_cursor;
+
/* pid 0 == swapper == idle task */
if (sample->pid == 0)
return true;
@@ -1889,6 +1910,25 @@ static bool is_idle_sample(struct perf_sample *sample,
if (perf_evsel__intval(evsel, sample, "prev_pid") == 0)
return true;
}
+
+ /* want main thread for process - has maps */
+ thread = machine__findnew_thread(machine, sample->pid, sample->pid);
+ if (thread == NULL) {
+ pr_debug("Failed to get thread for pid %d.\n", sample->pid);
+ return false;
+ }
+
+ if (!symbol_conf.use_callchain || sample->callchain == NULL)
+ return false;
+
+ if (thread__resolve_callchain(thread, cursor, evsel, sample,
+ NULL, NULL, sched->max_stack) != 0) {
+ if (verbose)
+ error("Failed to resolve callchain. Skipping\n");
+
+ return false;
+ }
+ callchain_cursor_commit(cursor);
return false;
}
@@ -1999,13 +2039,14 @@ static struct thread_runtime *thread__get_runtime(struct thread *thread)
return tr;
}
-static struct thread *timehist_get_thread(struct perf_sample *sample,
+static struct thread *timehist_get_thread(struct perf_sched *sched,
+ struct perf_sample *sample,
struct machine *machine,
struct perf_evsel *evsel)
{
struct thread *thread;
- if (is_idle_sample(sample, evsel)) {
+ if (is_idle_sample(sched, sample, evsel, machine)) {
thread = get_idle_thread(sample->cpu);
if (thread == NULL)
pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
@@ -2115,7 +2156,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
goto out;
}
- thread = timehist_get_thread(sample, machine, evsel);
+ thread = timehist_get_thread(sched, sample, machine, evsel);
if (thread == NULL) {
rc = -1;
goto out;
@@ -2134,7 +2175,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
timehist_update_runtime_stats(tr, sample->time, tprev);
if (!sched->summary_only)
- timehist_print_sample(sched, sample, thread);
+ timehist_print_sample(sched, sample, &al, thread);
out:
if (tr) {
@@ -2327,6 +2368,30 @@ static int perf_timehist__process_sample(struct perf_tool *tool,
return err;
}
+static int timehist_check_attr(struct perf_sched *sched,
+ struct perf_evlist *evlist)
+{
+ struct perf_evsel *evsel;
+ struct evsel_runtime *er;
+
+ list_for_each_entry(evsel, &evlist->entries, node) {
+ er = perf_evsel__get_runtime(evsel);
+ if (er == NULL) {
+ pr_err("Failed to allocate memory for evsel runtime data\n");
+ return -1;
+ }
+
+ if (sched->show_callchain &&
+ !(evsel->attr.sample_type & PERF_SAMPLE_CALLCHAIN)) {
+ pr_info("Samples do not have callchains.\n");
+ sched->show_callchain = 0;
+ symbol_conf.use_callchain = 0;
+ }
+ }
+
+ return 0;
+}
+
static int perf_sched__timehist(struct perf_sched *sched)
{
const struct perf_evsel_str_handler handlers[] = {
@@ -2359,6 +2424,8 @@ static int perf_sched__timehist(struct perf_sched *sched)
sched->tool.ordered_events = true;
sched->tool.ordering_requires_timestamps = true;
+ symbol_conf.use_callchain = sched->show_callchain;
+
session = perf_session__new(&file, false, &sched->tool);
if (session == NULL)
return -ENOMEM;
@@ -2367,6 +2434,9 @@ static int perf_sched__timehist(struct perf_sched *sched)
symbol__init(&session->header.env);
+ if (timehist_check_attr(sched, evlist) != 0)
+ goto out;
+
setup_pager();
/* setup per-evsel handlers */
@@ -2714,6 +2784,8 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
.next_shortname1 = 'A',
.next_shortname2 = '0',
.skip_merge = 0,
+ .show_callchain = 1,
+ .max_stack = 5,
};
const struct option sched_options[] = {
OPT_STRING('i', "input", &input_name, "file",
@@ -2759,6 +2831,10 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"file", "vmlinux pathname"),
OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
"file", "kallsyms pathname"),
+ OPT_BOOLEAN('g', "call-graph", &sched.show_callchain,
+ "Display call chains if present (default on)"),
+ OPT_UINTEGER(0, "max-stack", &sched.max_stack,
+ "Maximum number of functions to display backtrace."),
OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
"Look for files with symbols relative to this directory"),
OPT_BOOLEAN('s', "summary", &sched.summary_only,
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* [tip:perf/core] perf sched timehist: Add call graph options
2016-11-16 6:06 ` [PATCH v2 6/8] perf sched timehist: Add call graph options Namhyung Kim
@ 2016-11-24 4:20 ` tip-bot for David Ahern
0 siblings, 0 replies; 23+ messages in thread
From: tip-bot for David Ahern @ 2016-11-24 4:20 UTC (permalink / raw)
To: linux-tip-commits
Cc: tglx, jolsa, andi, a.p.zijlstra, eranian, linux-kernel, namhyung,
acme, hpa, mingo, dsahern
Commit-ID: 6c973c90852c3fa4b4e76a061ce89dcd373efccc
Gitweb: http://git.kernel.org/tip/6c973c90852c3fa4b4e76a061ce89dcd373efccc
Author: David Ahern <dsahern@gmail.com>
AuthorDate: Wed, 16 Nov 2016 15:06:32 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:09 -0300
perf sched timehist: Add call graph options
If callchains were recorded they are appended to the line with a default stack depth of 5:
1.874569 [0011] gcc[31949] 0.014 0.000 1.148 wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
1.874591 [0010] gcc[31951] 0.000 0.000 0.024 __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
1.874603 [0010] migration/10[59] 3.350 0.004 0.011 smpboot_thread_fn <- kthread <- ret_from_fork
1.874604 [0011] <idle> 1.148 0.000 0.035 cpu_startup_entry <- start_secondary
1.874723 [0005] <idle> 0.016 0.000 1.383 cpu_startup_entry <- start_secondary
1.874746 [0005] gcc[31949] 0.153 0.078 0.022 do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid
--no-call-graph can be used to not show the callchains. --max-stack is used
to control the number of frames shown (default of 5). -x/--excl options can
be used to collapse redundant callchains to get more relevant data on screen.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-7-namhyung@kernel.org
[ Add documentation based on above commit message ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/Documentation/perf-sched.txt | 7 +++
tools/perf/builtin-sched.c | 88 ++++++++++++++++++++++++++++++---
2 files changed, 89 insertions(+), 6 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 9a77bc7..8345208 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -99,6 +99,13 @@ OPTIONS for 'perf sched timehist'
--kallsyms=<file>::
kallsyms pathname
+-g::
+--no-call-graph::
+ Do not display call chains if present.
+
+--max-stack::
+ Maximum number of functions to display in backtrace, default 5.
+
-s::
--summary::
Show only a summary of scheduling by thread with min, max, and average
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 8fb7bcc..1f87316 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -14,6 +14,7 @@
#include "util/thread_map.h"
#include "util/color.h"
#include "util/stat.h"
+#include "util/callchain.h"
#include <subcmd/parse-options.h>
#include "util/trace-event.h"
@@ -198,6 +199,8 @@ struct perf_sched {
/* options for timehist command */
bool summary;
bool summary_only;
+ bool show_callchain;
+ unsigned int max_stack;
bool show_wakeups;
u64 skipped_samples;
};
@@ -1810,6 +1813,7 @@ static void timehist_header(void)
static void timehist_print_sample(struct perf_sched *sched,
struct perf_sample *sample,
+ struct addr_location *al,
struct thread *thread)
{
struct thread_runtime *tr = thread__priv(thread);
@@ -1827,6 +1831,18 @@ static void timehist_print_sample(struct perf_sched *sched,
if (sched->show_wakeups)
printf(" %-*s", comm_width, "");
+ if (thread->tid == 0)
+ goto out;
+
+ if (sched->show_callchain)
+ printf(" ");
+
+ sample__fprintf_sym(sample, al, 0,
+ EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
+ EVSEL__PRINT_CALLCHAIN_ARROW,
+ &callchain_cursor, stdout);
+
+out:
printf("\n");
}
@@ -1878,9 +1894,14 @@ static void timehist_update_runtime_stats(struct thread_runtime *r,
r->total_run_time += r->dt_run;
}
-static bool is_idle_sample(struct perf_sample *sample,
- struct perf_evsel *evsel)
+static bool is_idle_sample(struct perf_sched *sched,
+ struct perf_sample *sample,
+ struct perf_evsel *evsel,
+ struct machine *machine)
{
+ struct thread *thread;
+ struct callchain_cursor *cursor = &callchain_cursor;
+
/* pid 0 == swapper == idle task */
if (sample->pid == 0)
return true;
@@ -1889,6 +1910,25 @@ static bool is_idle_sample(struct perf_sample *sample,
if (perf_evsel__intval(evsel, sample, "prev_pid") == 0)
return true;
}
+
+ /* want main thread for process - has maps */
+ thread = machine__findnew_thread(machine, sample->pid, sample->pid);
+ if (thread == NULL) {
+ pr_debug("Failed to get thread for pid %d.\n", sample->pid);
+ return false;
+ }
+
+ if (!symbol_conf.use_callchain || sample->callchain == NULL)
+ return false;
+
+ if (thread__resolve_callchain(thread, cursor, evsel, sample,
+ NULL, NULL, sched->max_stack) != 0) {
+ if (verbose)
+ error("Failed to resolve callchain. Skipping\n");
+
+ return false;
+ }
+ callchain_cursor_commit(cursor);
return false;
}
@@ -1999,13 +2039,14 @@ static struct thread_runtime *thread__get_runtime(struct thread *thread)
return tr;
}
-static struct thread *timehist_get_thread(struct perf_sample *sample,
+static struct thread *timehist_get_thread(struct perf_sched *sched,
+ struct perf_sample *sample,
struct machine *machine,
struct perf_evsel *evsel)
{
struct thread *thread;
- if (is_idle_sample(sample, evsel)) {
+ if (is_idle_sample(sched, sample, evsel, machine)) {
thread = get_idle_thread(sample->cpu);
if (thread == NULL)
pr_err("Failed to get idle thread for cpu %d.\n", sample->cpu);
@@ -2115,7 +2156,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
goto out;
}
- thread = timehist_get_thread(sample, machine, evsel);
+ thread = timehist_get_thread(sched, sample, machine, evsel);
if (thread == NULL) {
rc = -1;
goto out;
@@ -2134,7 +2175,7 @@ static int timehist_sched_change_event(struct perf_tool *tool,
timehist_update_runtime_stats(tr, sample->time, tprev);
if (!sched->summary_only)
- timehist_print_sample(sched, sample, thread);
+ timehist_print_sample(sched, sample, &al, thread);
out:
if (tr) {
@@ -2327,6 +2368,30 @@ static int perf_timehist__process_sample(struct perf_tool *tool,
return err;
}
+static int timehist_check_attr(struct perf_sched *sched,
+ struct perf_evlist *evlist)
+{
+ struct perf_evsel *evsel;
+ struct evsel_runtime *er;
+
+ list_for_each_entry(evsel, &evlist->entries, node) {
+ er = perf_evsel__get_runtime(evsel);
+ if (er == NULL) {
+ pr_err("Failed to allocate memory for evsel runtime data\n");
+ return -1;
+ }
+
+ if (sched->show_callchain &&
+ !(evsel->attr.sample_type & PERF_SAMPLE_CALLCHAIN)) {
+ pr_info("Samples do not have callchains.\n");
+ sched->show_callchain = 0;
+ symbol_conf.use_callchain = 0;
+ }
+ }
+
+ return 0;
+}
+
static int perf_sched__timehist(struct perf_sched *sched)
{
const struct perf_evsel_str_handler handlers[] = {
@@ -2359,6 +2424,8 @@ static int perf_sched__timehist(struct perf_sched *sched)
sched->tool.ordered_events = true;
sched->tool.ordering_requires_timestamps = true;
+ symbol_conf.use_callchain = sched->show_callchain;
+
session = perf_session__new(&file, false, &sched->tool);
if (session == NULL)
return -ENOMEM;
@@ -2367,6 +2434,9 @@ static int perf_sched__timehist(struct perf_sched *sched)
symbol__init(&session->header.env);
+ if (timehist_check_attr(sched, evlist) != 0)
+ goto out;
+
setup_pager();
/* setup per-evsel handlers */
@@ -2714,6 +2784,8 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
.next_shortname1 = 'A',
.next_shortname2 = '0',
.skip_merge = 0,
+ .show_callchain = 1,
+ .max_stack = 5,
};
const struct option sched_options[] = {
OPT_STRING('i', "input", &input_name, "file",
@@ -2759,6 +2831,10 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
"file", "vmlinux pathname"),
OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
"file", "kallsyms pathname"),
+ OPT_BOOLEAN('g', "call-graph", &sched.show_callchain,
+ "Display call chains if present (default on)"),
+ OPT_UINTEGER(0, "max-stack", &sched.max_stack,
+ "Maximum number of functions to display backtrace."),
OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
"Look for files with symbols relative to this directory"),
OPT_BOOLEAN('s', "summary", &sched.summary_only,
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (5 preceding siblings ...)
2016-11-16 6:06 ` [PATCH v2 6/8] perf sched timehist: Add call graph options Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-22 18:33 ` Arnaldo Carvalho de Melo
2016-11-24 4:21 ` [tip:perf/core] " tip-bot for David Ahern
2016-11-16 6:06 ` [PATCH v2 8/8] perf sched: Add documentation for timehist options Namhyung Kim
` (3 subsequent siblings)
10 siblings, 2 replies; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
From: David Ahern <dsahern@gmail.com>
The -V option provides a visual aid for sched switches by cpu:
$ perf sched timehist -V
time cpu 0123456789abc task name b/n time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------- -------------------- --------- --------- ---------
...
2412598.429696 [0009] i <idle> 0.000 0.000 0.000
2412598.429767 [0002] s perf[7219] 0.000 0.000 0.000
2412598.429783 [0009] s perf[7220] 0.000 0.006 0.087
2412598.429794 [0010] i <idle> 0.000 0.000 0.000
2412598.429795 [0009] s migration/9[53] 0.000 0.003 0.011
2412598.430370 [0010] s sleep[7220] 0.011 0.000 0.576
2412598.432584 [0003] i <idle> 0.000 0.000 0.000
...
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++--
1 file changed, 42 insertions(+), 2 deletions(-)
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1f8731640809..829468defa07 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -201,6 +201,7 @@ struct perf_sched {
bool summary_only;
bool show_callchain;
unsigned int max_stack;
+ bool show_cpu_visual;
bool show_wakeups;
u64 skipped_samples;
};
@@ -1783,10 +1784,23 @@ static char *timehist_get_commstr(struct thread *thread)
return str;
}
-static void timehist_header(void)
+static void timehist_header(struct perf_sched *sched)
{
+ u32 ncpus = sched->max_cpu + 1;
+ u32 i, j;
+
printf("%15s %6s ", "time", "cpu");
+ if (sched->show_cpu_visual) {
+ printf(" ");
+ for (i = 0, j = 0; i < ncpus; ++i) {
+ printf("%x", j++);
+ if (j > 15)
+ j = 0;
+ }
+ printf(" ");
+ }
+
printf(" %-20s %9s %9s %9s",
"task name", "wait time", "sch delay", "run time");
@@ -1797,6 +1811,9 @@ static void timehist_header(void)
*/
printf("%15s %-6s ", "", "");
+ if (sched->show_cpu_visual)
+ printf(" %*s ", ncpus, "");
+
printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
/*
@@ -1804,6 +1821,9 @@ static void timehist_header(void)
*/
printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
+ if (sched->show_cpu_visual)
+ printf(" %.*s ", ncpus, graph_dotted_line);
+
printf(" %.20s %.9s %.9s %.9s",
graph_dotted_line, graph_dotted_line, graph_dotted_line,
graph_dotted_line);
@@ -1817,11 +1837,28 @@ static void timehist_print_sample(struct perf_sched *sched,
struct thread *thread)
{
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));
printf("%15s [%04d] ", tstr, sample->cpu);
+ if (sched->show_cpu_visual) {
+ u32 i;
+ char c;
+
+ printf(" ");
+ for (i = 0; i < max_cpus; ++i) {
+ /* flag idle times with 'i'; others are sched events */
+ if (i == sample->cpu)
+ c = (thread->tid == 0) ? 'i' : 's';
+ else
+ c = ' ';
+ printf("%c", c);
+ }
+ printf(" ");
+ }
+
printf(" %-*s ", comm_width, timehist_get_commstr(thread));
print_sched_time(tr->dt_wait, 6);
@@ -2095,6 +2132,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
printf("%15s [%04d] ", tstr, sample->cpu);
+ if (sched->show_cpu_visual)
+ printf(" %*s ", sched->max_cpu + 1, "");
printf(" %-*s ", comm_width, timehist_get_commstr(thread));
@@ -2458,7 +2497,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
sched->summary = sched->summary_only;
if (!sched->summary_only)
- timehist_header();
+ timehist_header(sched);
err = perf_session__process_events(session);
if (err) {
@@ -2842,6 +2881,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
OPT_BOOLEAN('S', "with-summary", &sched.summary,
"Show all syscalls and summary with statistics"),
OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
+ OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
OPT_PARENT(sched_options)
};
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* Re: [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option
2016-11-16 6:06 ` [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option Namhyung Kim
@ 2016-11-22 18:33 ` Arnaldo Carvalho de Melo
2016-11-23 5:34 ` Namhyung Kim
2016-11-24 4:21 ` [tip:perf/core] " tip-bot for David Ahern
1 sibling, 1 reply; 23+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-11-22 18:33 UTC (permalink / raw)
To: Namhyung Kim
Cc: David Ahern, Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML,
Stephane Eranian, Andi Kleen
Em Wed, Nov 16, 2016 at 03:06:33PM +0900, Namhyung Kim escreveu:
> From: David Ahern <dsahern@gmail.com>
>
> The -V option provides a visual aid for sched switches by cpu:
>
> $ perf sched timehist -V
> time cpu 0123456789abc task name b/n time sch delay run time
> [tid/pid] (msec) (msec) (msec)
> --------------- ------ ------------- -------------------- --------- --------- ---------
> ...
> 2412598.429696 [0009] i <idle> 0.000 0.000 0.000
> 2412598.429767 [0002] s perf[7219] 0.000 0.000 0.000
> 2412598.429783 [0009] s perf[7220] 0.000 0.006 0.087
> 2412598.429794 [0010] i <idle> 0.000 0.000 0.000
> 2412598.429795 [0009] s migration/9[53] 0.000 0.003 0.011
> 2412598.430370 [0010] s sleep[7220] 0.011 0.000 0.576
> 2412598.432584 [0003] i <idle> 0.000 0.000 0.000
> ...
Forgot to add docs, will do.
- Arnaldo
> Signed-off-by: David Ahern <dsahern@gmail.com>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
> tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++--
> 1 file changed, 42 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 1f8731640809..829468defa07 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -201,6 +201,7 @@ struct perf_sched {
> bool summary_only;
> bool show_callchain;
> unsigned int max_stack;
> + bool show_cpu_visual;
> bool show_wakeups;
> u64 skipped_samples;
> };
> @@ -1783,10 +1784,23 @@ static char *timehist_get_commstr(struct thread *thread)
> return str;
> }
>
> -static void timehist_header(void)
> +static void timehist_header(struct perf_sched *sched)
> {
> + u32 ncpus = sched->max_cpu + 1;
> + u32 i, j;
> +
> printf("%15s %6s ", "time", "cpu");
>
> + if (sched->show_cpu_visual) {
> + printf(" ");
> + for (i = 0, j = 0; i < ncpus; ++i) {
> + printf("%x", j++);
> + if (j > 15)
> + j = 0;
> + }
> + printf(" ");
> + }
> +
> printf(" %-20s %9s %9s %9s",
> "task name", "wait time", "sch delay", "run time");
>
> @@ -1797,6 +1811,9 @@ static void timehist_header(void)
> */
> printf("%15s %-6s ", "", "");
>
> + if (sched->show_cpu_visual)
> + printf(" %*s ", ncpus, "");
> +
> printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
>
> /*
> @@ -1804,6 +1821,9 @@ static void timehist_header(void)
> */
> printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
>
> + if (sched->show_cpu_visual)
> + printf(" %.*s ", ncpus, graph_dotted_line);
> +
> printf(" %.20s %.9s %.9s %.9s",
> graph_dotted_line, graph_dotted_line, graph_dotted_line,
> graph_dotted_line);
> @@ -1817,11 +1837,28 @@ static void timehist_print_sample(struct perf_sched *sched,
> struct thread *thread)
> {
> 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));
> printf("%15s [%04d] ", tstr, sample->cpu);
>
> + if (sched->show_cpu_visual) {
> + u32 i;
> + char c;
> +
> + printf(" ");
> + for (i = 0; i < max_cpus; ++i) {
> + /* flag idle times with 'i'; others are sched events */
> + if (i == sample->cpu)
> + c = (thread->tid == 0) ? 'i' : 's';
> + else
> + c = ' ';
> + printf("%c", c);
> + }
> + printf(" ");
> + }
> +
> printf(" %-*s ", comm_width, timehist_get_commstr(thread));
>
> print_sched_time(tr->dt_wait, 6);
> @@ -2095,6 +2132,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
>
> timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
> printf("%15s [%04d] ", tstr, sample->cpu);
> + if (sched->show_cpu_visual)
> + printf(" %*s ", sched->max_cpu + 1, "");
>
> printf(" %-*s ", comm_width, timehist_get_commstr(thread));
>
> @@ -2458,7 +2497,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
> sched->summary = sched->summary_only;
>
> if (!sched->summary_only)
> - timehist_header();
> + timehist_header(sched);
>
> err = perf_session__process_events(session);
> if (err) {
> @@ -2842,6 +2881,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
> OPT_BOOLEAN('S', "with-summary", &sched.summary,
> "Show all syscalls and summary with statistics"),
> OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
> + OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
> OPT_PARENT(sched_options)
> };
>
> --
> 2.10.1
^ permalink raw reply [flat|nested] 23+ messages in thread* Re: [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option
2016-11-22 18:33 ` Arnaldo Carvalho de Melo
@ 2016-11-23 5:34 ` Namhyung Kim
2016-11-23 13:36 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 23+ messages in thread
From: Namhyung Kim @ 2016-11-23 5:34 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: David Ahern, Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML,
Stephane Eranian, Andi Kleen
On Tue, Nov 22, 2016 at 03:33:26PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Wed, Nov 16, 2016 at 03:06:33PM +0900, Namhyung Kim escreveu:
> > From: David Ahern <dsahern@gmail.com>
> >
> > The -V option provides a visual aid for sched switches by cpu:
> >
> > $ perf sched timehist -V
> > time cpu 0123456789abc task name b/n time sch delay run time
> > [tid/pid] (msec) (msec) (msec)
> > --------------- ------ ------------- -------------------- --------- --------- ---------
> > ...
> > 2412598.429696 [0009] i <idle> 0.000 0.000 0.000
> > 2412598.429767 [0002] s perf[7219] 0.000 0.000 0.000
> > 2412598.429783 [0009] s perf[7220] 0.000 0.006 0.087
> > 2412598.429794 [0010] i <idle> 0.000 0.000 0.000
> > 2412598.429795 [0009] s migration/9[53] 0.000 0.003 0.011
> > 2412598.430370 [0010] s sleep[7220] 0.011 0.000 0.576
> > 2412598.432584 [0003] i <idle> 0.000 0.000 0.000
> > ...
>
> Forgot to add docs, will do.
The documentation of sched timehist command (including the -V option)
comes with the next patch (8/8).
Thanks,
Namhyung
>
> - Arnaldo
>
> > Signed-off-by: David Ahern <dsahern@gmail.com>
> > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > ---
> > tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++--
> > 1 file changed, 42 insertions(+), 2 deletions(-)
> >
> > diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> > index 1f8731640809..829468defa07 100644
> > --- a/tools/perf/builtin-sched.c
> > +++ b/tools/perf/builtin-sched.c
> > @@ -201,6 +201,7 @@ struct perf_sched {
> > bool summary_only;
> > bool show_callchain;
> > unsigned int max_stack;
> > + bool show_cpu_visual;
> > bool show_wakeups;
> > u64 skipped_samples;
> > };
> > @@ -1783,10 +1784,23 @@ static char *timehist_get_commstr(struct thread *thread)
> > return str;
> > }
> >
> > -static void timehist_header(void)
> > +static void timehist_header(struct perf_sched *sched)
> > {
> > + u32 ncpus = sched->max_cpu + 1;
> > + u32 i, j;
> > +
> > printf("%15s %6s ", "time", "cpu");
> >
> > + if (sched->show_cpu_visual) {
> > + printf(" ");
> > + for (i = 0, j = 0; i < ncpus; ++i) {
> > + printf("%x", j++);
> > + if (j > 15)
> > + j = 0;
> > + }
> > + printf(" ");
> > + }
> > +
> > printf(" %-20s %9s %9s %9s",
> > "task name", "wait time", "sch delay", "run time");
> >
> > @@ -1797,6 +1811,9 @@ static void timehist_header(void)
> > */
> > printf("%15s %-6s ", "", "");
> >
> > + if (sched->show_cpu_visual)
> > + printf(" %*s ", ncpus, "");
> > +
> > printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
> >
> > /*
> > @@ -1804,6 +1821,9 @@ static void timehist_header(void)
> > */
> > printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
> >
> > + if (sched->show_cpu_visual)
> > + printf(" %.*s ", ncpus, graph_dotted_line);
> > +
> > printf(" %.20s %.9s %.9s %.9s",
> > graph_dotted_line, graph_dotted_line, graph_dotted_line,
> > graph_dotted_line);
> > @@ -1817,11 +1837,28 @@ static void timehist_print_sample(struct perf_sched *sched,
> > struct thread *thread)
> > {
> > 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));
> > printf("%15s [%04d] ", tstr, sample->cpu);
> >
> > + if (sched->show_cpu_visual) {
> > + u32 i;
> > + char c;
> > +
> > + printf(" ");
> > + for (i = 0; i < max_cpus; ++i) {
> > + /* flag idle times with 'i'; others are sched events */
> > + if (i == sample->cpu)
> > + c = (thread->tid == 0) ? 'i' : 's';
> > + else
> > + c = ' ';
> > + printf("%c", c);
> > + }
> > + printf(" ");
> > + }
> > +
> > printf(" %-*s ", comm_width, timehist_get_commstr(thread));
> >
> > print_sched_time(tr->dt_wait, 6);
> > @@ -2095,6 +2132,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
> >
> > timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
> > printf("%15s [%04d] ", tstr, sample->cpu);
> > + if (sched->show_cpu_visual)
> > + printf(" %*s ", sched->max_cpu + 1, "");
> >
> > printf(" %-*s ", comm_width, timehist_get_commstr(thread));
> >
> > @@ -2458,7 +2497,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
> > sched->summary = sched->summary_only;
> >
> > if (!sched->summary_only)
> > - timehist_header();
> > + timehist_header(sched);
> >
> > err = perf_session__process_events(session);
> > if (err) {
> > @@ -2842,6 +2881,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
> > OPT_BOOLEAN('S', "with-summary", &sched.summary,
> > "Show all syscalls and summary with statistics"),
> > OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
> > + OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
> > OPT_PARENT(sched_options)
> > };
> >
> > --
> > 2.10.1
^ permalink raw reply [flat|nested] 23+ messages in thread* Re: [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option
2016-11-23 5:34 ` Namhyung Kim
@ 2016-11-23 13:36 ` Arnaldo Carvalho de Melo
0 siblings, 0 replies; 23+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-11-23 13:36 UTC (permalink / raw)
To: Namhyung Kim
Cc: David Ahern, Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML,
Stephane Eranian, Andi Kleen
Em Wed, Nov 23, 2016 at 02:34:40PM +0900, Namhyung Kim escreveu:
> On Tue, Nov 22, 2016 at 03:33:26PM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Wed, Nov 16, 2016 at 03:06:33PM +0900, Namhyung Kim escreveu:
> > > From: David Ahern <dsahern@gmail.com>
> > >
> > > The -V option provides a visual aid for sched switches by cpu:
> > >
> > > $ perf sched timehist -V
> > > time cpu 0123456789abc task name b/n time sch delay run time
> > > [tid/pid] (msec) (msec) (msec)
> > > --------------- ------ ------------- -------------------- --------- --------- ---------
> > > ...
> > > 2412598.429696 [0009] i <idle> 0.000 0.000 0.000
> > > 2412598.429767 [0002] s perf[7219] 0.000 0.000 0.000
> > > 2412598.429783 [0009] s perf[7220] 0.000 0.006 0.087
> > > 2412598.429794 [0010] i <idle> 0.000 0.000 0.000
> > > 2412598.429795 [0009] s migration/9[53] 0.000 0.003 0.011
> > > 2412598.430370 [0010] s sleep[7220] 0.011 0.000 0.576
> > > 2412598.432584 [0003] i <idle> 0.000 0.000 0.000
> > > ...
> >
> > Forgot to add docs, will do.
>
> The documentation of sched timehist command (including the -V option)
> comes with the next patch (8/8).
I changed that to do it the preferred way, which is to add documentation
on the same changeset that introduces a new command line option.
I have it queued up, just reworking some stuff on a patch I wrote to
then send all this to Ingo, shouldn't take long,
Thanks,
- Arnaldo
> Thanks,
> Namhyung
>
>
> >
> > - Arnaldo
> >
> > > Signed-off-by: David Ahern <dsahern@gmail.com>
> > > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > > ---
> > > tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++--
> > > 1 file changed, 42 insertions(+), 2 deletions(-)
> > >
> > > diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> > > index 1f8731640809..829468defa07 100644
> > > --- a/tools/perf/builtin-sched.c
> > > +++ b/tools/perf/builtin-sched.c
> > > @@ -201,6 +201,7 @@ struct perf_sched {
> > > bool summary_only;
> > > bool show_callchain;
> > > unsigned int max_stack;
> > > + bool show_cpu_visual;
> > > bool show_wakeups;
> > > u64 skipped_samples;
> > > };
> > > @@ -1783,10 +1784,23 @@ static char *timehist_get_commstr(struct thread *thread)
> > > return str;
> > > }
> > >
> > > -static void timehist_header(void)
> > > +static void timehist_header(struct perf_sched *sched)
> > > {
> > > + u32 ncpus = sched->max_cpu + 1;
> > > + u32 i, j;
> > > +
> > > printf("%15s %6s ", "time", "cpu");
> > >
> > > + if (sched->show_cpu_visual) {
> > > + printf(" ");
> > > + for (i = 0, j = 0; i < ncpus; ++i) {
> > > + printf("%x", j++);
> > > + if (j > 15)
> > > + j = 0;
> > > + }
> > > + printf(" ");
> > > + }
> > > +
> > > printf(" %-20s %9s %9s %9s",
> > > "task name", "wait time", "sch delay", "run time");
> > >
> > > @@ -1797,6 +1811,9 @@ static void timehist_header(void)
> > > */
> > > printf("%15s %-6s ", "", "");
> > >
> > > + if (sched->show_cpu_visual)
> > > + printf(" %*s ", ncpus, "");
> > > +
> > > printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
> > >
> > > /*
> > > @@ -1804,6 +1821,9 @@ static void timehist_header(void)
> > > */
> > > printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
> > >
> > > + if (sched->show_cpu_visual)
> > > + printf(" %.*s ", ncpus, graph_dotted_line);
> > > +
> > > printf(" %.20s %.9s %.9s %.9s",
> > > graph_dotted_line, graph_dotted_line, graph_dotted_line,
> > > graph_dotted_line);
> > > @@ -1817,11 +1837,28 @@ static void timehist_print_sample(struct perf_sched *sched,
> > > struct thread *thread)
> > > {
> > > 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));
> > > printf("%15s [%04d] ", tstr, sample->cpu);
> > >
> > > + if (sched->show_cpu_visual) {
> > > + u32 i;
> > > + char c;
> > > +
> > > + printf(" ");
> > > + for (i = 0; i < max_cpus; ++i) {
> > > + /* flag idle times with 'i'; others are sched events */
> > > + if (i == sample->cpu)
> > > + c = (thread->tid == 0) ? 'i' : 's';
> > > + else
> > > + c = ' ';
> > > + printf("%c", c);
> > > + }
> > > + printf(" ");
> > > + }
> > > +
> > > printf(" %-*s ", comm_width, timehist_get_commstr(thread));
> > >
> > > print_sched_time(tr->dt_wait, 6);
> > > @@ -2095,6 +2132,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
> > >
> > > timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
> > > printf("%15s [%04d] ", tstr, sample->cpu);
> > > + if (sched->show_cpu_visual)
> > > + printf(" %*s ", sched->max_cpu + 1, "");
> > >
> > > printf(" %-*s ", comm_width, timehist_get_commstr(thread));
> > >
> > > @@ -2458,7 +2497,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
> > > sched->summary = sched->summary_only;
> > >
> > > if (!sched->summary_only)
> > > - timehist_header();
> > > + timehist_header(sched);
> > >
> > > err = perf_session__process_events(session);
> > > if (err) {
> > > @@ -2842,6 +2881,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
> > > OPT_BOOLEAN('S', "with-summary", &sched.summary,
> > > "Show all syscalls and summary with statistics"),
> > > OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
> > > + OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
> > > OPT_PARENT(sched_options)
> > > };
> > >
> > > --
> > > 2.10.1
^ permalink raw reply [flat|nested] 23+ messages in thread
* [tip:perf/core] perf sched timehist: Add -V/--cpu-visual option
2016-11-16 6:06 ` [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option Namhyung Kim
2016-11-22 18:33 ` Arnaldo Carvalho de Melo
@ 2016-11-24 4:21 ` tip-bot for David Ahern
1 sibling, 0 replies; 23+ messages in thread
From: tip-bot for David Ahern @ 2016-11-24 4:21 UTC (permalink / raw)
To: linux-tip-commits
Cc: linux-kernel, acme, jolsa, hpa, eranian, tglx, dsahern,
a.p.zijlstra, mingo, namhyung, andi
Commit-ID: a407b0678bc1c39d70af5fdbe6421c164b69a8c0
Gitweb: http://git.kernel.org/tip/a407b0678bc1c39d70af5fdbe6421c164b69a8c0
Author: David Ahern <dsahern@gmail.com>
AuthorDate: Wed, 16 Nov 2016 15:06:33 +0900
Committer: Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Wed, 23 Nov 2016 10:44:09 -0300
perf sched timehist: Add -V/--cpu-visual option
The -V option provides a visual aid for sched switches by cpu:
$ perf sched timehist -V
time cpu 0123456789abc task name b/n time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------------- -------------------- --------- --------- ---------
...
2412598.429696 [0009] i <idle> 0.000 0.000 0.000
2412598.429767 [0002] s perf[7219] 0.000 0.000 0.000
2412598.429783 [0009] s perf[7220] 0.000 0.006 0.087
2412598.429794 [0010] i <idle> 0.000 0.000 0.000
2412598.429795 [0009] s migration/9[53] 0.000 0.003 0.011
2412598.430370 [0010] s sleep[7220] 0.011 0.000 0.576
2412598.432584 [0003] i <idle> 0.000 0.000 0.000
...
Committer notes:
'i' marks idle time, 's' are scheduler events.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-8-namhyung@kernel.org
[ Add documentation based on above commit message ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
tools/perf/Documentation/perf-sched.txt | 5 ++++
tools/perf/builtin-sched.c | 44 +++++++++++++++++++++++++++++++--
2 files changed, 47 insertions(+), 2 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 8345208..fb9e52d 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -119,6 +119,11 @@ OPTIONS for 'perf sched timehist'
--symfs=<directory>::
Look for files with symbols relative to this directory.
+-V::
+--cpu-visual::
+ Show visual aid for sched switches by CPU: 'i' marks idle time,
+ 's' are scheduler events.
+
-w::
--wakeups::
Show wakeup events.
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 1f87316..829468d 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -201,6 +201,7 @@ struct perf_sched {
bool summary_only;
bool show_callchain;
unsigned int max_stack;
+ bool show_cpu_visual;
bool show_wakeups;
u64 skipped_samples;
};
@@ -1783,10 +1784,23 @@ static char *timehist_get_commstr(struct thread *thread)
return str;
}
-static void timehist_header(void)
+static void timehist_header(struct perf_sched *sched)
{
+ u32 ncpus = sched->max_cpu + 1;
+ u32 i, j;
+
printf("%15s %6s ", "time", "cpu");
+ if (sched->show_cpu_visual) {
+ printf(" ");
+ for (i = 0, j = 0; i < ncpus; ++i) {
+ printf("%x", j++);
+ if (j > 15)
+ j = 0;
+ }
+ printf(" ");
+ }
+
printf(" %-20s %9s %9s %9s",
"task name", "wait time", "sch delay", "run time");
@@ -1797,6 +1811,9 @@ static void timehist_header(void)
*/
printf("%15s %-6s ", "", "");
+ if (sched->show_cpu_visual)
+ printf(" %*s ", ncpus, "");
+
printf(" %-20s %9s %9s %9s\n", "[tid/pid]", "(msec)", "(msec)", "(msec)");
/*
@@ -1804,6 +1821,9 @@ static void timehist_header(void)
*/
printf("%.15s %.6s ", graph_dotted_line, graph_dotted_line);
+ if (sched->show_cpu_visual)
+ printf(" %.*s ", ncpus, graph_dotted_line);
+
printf(" %.20s %.9s %.9s %.9s",
graph_dotted_line, graph_dotted_line, graph_dotted_line,
graph_dotted_line);
@@ -1817,11 +1837,28 @@ static void timehist_print_sample(struct perf_sched *sched,
struct thread *thread)
{
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));
printf("%15s [%04d] ", tstr, sample->cpu);
+ if (sched->show_cpu_visual) {
+ u32 i;
+ char c;
+
+ printf(" ");
+ for (i = 0; i < max_cpus; ++i) {
+ /* flag idle times with 'i'; others are sched events */
+ if (i == sample->cpu)
+ c = (thread->tid == 0) ? 'i' : 's';
+ else
+ c = ' ';
+ printf("%c", c);
+ }
+ printf(" ");
+ }
+
printf(" %-*s ", comm_width, timehist_get_commstr(thread));
print_sched_time(tr->dt_wait, 6);
@@ -2095,6 +2132,8 @@ static void timehist_print_wakeup_event(struct perf_sched *sched,
timestamp__scnprintf_usec(sample->time, tstr, sizeof(tstr));
printf("%15s [%04d] ", tstr, sample->cpu);
+ if (sched->show_cpu_visual)
+ printf(" %*s ", sched->max_cpu + 1, "");
printf(" %-*s ", comm_width, timehist_get_commstr(thread));
@@ -2458,7 +2497,7 @@ static int perf_sched__timehist(struct perf_sched *sched)
sched->summary = sched->summary_only;
if (!sched->summary_only)
- timehist_header();
+ timehist_header(sched);
err = perf_session__process_events(session);
if (err) {
@@ -2842,6 +2881,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __maybe_unused)
OPT_BOOLEAN('S', "with-summary", &sched.summary,
"Show all syscalls and summary with statistics"),
OPT_BOOLEAN('w', "wakeups", &sched.show_wakeups, "Show wakeup events"),
+ OPT_BOOLEAN('V', "cpu-visual", &sched.show_cpu_visual, "Add CPU visual"),
OPT_PARENT(sched_options)
};
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 8/8] perf sched: Add documentation for timehist options
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (6 preceding siblings ...)
2016-11-16 6:06 ` [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option Namhyung Kim
@ 2016-11-16 6:06 ` Namhyung Kim
2016-11-16 7:52 ` [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Ingo Molnar
` (2 subsequent siblings)
10 siblings, 0 replies; 23+ messages in thread
From: Namhyung Kim @ 2016-11-16 6:06 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
From: David Ahern <dsahern@gmail.com>
Add entry to perf-sched documentation for timehist command and its
options.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/Documentation/perf-sched.txt | 46 +++++++++++++++++++++++++++++++--
1 file changed, 44 insertions(+), 2 deletions(-)
diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index 1cc08cc47ac5..a0344643f008 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -8,11 +8,11 @@ perf-sched - Tool to trace/measure scheduler properties (latencies)
SYNOPSIS
--------
[verse]
-'perf sched' {record|latency|map|replay|script}
+'perf sched' {record|latency|map|replay|script|timehist}
DESCRIPTION
-----------
-There are five variants of perf sched:
+There are several variants of perf sched:
'perf sched record <command>' to record the scheduling events
of an arbitrary workload.
@@ -36,6 +36,11 @@ There are five variants of perf sched:
are running on a CPU. A '*' denotes the CPU that had the event, and
a dot signals an idle CPU.
+ 'perf sched timehist' to show context-switching analysis with times
+ between schedule-in, schedule delay, and run time. If callchains are
+ present stack trace is dumped at the end of the line. A summary of
+ run times can be shown as well.
+
OPTIONS
-------
-i::
@@ -66,6 +71,43 @@ OPTIONS for 'perf sched map'
--color-pids::
Highlight the given pids.
+OPTIONS for 'perf sched timehist'
+---------------------------------
+-k::
+--vmlinux=<file>::
+ vmlinux pathname
+
+--kallsyms=<file>::
+ kallsyms pathname
+
+-s::
+--summary::
+ Show only a summary of scheduling by thread with min, max, and average
+ run times (in sec) and relative stddev.
+
+-S::
+--with-summary::
+ Show all scheduling events followed by a summary by thread with min,
+ max, and average run times (in sec) and relative stddev.
+
+-w::
+--wakeups::
+ Show wakeup events.
+
+--call-graph::
+ Display call chains. Default is on. Use --no-call-graph to suppress
+
+--max-stack::
+ Set the stack depth limit when showing the callchains. Default: 5
+
+--symfs=<directory>::
+ Look for files with symbols relative to this directory.
+
+-V::
+--cpu-visual::
+ Add a visual that better emphasizes activity by cpu. Idle times
+ are denoted with 'i'; schedule events with an 's'.
+
SEE ALSO
--------
linkperf:perf-record[1]
--
2.10.1
^ permalink raw reply related [flat|nested] 23+ messages in thread* Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (7 preceding siblings ...)
2016-11-16 6:06 ` [PATCH v2 8/8] perf sched: Add documentation for timehist options Namhyung Kim
@ 2016-11-16 7:52 ` Ingo Molnar
2016-11-16 15:34 ` Jiri Olsa
2016-11-22 7:00 ` Namhyung Kim
10 siblings, 0 replies; 23+ messages in thread
From: Ingo Molnar @ 2016-11-16 7:52 UTC (permalink / raw)
To: Namhyung Kim
Cc: Arnaldo Carvalho de Melo, David Ahern, Peter Zijlstra, Jiri Olsa,
LKML, Stephane Eranian, Andi Kleen
* Namhyung Kim <namhyung@kernel.org> wrote:
> Hello,
>
> This patchset is a rebased version of David's sched timehist work [1].
> I plan to improve perf sched command more and think that having
> timehist command before the work looks good. It seems David is busy
> these days, so I'm retrying it by myself.
>
> * changes in v2)
> - change name 'b/n time' to 'wait time' (Ingo)
> - show arrow between functions in the callchain (Ingo)
> - fix a bug in calculating initial run time
>
> This implements only basic feature and a few options. I just split
> the patch to make it easier to review and did some cosmetic changes.
> More patches will come later.
>
> The below is from the David's original description (w/ slight change):
>
> ------------------------8<-------------------------
> 'perf sched timehist' provides an analysis of scheduling events.
>
> Example usage:
> perf sched record -- sleep 1
> perf sched timehist
>
> By default it shows the individual schedule events, including the time between
> sched-in events for the task, the task scheduling delay (time between wakeup
> and actually running) and run time for the task:
>
> time cpu task name[tid/pid] wait time sch delay run time
> ------------- ---- -------------------- --------- --------- ---------
> 79371.874569 [11] gcc[31949] 0.014 0.000 1.148
> 79371.874591 [10] gcc[31951] 0.000 0.000 0.024
> 79371.874603 [10] migration/10[59] 3.350 0.004 0.011
> 79371.874604 [11] <idle> 1.148 0.000 0.035
> 79371.874723 [05] <idle> 0.016 0.000 1.383
> 79371.874746 [05] gcc[31949] 0.153 0.078 0.022
> ...
>
> Times are in msec.usec.
>
> If callchains were recorded they are appended to the line with a default stack depth of 5:
>
> 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
> 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
> 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 smpboot_thread_fn <- kthread <- ret_from_fork
> 79371.874604 [11] <idle> 1.148 0.000 0.035 cpu_startup_entry <- start_secondary
> 79371.874723 [05] <idle> 0.016 0.000 1.383 cpu_startup_entry <- start_secondary
> 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid
>
> --no-call-graph can be used to not show the callchains. --max-stack is used
> to control the number of frames shown (default of 5). -x/--excl options can
> be used to collapse redundant callchains to get more relevant data on screen.
>
> Similar to perf-trace -s and -S can be used to dump a statistical summary
> without or with events (respectively). Statistics include min run time,
> average run time and max run time. Stats are also shown for run time by
> cpu.
>
> The cpu-visual option provides a visual aid for sched switches by cpu:
> ...
> 79371.874569 [11] s gcc[31949] 0.014 0.000 1.148
> 79371.874591 [10] s gcc[31951] 0.000 0.000 0.024
> 79371.874603 [10] s migration/10[59] 3.350 0.004 0.011
> 79371.874604 [11] i <idle> 1.148 0.000 0.035
> 79371.874723 [05] i <idle> 0.016 0.000 1.383
> 79371.874746 [05] s gcc[31949] 0.153 0.078 0.022
> ...
Looks great to me!
Acked-by: Ingo Molnar <mingo@kernel.org>
Thanks,
Ingo
^ permalink raw reply [flat|nested] 23+ messages in thread* Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (8 preceding siblings ...)
2016-11-16 7:52 ` [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Ingo Molnar
@ 2016-11-16 15:34 ` Jiri Olsa
2016-11-22 6:59 ` Namhyung Kim
2016-11-22 7:00 ` Namhyung Kim
10 siblings, 1 reply; 23+ messages in thread
From: Jiri Olsa @ 2016-11-16 15:34 UTC (permalink / raw)
To: Namhyung Kim
Cc: Arnaldo Carvalho de Melo, David Ahern, Ingo Molnar,
Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian, Andi Kleen
On Wed, Nov 16, 2016 at 03:06:26PM +0900, Namhyung Kim wrote:
> Hello,
>
> This patchset is a rebased version of David's sched timehist work [1].
> I plan to improve perf sched command more and think that having
> timehist command before the work looks good. It seems David is busy
> these days, so I'm retrying it by myself.
>
> * changes in v2)
> - change name 'b/n time' to 'wait time' (Ingo)
> - show arrow between functions in the callchain (Ingo)
> - fix a bug in calculating initial run time
you might want to add some column width cuts.. I've got this:
time cpu task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ -------------------- --------- --------- ---------
482381.387934 [0000] perf[6870] 0.000 0.000 0.000
482381.388838 [0002] <idle> 0.000 0.000 0.000
482381.388845 [0002] plugin-containe[25990/25970] 0.000 0.004 0.007
482381.388897 [0003] <idle> 0.000 0.000 0.000
482381.388919 [0002] <idle> 0.007 0.000 0.074
482381.388925 [0003] Timer[15210/15178] 0.000 0.002 0.027
other than that:
Acked-by: Jiri Olsa <jolsa@redhat.com>
thanks,
jirka
^ permalink raw reply [flat|nested] 23+ messages in thread* Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)
2016-11-16 15:34 ` Jiri Olsa
@ 2016-11-22 6:59 ` Namhyung Kim
0 siblings, 0 replies; 23+ messages in thread
From: Namhyung Kim @ 2016-11-22 6:59 UTC (permalink / raw)
To: Jiri Olsa
Cc: Arnaldo Carvalho de Melo, David Ahern, Ingo Molnar,
Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian, Andi Kleen
Hi Jiri,
On Wed, Nov 16, 2016 at 04:34:28PM +0100, Jiri Olsa wrote:
> On Wed, Nov 16, 2016 at 03:06:26PM +0900, Namhyung Kim wrote:
> > Hello,
> >
> > This patchset is a rebased version of David's sched timehist work [1].
> > I plan to improve perf sched command more and think that having
> > timehist command before the work looks good. It seems David is busy
> > these days, so I'm retrying it by myself.
> >
> > * changes in v2)
> > - change name 'b/n time' to 'wait time' (Ingo)
> > - show arrow between functions in the callchain (Ingo)
> > - fix a bug in calculating initial run time
>
> you might want to add some column width cuts.. I've got this:
The task name column width is initially set to 20, and grow
dynamically when longer name + tid/pid is found. Maybe I need to
change it to have the max width initially.. (in later patch).
>
> time cpu task name wait time sch delay run time
> [tid/pid] (msec) (msec) (msec)
> --------------- ------ -------------------- --------- --------- ---------
> 482381.387934 [0000] perf[6870] 0.000 0.000 0.000
> 482381.388838 [0002] <idle> 0.000 0.000 0.000
> 482381.388845 [0002] plugin-containe[25990/25970] 0.000 0.004 0.007
> 482381.388897 [0003] <idle> 0.000 0.000 0.000
> 482381.388919 [0002] <idle> 0.007 0.000 0.074
> 482381.388925 [0003] Timer[15210/15178] 0.000 0.002 0.027
>
>
>
> other than that:
>
> Acked-by: Jiri Olsa <jolsa@redhat.com>
Thanks,
Namhyung
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)
2016-11-16 6:06 [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2) Namhyung Kim
` (9 preceding siblings ...)
2016-11-16 15:34 ` Jiri Olsa
@ 2016-11-22 7:00 ` Namhyung Kim
10 siblings, 0 replies; 23+ messages in thread
From: Namhyung Kim @ 2016-11-22 7:00 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, David Ahern
Cc: Ingo Molnar, Peter Zijlstra, Jiri Olsa, LKML, Stephane Eranian,
Andi Kleen
Hi Arnaldo,
Could you please take a look at this?
Thanks,
Namhyung
On Wed, Nov 16, 2016 at 03:06:26PM +0900, Namhyung Kim wrote:
> Hello,
>
> This patchset is a rebased version of David's sched timehist work [1].
> I plan to improve perf sched command more and think that having
> timehist command before the work looks good. It seems David is busy
> these days, so I'm retrying it by myself.
>
> * changes in v2)
> - change name 'b/n time' to 'wait time' (Ingo)
> - show arrow between functions in the callchain (Ingo)
> - fix a bug in calculating initial run time
>
> This implements only basic feature and a few options. I just split
> the patch to make it easier to review and did some cosmetic changes.
> More patches will come later.
>
> The below is from the David's original description (w/ slight change):
>
> ------------------------8<-------------------------
> 'perf sched timehist' provides an analysis of scheduling events.
>
> Example usage:
> perf sched record -- sleep 1
> perf sched timehist
>
> By default it shows the individual schedule events, including the time between
> sched-in events for the task, the task scheduling delay (time between wakeup
> and actually running) and run time for the task:
>
> time cpu task name[tid/pid] wait time sch delay run time
> ------------- ---- -------------------- --------- --------- ---------
> 79371.874569 [11] gcc[31949] 0.014 0.000 1.148
> 79371.874591 [10] gcc[31951] 0.000 0.000 0.024
> 79371.874603 [10] migration/10[59] 3.350 0.004 0.011
> 79371.874604 [11] <idle> 1.148 0.000 0.035
> 79371.874723 [05] <idle> 0.016 0.000 1.383
> 79371.874746 [05] gcc[31949] 0.153 0.078 0.022
> ...
>
> Times are in msec.usec.
>
> If callchains were recorded they are appended to the line with a default stack depth of 5:
>
> 79371.874569 [11] gcc[31949] 0.014 0.000 1.148 wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
> 79371.874591 [10] gcc[31951] 0.000 0.000 0.024 __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
> 79371.874603 [10] migration/10[59] 3.350 0.004 0.011 smpboot_thread_fn <- kthread <- ret_from_fork
> 79371.874604 [11] <idle> 1.148 0.000 0.035 cpu_startup_entry <- start_secondary
> 79371.874723 [05] <idle> 0.016 0.000 1.383 cpu_startup_entry <- start_secondary
> 79371.874746 [05] gcc[31949] 0.153 0.078 0.022 do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid
>
> --no-call-graph can be used to not show the callchains. --max-stack is used
> to control the number of frames shown (default of 5). -x/--excl options can
> be used to collapse redundant callchains to get more relevant data on screen.
>
> Similar to perf-trace -s and -S can be used to dump a statistical summary
> without or with events (respectively). Statistics include min run time,
> average run time and max run time. Stats are also shown for run time by
> cpu.
>
> The cpu-visual option provides a visual aid for sched switches by cpu:
> ...
> 79371.874569 [11] s gcc[31949] 0.014 0.000 1.148
> 79371.874591 [10] s gcc[31951] 0.000 0.000 0.024
> 79371.874603 [10] s migration/10[59] 3.350 0.004 0.011
> 79371.874604 [11] i <idle> 1.148 0.000 0.035
> 79371.874723 [05] i <idle> 0.016 0.000 1.383
> 79371.874746 [05] s gcc[31949] 0.153 0.078 0.022
> ...
>
> ------------------------8<-------------------------
>
> This code is available at 'perf/timehist-v2' branch in my tree
>
> git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
>
> Any feedback is welcomed.
>
> Thanks,
> Namhyung
>
>
> [1] https://lkml.org/lkml/2013/12/1/129
>
> David Ahern (6):
> perf sched timehist: Introduce timehist command
> perf sched timehist: Add summary options
> perf sched timehist: Add -w/--wakeups option
> perf sched timehist: Add call graph options
> perf sched timehist: Add -V/--cpu-visual option
> perf sched: Add documentation for timehist options
>
> Namhyung Kim (2):
> perf symbol: Print symbol offsets conditionally
> perf tools: Support printing callchains with arrows
>
> tools/perf/Documentation/perf-sched.txt | 46 +-
> tools/perf/builtin-sched.c | 914 +++++++++++++++++++++++++++++++-
> tools/perf/util/evsel.h | 1 +
> tools/perf/util/evsel_fprintf.c | 12 +-
> tools/perf/util/symbol.h | 3 +-
> tools/perf/util/symbol_fprintf.c | 11 +-
> 6 files changed, 972 insertions(+), 15 deletions(-)
>
> --
> 2.10.1
>
^ permalink raw reply [flat|nested] 23+ messages in thread