Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v2)

[Namhyung Kim <namhyung@kernel.org>]

Hi Arnaldo,

Could you please take a look at this?

Thanks,
Namhyung


On Wed, Nov 16, 2016 at 03:06:26PM +0900, Namhyung Kim wrote:
> Hello,
> 
> This patchset is a rebased version of David's sched timehist work [1].
> I plan to improve perf sched command more and think that having
> timehist command before the work looks good.  It seems David is busy
> these days, so I'm retrying it by myself.
> 
>  * changes in v2)
>   - change name 'b/n time' to 'wait time'  (Ingo)
>   - show arrow between functions in the callchain  (Ingo)
>   - fix a bug in calculating initial run time
>   
> This implements only basic feature and a few options.  I just split
> the patch to make it easier to review and did some cosmetic changes.
> More patches will come later.
> 
> The below is from the David's original description (w/ slight change):
> 
> ------------------------8<-------------------------
> 'perf sched timehist' provides an analysis of scheduling events.
> 
> Example usage:
>     perf sched record -- sleep 1
>     perf sched timehist
> 
> By default it shows the individual schedule events, including the time between
> sched-in events for the task, the task scheduling delay (time between wakeup
> and actually running) and run time for the task:
> 
>            time cpu  task name[tid/pid]   wait time sch delay  run time
>   ------------- ---- -------------------- --------- --------- ---------
>    79371.874569 [11] gcc[31949]               0.014     0.000     1.148
>    79371.874591 [10] gcc[31951]               0.000     0.000     0.024
>    79371.874603 [10] migration/10[59]         3.350     0.004     0.011
>    79371.874604 [11] <idle>                   1.148     0.000     0.035
>    79371.874723 [05] <idle>                   0.016     0.000     1.383
>    79371.874746 [05] gcc[31949]               0.153     0.078     0.022
> ...
> 
> Times are in msec.usec.
> 
> If callchains were recorded they are appended to the line with a default stack depth of 5:
> 
>    79371.874569 [11] gcc[31949]               0.014     0.000     1.148  wait_for_completion_killable <- do_fork <- sys_vfork <- stub_vfork <- __vfork
>    79371.874591 [10] gcc[31951]               0.000     0.000     0.024  __cond_resched <- _cond_resched <- wait_for_completion <- stop_one_cpu <- sched_exec
>    79371.874603 [10] migration/10[59]         3.350     0.004     0.011  smpboot_thread_fn <- kthread <- ret_from_fork
>    79371.874604 [11] <idle>                   1.148     0.000     0.035  cpu_startup_entry <- start_secondary
>    79371.874723 [05] <idle>                   0.016     0.000     1.383  cpu_startup_entry <- start_secondary
>    79371.874746 [05] gcc[31949]               0.153     0.078     0.022  do_wait sys_wait4 <- system_call_fastpath <- __GI___waitpid
> 
> --no-call-graph can be used to not show the callchains. --max-stack is used
> to control the number of frames shown (default of 5). -x/--excl options can
> be used to collapse redundant callchains to get more relevant data on screen.
> 
> Similar to perf-trace -s and -S can be used to dump a statistical summary
> without or with events (respectively). Statistics include min run time,
> average run time and max run time. Stats are also shown for run time by
> cpu.
> 
> The cpu-visual option provides a visual aid for sched switches by cpu:
> ...
>    79371.874569 [11]            s      gcc[31949]                  0.014     0.000     1.148
>    79371.874591 [10]           s       gcc[31951]                  0.000     0.000     0.024
>    79371.874603 [10]           s       migration/10[59]            3.350     0.004     0.011
>    79371.874604 [11]            i      <idle>                      1.148     0.000     0.035
>    79371.874723 [05]      i            <idle>                      0.016     0.000     1.383
>    79371.874746 [05]      s            gcc[31949]                  0.153     0.078     0.022
> ...
> 
> ------------------------8<-------------------------
> 
> This code is available at 'perf/timehist-v2' branch in my tree
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
> 
> Any feedback is welcomed.
> 
> Thanks,
> Namhyung
> 
> 
> [1] https://lkml.org/lkml/2013/12/1/129
> 
> David Ahern (6):
>   perf sched timehist: Introduce timehist command
>   perf sched timehist: Add summary options
>   perf sched timehist: Add -w/--wakeups option
>   perf sched timehist: Add call graph options
>   perf sched timehist: Add -V/--cpu-visual option
>   perf sched: Add documentation for timehist options
> 
> Namhyung Kim (2):
>   perf symbol: Print symbol offsets conditionally
>   perf tools: Support printing callchains with arrows
> 
>  tools/perf/Documentation/perf-sched.txt |  46 +-
>  tools/perf/builtin-sched.c              | 914 +++++++++++++++++++++++++++++++-
>  tools/perf/util/evsel.h                 |   1 +
>  tools/perf/util/evsel_fprintf.c         |  12 +-
>  tools/perf/util/symbol.h                |   3 +-
>  tools/perf/util/symbol_fprintf.c        |  11 +-
>  6 files changed, 972 insertions(+), 15 deletions(-)
> 
> -- 
> 2.10.1
>