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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-Id: <20161116060634.28477-1-namhyung@kernel.org>
Date:   Wed, 16 Nov 2016 15:06:26 +0900
From:   Namhyung Kim <namhyung@...nel.org>
To:     Arnaldo Carvalho de Melo <acme@...nel.org>,
        David Ahern <dsahern@...il.com>
Cc:     Ingo Molnar <mingo@...nel.org>,
        Peter Zijlstra <a.p.zijlstra@...llo.nl>,
        Jiri Olsa <jolsa@...nel.org>,
        LKML <linux-kernel@...r.kernel.org>,
        Stephane Eranian <eranian@...gle.com>,
        Andi Kleen <andi@...stfloor.org>
Subject: [PATCHSET 0/7] 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(-)

-- 
2.10.1