perf sched: Introduce timehist command, again (v2)
Namhyung Kim
maintainercover perf sched: Introduce timehist command, again (v2)
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(-)
Signature · 1 line
2.10.1
Namhyung Kim
maintainerPATCH v2 1/8 perf symbol: 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..
--- 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(-)
tools/perf/util/evsel_fprintf.c +4 -2
@@ -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);
tools/perf/util/symbol.h +2 -1
@@ -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,
tools/perf/util/symbol_fprintf.c +6 -5
@@ -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,
Signature · 1 line
2.10.1
tip-bot for Namhyung Kim
merge bot[tip:perf/core] perf symbols: Print symbol offsets conditionally
perf symbols: Print symbol offsets conditionally
Commit-ID: a8763445f6c78628bd96d51649745065c0bb2c92 Gitweb: http://git.kernel.org/tip/a8763445f6c78628bd96d51649745065c0bb2c92 Author: Namhyung Kim <[email protected]> AuthorDate: Wed, 16 Nov 2016 15:06:27 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> 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..
--- 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(-)
tools/perf/util/evsel_fprintf.c +4 -2
@@ -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);
tools/perf/util/symbol.h +2 -1
@@ -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,
tools/perf/util/symbol_fprintf.c +6 -5
@@ -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,
Namhyung Kim
maintainerPATCH v2 2/8 perf tools: Support printing callchains with arrows
In reply to Namhyung KimThe 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
--- tools/perf/util/evsel.h | 1 + tools/perf/util/evsel_fprintf.c | 6 ++++++ 2 files changed, 7 insertions(+)
tools/perf/util/evsel.h +1 -0
@@ -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 ;
tools/perf/util/evsel_fprintf.c +6 -0
@@ -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; } }
Signature · 1 line
2.10.1
tip-bot for Namhyung Kim
merge bot[tip:perf/core] perf evsel: Support printing callchains with arrows
perf evsel: Support printing callchains with arrows
Commit-ID: 69b7e48070ca2ecee7498166259b5826b22e8b2e Gitweb: http://git.kernel.org/tip/69b7e48070ca2ecee7498166259b5826b22e8b2e Author: Namhyung Kim <[email protected]> AuthorDate: Wed, 16 Nov 2016 15:06:28 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> 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
--- tools/perf/util/evsel.h | 1 + tools/perf/util/evsel_fprintf.c | 6 ++++++ 2 files changed, 7 insertions(+)
tools/perf/util/evsel.h +1 -0
@@ -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 ;
tools/perf/util/evsel_fprintf.c +6 -0
@@ -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; } }
Namhyung Kim
maintainerPATCH v2 3/8 perf sched timehist: Introduce timehist command
In reply to Namhyung KimFrom: David Ahern <[email protected]>
'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.
--- tools/perf/builtin-sched.c | 594 ++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 589 insertions(+), 5 deletions(-)
tools/perf/builtin-sched.c +589 -5
@@ -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); }
Signature · 1 line
2.10.1
tip-bot for David Ahern
merge bot[tip:perf/core] perf sched timehist: Introduce timehist command
perf sched timehist: Introduce timehist command
Commit-ID: 49394a2a24c78ce034fe0e732b1b54922c23fd92 Gitweb: http://git.kernel.org/tip/49394a2a24c78ce034fe0e732b1b54922c23fd92 Author: David Ahern <[email protected]> AuthorDate: Wed, 16 Nov 2016 15:06:29 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> 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'.
--- tools/perf/Documentation/perf-sched.txt | 50 ++- tools/perf/builtin-sched.c | 594 +++++++++++++++++++++++++++++++- 2 files changed, 637 insertions(+), 7 deletions(-)
tools/perf/Documentation/perf-sched.txt +48 -2
@@ -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]
tools/perf/builtin-sched.c +589 -5
649 lines not on this page · raw message
Namhyung Kim
maintainerPATCH v2 4/8 perf sched timehist: Add summary options
In reply to Namhyung KimFrom: David Ahern <[email protected]>
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
--- tools/perf/builtin-sched.c | 166 +++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 160 insertions(+), 6 deletions(-)
tools/perf/builtin-sched.c +160 -6
@@ -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) };
Signature · 1 line
2.10.1
tip-bot for David Ahern
merge bot[tip:perf/core] perf sched timehist: Add summary options
perf sched timehist: Add summary options
Commit-ID: 52df138caaa8daaaf4e0dc64428ef06f303a8dbf Gitweb: http://git.kernel.org/tip/52df138caaa8daaaf4e0dc64428ef06f303a8dbf Author: David Ahern <[email protected]> AuthorDate: Wed, 16 Nov 2016 15:06:30 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> 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
--- tools/perf/builtin-sched.c | 166 +++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 160 insertions(+), 6 deletions(-)
tools/perf/builtin-sched.c +160 -6
@@ -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) };
Namhyung Kim
maintainerPATCH v2 5/8 perf sched timehist: Add -w/--wakeups option
In reply to Namhyung KimFrom: David Ahern <[email protected]>
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]
...--- tools/perf/builtin-sched.c | 58 ++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 54 insertions(+), 4 deletions(-)
tools/perf/builtin-sched.c +54 -4
@@ -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);
Signature · 1 line
2.10.1
tip-bot for David Ahern
merge bot[tip:perf/core] perf sched timehist: Add -w/--wakeups option
perf sched timehist: Add -w/--wakeups option
Commit-ID: fc1469f1b20777929a47f6f8e55bca12c6f142ac Gitweb: http://git.kernel.org/tip/fc1469f1b20777929a47f6f8e55bca12c6f142ac Author: David Ahern <[email protected]> AuthorDate: Wed, 16 Nov 2016 15:06:31 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> 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]
...--- tools/perf/Documentation/perf-sched.txt | 4 +++ tools/perf/builtin-sched.c | 58 ++++++++++++++++++++++++++++++--- 2 files changed, 58 insertions(+), 4 deletions(-)
tools/perf/Documentation/perf-sched.txt +4 -0
@@ -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]
tools/perf/builtin-sched.c +54 -4
122 lines not on this page · raw message
Namhyung Kim
maintainerPATCH v2 6/8 perf sched timehist: Add call graph options
In reply to Namhyung KimFrom: David Ahern <[email protected]>
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.
--- tools/perf/builtin-sched.c | 88 ++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 82 insertions(+), 6 deletions(-)
tools/perf/builtin-sched.c +82 -6
@@ -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,
Signature · 1 line
2.10.1
tip-bot for David Ahern
merge bot[tip:perf/core] perf sched timehist: Add call graph options
perf sched timehist: Add call graph options
Commit-ID: 6c973c90852c3fa4b4e76a061ce89dcd373efccc Gitweb: http://git.kernel.org/tip/6c973c90852c3fa4b4e76a061ce89dcd373efccc Author: David Ahern <[email protected]> AuthorDate: Wed, 16 Nov 2016 15:06:32 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> 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.
--- tools/perf/Documentation/perf-sched.txt | 7 +++ tools/perf/builtin-sched.c | 88 ++++++++++++++++++++++++++++++--- 2 files changed, 89 insertions(+), 6 deletions(-)
tools/perf/Documentation/perf-sched.txt +7 -0
@@ -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
tools/perf/builtin-sched.c +82 -6
178 lines not on this page · raw message
Namhyung Kim
maintainerPATCH v2 7/8 perf sched timehist: Add -V/--cpu-visual option
In reply to Namhyung KimFrom: David Ahern <[email protected]>
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
...--- tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 42 insertions(+), 2 deletions(-)
tools/perf/builtin-sched.c +42 -2
@@ -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) };
Signature · 1 line
2.10.1
Arnaldo Carvalho de Melo
maintainerRe: [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option
Em Wed, Nov 16, 2016 at 03:06:33PM +0900, Namhyung Kim escreveu:
Quoted 4 lines
From: David Ahern <[email protected]>
The -V option provides a visual aid for sched switches by cpu:
Quoted 13 lines
$ 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
Quoted 120 lines
Signed-off-by David Ahern <[email protected]>Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 42 insertions(+), 2 deletions(-)tools/perf/builtin-sched.c +42
-2@@ -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) };Signature · 1 line
2.10.1
Namhyung Kim
maintainerRe: [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option
Quoted 19 lines · Arnaldo Carvalho de Melo
Em Wed, Nov 16, 2016 at 03:06:33PM +0900, Namhyung Kim escreveu:
Quoted 4 lines
From: David Ahern <[email protected]>
The -V option provides a visual aid for sched switches by cpu:
Quoted 13 lines
$ 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 ...
Quoted 1 line
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
Quoted 123 lines
- Arnaldo
Quoted 120 lines
Signed-off-by David Ahern <[email protected]>Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 42 insertions(+), 2 deletions(-)tools/perf/builtin-sched.c +42
-2@@ -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) };Signature · 1 line
2.10.1
Arnaldo Carvalho de Melo
maintainerRe: [PATCH v2 7/8] perf sched timehist: Add -V/--cpu-visual option
Em Wed, Nov 23, 2016 at 02:34:40PM +0900, Namhyung Kim escreveu:
Quoted 20 lines · Arnaldo Carvalho de Melo
Quoted 19 lines
Em Wed, Nov 16, 2016 at 03:06:33PM +0900, Namhyung Kim escreveu:
Quoted 17 lines
From: David Ahern <[email protected]>
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 ...
Quoted 4 lines
Quoted 1 line
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
Quoted 127 lines
Thanks,
NamhyungQuoted 123 lines
- Arnaldo
Quoted 120 lines
Signed-off-by David Ahern <[email protected]>Signed-off-by Namhyung Kim <[email protected]>--- tools/perf/builtin-sched.c | 44 ++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 42 insertions(+), 2 deletions(-)tools/perf/builtin-sched.c +42
-2@@ -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) };Signature · 1 line
2.10.1
tip-bot for David Ahern
merge bot[tip:perf/core] perf sched timehist: Add -V/--cpu-visual option
In reply to Namhyung Kimperf sched timehist: Add -V/--cpu-visual option
Commit-ID: a407b0678bc1c39d70af5fdbe6421c164b69a8c0 Gitweb: http://git.kernel.org/tip/a407b0678bc1c39d70af5fdbe6421c164b69a8c0 Author: David Ahern <[email protected]> AuthorDate: Wed, 16 Nov 2016 15:06:33 +0900 Committer: Arnaldo Carvalho de Melo <[email protected]> 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.
--- tools/perf/Documentation/perf-sched.txt | 5 ++++ tools/perf/builtin-sched.c | 44 +++++++++++++++++++++++++++++++-- 2 files changed, 47 insertions(+), 2 deletions(-)
tools/perf/Documentation/perf-sched.txt +5 -0
@@ -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.
tools/perf/builtin-sched.c +42 -2
100 lines not on this page · raw message
Namhyung Kim
maintainerPATCH v2 8/8 perf sched: Add documentation for timehist options
In reply to Namhyung KimFrom: David Ahern <[email protected]>
Add entry to perf-sched documentation for timehist command and its options.
--- tools/perf/Documentation/perf-sched.txt | 46 +++++++++++++++++++++++++++++++-- 1 file changed, 44 insertions(+), 2 deletions(-)
tools/perf/Documentation/perf-sched.txt +44 -2
@@ -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]
Signature · 1 line
2.10.1
Quoted 61 lines · Namhyung Kim
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 timeThis 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 timehistBy 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:
...
Quoted 7 lines
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!
Thanks,
Ingo
Quoted 11 lines · Namhyung Kim
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:
thanks,
jirka
Namhyung Kim
maintainerHi Jiri,
Quoted 8 lines · Jiri Olsa
Quoted 7 lines · Namhyung Kim
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.
Quoted 6 lines
Quoted 4 lines
* 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 timeyou 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).
Quoted 13 lines
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
Quoted 3 lines
other than that:
Acked-by Jiri Olsa <[email protected]>
Thanks,
Namhyung
Namhyung Kim
maintainerHi Arnaldo,
Could you please take a look at this?
Thanks,
Namhyung
Quoted 106 lines · Namhyung Kim
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 timeThis 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 timehistBy 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.gitAny 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 optionsNamhyung Kim (2):
perf symbol: Print symbol offsets conditionally perf tools: Support printing callchains with arrowstools/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(-)Signature · 1 line
2.10.1