linux.git/tools/perf, branch v4.12-rc4

perf tools: Put caller above callee in --children mode

2017-05-24T06:41:49+00:00

The __hpp__sort_acc() sorts entries using callchain depth in order to
put callers above in children mode.  But it assumed the callchain order
was callee-first.  Now default (for children) is caller-first so the
order of entries is reverted.

For example, consider following case:

  $ perf report --no-children
  ..l
  # Overhead  Command  Shared Object        Symbol
  # ........  .......  ...................  ..........................
  #
      99.44%  a.out    a.out                [.] main
              |
              ---main
                 __libc_start_main
                 _start

Then children mode should show 'start' above '__libc_start_main' since
it's the caller (parent) of the __libc_start_main.  But it's reversed:

  # Children      Self  Command  Shared Object    Symbol
  # ........  ........  .......  ...............  .....................
  #
      99.61%     0.00%  a.out    libc-2.25.so     [.] __libc_start_main
      99.61%     0.00%  a.out    a.out            [.] _start
      99.54%    99.44%  a.out    a.out            [.] main

This patch fixes it.

  # Children      Self  Command  Shared Object    Symbol
  # ........  ........  .......  ...............  .....................
  #
      99.61%     0.00%  a.out    a.out            [.] _start
      99.61%     0.00%  a.out    libc-2.25.so     [.] __libc_start_main
      99.54%    99.44%  a.out    a.out            [.] main

Signed-off-by: Namhyung Kim 
Acked-by: Jiri Olsa 
Cc: Arnaldo Carvalho de Melo 
Cc: Arnaldo Carvalho de Melo 
Cc: Frederic Weisbecker 
Cc: Jiri Olsa 
Cc: Linus Torvalds 
Cc: Milian Wolff 
Cc: Peter Zijlstra 
Cc: Thomas Gleixner 
Cc: Yao Jin 
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-8-namhyung@kernel.org
Signed-off-by: Ingo Molnar

perf report: Do not drop last inlined frame

2017-05-24T06:41:48+00:00

The very last inlined frame, i.e. the one furthest away from the
non-inlined frame, was silently dropped. This is apparent when
comparing the output of `perf script` and `addr2line`:

~~~~~~
  $ perf script --inline
  ...
  a.out 26722 80836.309329:      72425 cycles:
                     21561 __hypot_finite (/usr/lib/libm-2.25.so)
                      ace3 hypot (/usr/lib/libm-2.25.so)
                       a4a main (a.out)
                           std::abs
                           std::_Norm_helper::_S_do_it
                           std::norm
                           main
                     20510 __libc_start_main (/usr/lib/libc-2.25.so)
                       bd9 _start (a.out)

  $ addr2line -a -f -i -e /tmp/a.out a4a | c++filt
  0x0000000000000a4a
  std::__complex_abs(doublecomplex )
  /usr/include/c++/6.3.1/complex:589
  double std::abs(std::complex const&)
  /usr/include/c++/6.3.1/complex:597
  double std::_Norm_helper::_S_do_it(std::complex const&)
  /usr/include/c++/6.3.1/complex:654
  double std::norm(std::complex const&)
  /usr/include/c++/6.3.1/complex:664
  main
  /tmp/inlining.cpp:14
~~~~~

Note how `std::__complex_abs` is missing from the `perf script`
output. This is similarly showing up in `perf report`. The patch
here fixes this issue, and the output becomes:

~~~~~
  a.out 26722 80836.309329:      72425 cycles:
                     21561 __hypot_finite (/usr/lib/libm-2.25.so)
                      ace3 hypot (/usr/lib/libm-2.25.so)
                       a4a main (a.out)
                           std::__complex_abs
                           std::abs
                           std::_Norm_helper::_S_do_it
                           std::norm
                           main
                     20510 __libc_start_main (/usr/lib/libc-2.25.so)
                       bd9 _start (a.out)
~~~~~

Signed-off-by: Milian Wolff 
Signed-off-by: Namhyung Kim 
Cc: Arnaldo Carvalho de Melo 
Cc: Arnaldo Carvalho de Melo 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Jiri Olsa 
Cc: Linus Torvalds 
Cc: Peter Zijlstra 
Cc: Peter Zijlstra 
Cc: Thomas Gleixner 
Cc: Yao Jin 
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-7-namhyung@kernel.org
Signed-off-by: Ingo Molnar

perf report: Always honor callchain order for inlined nodes

2017-05-24T06:41:48+00:00

So far, the inlined nodes where only reversed when we built perf
against libbfd. If that was not available, the addr2line fallback
code path was missing the inline_list__reverse call.

Now we always add the nodes in the correct order within
inline_list__append. This removes the need to reverse the list
and also ensures that all callers construct the list in the right
order.

Signed-off-by: Milian Wolff 
Signed-off-by: Namhyung Kim 
Cc: Arnaldo Carvalho de Melo 
Cc: Arnaldo Carvalho de Melo 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Jiri Olsa 
Cc: Linus Torvalds 
Cc: Peter Zijlstra 
Cc: Peter Zijlstra 
Cc: Thomas Gleixner 
Cc: Yao Jin 
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-6-namhyung@kernel.org
Signed-off-by: Ingo Molnar

perf script: Add --inline option for debugging

2017-05-24T06:41:48+00:00

The --inline option is to show inlined functions in callchains.

For example:

  $ perf script
  a.out  5644 11611.467597:     309961 cycles:u:
                     790 main (/home/namhyung/tmp/perf/a.out)
                   20511 __libc_start_main (/usr/lib/libc-2.25.so)
                     8ba _start (/home/namhyung/tmp/perf/a.out)
  ...

  $ perf script --inline
  a.out  5644 11611.467597:     309961 cycles:u:
                     790 main (/home/namhyung/tmp/perf/a.out)
                         std::__detail::_Adaptor, double>::operator()
                         std::uniform_real_distribution::operator() >
                         std::uniform_real_distribution::operator() >
                         main
                   20511 __libc_start_main (/usr/lib/libc-2.25.so)
                     8ba _start (/home/namhyung/tmp/perf/a.out)
  ...

Reviewed-and-tested-by: Milian Wolff 
Signed-off-by: Namhyung Kim 
Cc: Arnaldo Carvalho de Melo 
Cc: Arnaldo Carvalho de Melo 
Cc: Jin Yao 
Cc: Jiri Olsa 
Cc: Jiri Olsa 
Cc: Linus Torvalds 
Cc: Milian Wolff 
Cc: Peter Zijlstra 
Cc: Thomas Gleixner 
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-5-namhyung@kernel.org
Signed-off-by: Ingo Molnar

perf report: Fix off-by-one for non-activation frames

2017-05-24T06:41:48+00:00

As the documentation for dwfl_frame_pc says, frames that
are no activation frames need to have their program counter
decremented by one to properly find the function of the caller.

This fixes many cases where perf report currently attributes
the cost to the next line. I.e. I have code like this:

~~~~~~~~~~~~~~~
  #include 
  #include 

  using namespace std;

  int main()
  {
    this_thread::sleep_for(chrono::milliseconds(1000));
    this_thread::sleep_for(chrono::milliseconds(100));
    this_thread::sleep_for(chrono::milliseconds(10));

    return 0;
  }
~~~~~~~~~~~~~~~

Now compile and record it:

~~~~~~~~~~~~~~~
  g++ -std=c++11 -g -O2 test.cpp
  echo 1 | sudo tee /proc/sys/kernel/sched_schedstats
  perf record \
    --event sched:sched_stat_sleep \
    --event sched:sched_process_exit \
    --event sched:sched_switch --call-graph=dwarf \
    --output perf.data.raw \
    ./a.out
  echo 0 | sudo tee /proc/sys/kernel/sched_schedstats
  perf inject --sched-stat --input perf.data.raw --output perf.data
~~~~~~~~~~~~~~~

Before this patch, the report clearly shows the off-by-one issue.
Most notably, the last sleep invocation is incorrectly attributed
to the "return 0;" line:

~~~~~~~~~~~~~~~
  Overhead  Source:Line
  ........  ...........

   100.00%  core.c:0
            |
            ---__schedule core.c:0
               schedule
               do_nanosleep hrtimer.c:0
               hrtimer_nanosleep
               sys_nanosleep
               entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
               __nanosleep_nocancel .:0
               std::this_thread::sleep_for > thread:323
               |
               |--90.08%--main test.cpp:9
               |          __libc_start_main
               |          _start
               |
               |--9.01%--main test.cpp:10
               |          __libc_start_main
               |          _start
               |
                --0.91%--main test.cpp:13
                          __libc_start_main
                          _start
~~~~~~~~~~~~~~~

With this patch here applied, the issue is fixed. The report becomes
much more usable:

~~~~~~~~~~~~~~~
  Overhead  Source:Line
  ........  ...........

   100.00%  core.c:0
            |
            ---__schedule core.c:0
               schedule
               do_nanosleep hrtimer.c:0
               hrtimer_nanosleep
               sys_nanosleep
               entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
               __nanosleep_nocancel .:0
               std::this_thread::sleep_for > thread:323
               |
               |--90.08%--main test.cpp:8
               |          __libc_start_main
               |          _start
               |
               |--9.01%--main test.cpp:9
               |          __libc_start_main
               |          _start
               |
                --0.91%--main test.cpp:10
                          __libc_start_main
                          _start
~~~~~~~~~~~~~~~

Similarly it works for signal frames:

~~~~~~~~~~~~~~~
  __noinline void bar(void)
  {
    volatile long cnt = 0;

    for (cnt = 0; cnt < 100000000; cnt++);
  }

  __noinline void foo(void)
  {
    bar();
  }

  void sig_handler(int sig)
  {
    foo();
  }

  int main(void)
  {
    signal(SIGUSR1, sig_handler);
    raise(SIGUSR1);

    foo();
    return 0;
  }
~~~~~~~~~~~~~~~~

Before, the report wrongly points to `signal.c:29` after raise():

~~~~~~~~~~~~~~~~
  $ perf report --stdio --no-children -g srcline -s srcline
  ...
   100.00%  signal.c:11
            |
            ---bar signal.c:11
               |
               |--50.49%--main signal.c:29
               |          __libc_start_main
               |          _start
               |
                --49.51%--0x33a8f
                          raise .:0
                          main signal.c:29
                          __libc_start_main
                          _start
~~~~~~~~~~~~~~~~

With this patch in, the issue is fixed and we instead get:

~~~~~~~~~~~~~~~~
   100.00%  signal   signal            [.] bar
            |
            ---bar signal.c:11
               |
               |--50.49%--main signal.c:29
               |          __libc_start_main
               |          _start
               |
                --49.51%--0x33a8f
                          raise .:0
                          main signal.c:27
                          __libc_start_main
                          _start
~~~~~~~~~~~~~~~~

Note how this patch fixes this issue for both unwinding methods, i.e.
both dwfl and libunwind. The former case is straight-forward thanks
to dwfl_frame_pc(). For libunwind, we replace the functionality via
unw_is_signal_frame() for any but the very first frame.

Signed-off-by: Milian Wolff 
Signed-off-by: Namhyung Kim 
Cc: Arnaldo Carvalho de Melo 
Cc: Arnaldo Carvalho de Melo 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Jiri Olsa 
Cc: Linus Torvalds 
Cc: Peter Zijlstra 
Cc: Peter Zijlstra 
Cc: Thomas Gleixner 
Cc: Yao Jin 
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-4-namhyung@kernel.org
Signed-off-by: Ingo Molnar

perf report: Fix memory leak in addr2line when called by addr2inlines

2017-05-24T06:41:48+00:00

When a filename was found in addr2line it was duplicated via strdup()
but never freed. Now we pass NULL and handle this gracefully in
addr2line.

Detected by Valgrind:

  ==16331== 1,680 bytes in 21 blocks are definitely lost in loss record 148 of 220
  ==16331==    at 0x4C2AF1F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
  ==16331==    by 0x672FA69: strdup (in /usr/lib/libc-2.25.so)
  ==16331==    by 0x52769F: addr2line (srcline.c:256)
  ==16331==    by 0x52769F: addr2inlines (srcline.c:294)
  ==16331==    by 0x52769F: dso__parse_addr_inlines (srcline.c:502)
  ==16331==    by 0x574D7A: inline__fprintf (hist.c:41)
  ==16331==    by 0x574D7A: ipchain__fprintf_graph (hist.c:147)
  ==16331==    by 0x57518A: __callchain__fprintf_graph (hist.c:212)
  ==16331==    by 0x5753CF: callchain__fprintf_graph.constprop.6 (hist.c:337)
  ==16331==    by 0x57738E: hist_entry__fprintf (hist.c:628)
  ==16331==    by 0x57738E: hists__fprintf (hist.c:882)
  ==16331==    by 0x44A20F: perf_evlist__tty_browse_hists (builtin-report.c:399)
  ==16331==    by 0x44A20F: report__browse_hists (builtin-report.c:491)
  ==16331==    by 0x44A20F: __cmd_report (builtin-report.c:624)
  ==16331==    by 0x44A20F: cmd_report (builtin-report.c:1054)
  ==16331==    by 0x4A49CE: run_builtin (perf.c:296)
  ==16331==    by 0x4A4CC0: handle_internal_command (perf.c:348)
  ==16331==    by 0x434371: run_argv (perf.c:392)
  ==16331==    by 0x434371: main (perf.c:530)

Signed-off-by: Milian Wolff 
Signed-off-by: Namhyung Kim 
Cc: Arnaldo Carvalho de Melo 
Cc: Arnaldo Carvalho de Melo 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Jiri Olsa 
Cc: Linus Torvalds 
Cc: Peter Zijlstra 
Cc: Peter Zijlstra 
Cc: Thomas Gleixner 
Cc: Yao Jin 
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-3-namhyung@kernel.org
Signed-off-by: Ingo Molnar

perf report: Don't crash on invalid maps in `-g srcline` mode

2017-05-24T06:41:47+00:00

I just hit a segfault when doing `perf report -g srcline`.
Valgrind pointed me at this code as the culprit:

  ==8359== Invalid read of size 8
  ==8359==    at 0x3096D9: map__rip_2objdump (map.c:430)
  ==8359==    by 0x2FC1A3: match_chain_srcline (callchain.c:645)
  ==8359==    by 0x2FC1A3: match_chain (callchain.c:700)
  ==8359==    by 0x2FC1A3: append_chain (callchain.c:895)
  ==8359==    by 0x2FC1A3: append_chain_children (callchain.c:846)
  ==8359==    by 0x2FF719: callchain_append (callchain.c:944)
  ==8359==    by 0x2FF719: hist_entry__append_callchain (callchain.c:1058)
  ==8359==    by 0x32FA06: iter_add_single_cumulative_entry (hist.c:908)
  ==8359==    by 0x33195C: hist_entry_iter__add (hist.c:1050)
  ==8359==    by 0x258F65: process_sample_event (builtin-report.c:204)
  ==8359==    by 0x30D60C: perf_session__deliver_event (session.c:1310)
  ==8359==    by 0x30D60C: ordered_events__deliver_event (session.c:119)
  ==8359==    by 0x310D12: __ordered_events__flush (ordered-events.c:210)
  ==8359==    by 0x310D12: ordered_events__flush.part.3 (ordered-events.c:277)
  ==8359==    by 0x30DD3C: perf_session__process_user_event (session.c:1349)
  ==8359==    by 0x30DD3C: perf_session__process_event (session.c:1475)
  ==8359==    by 0x30FC3C: __perf_session__process_events (session.c:1867)
  ==8359==    by 0x30FC3C: perf_session__process_events (session.c:1921)
  ==8359==    by 0x25A985: __cmd_report (builtin-report.c:575)
  ==8359==    by 0x25A985: cmd_report (builtin-report.c:1054)
  ==8359==    by 0x2B9A80: run_builtin (perf.c:296)
  ==8359==  Address 0x70 is not stack'd, malloc'd or (recently) free'd

This patch fixes the issue.

Signed-off-by: Milian Wolff 
[ Remove dependency from another change ]
Signed-off-by: Namhyung Kim 
Cc: Arnaldo Carvalho de Melo 
Cc: Arnaldo Carvalho de Melo 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Jiri Olsa 
Cc: Linus Torvalds 
Cc: Peter Zijlstra 
Cc: Peter Zijlstra 
Cc: Thomas Gleixner 
Cc: Yao Jin 
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-2-namhyung@kernel.org
Signed-off-by: Ingo Molnar

Merge branch 'perf-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip

2017-05-12T17:45:36+00:00

Pull perf updates/fixes from Ingo Molnar:
 "Mostly tooling updates, but also two kernel fixes: a call chain
  handling robustness fix and an x86 PMU driver event definition fix"

* 'perf-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip:
  perf/callchain: Force USER_DS when invoking perf_callchain_user()
  tools build: Fixup sched_getcpu feature test
  perf tests kmod-path: Don't fail if compressed modules aren't supported
  perf annotate: Fix AArch64 comment char
  perf tools: Fix spelling mistakes
  perf/x86: Fix Broadwell-EP DRAM RAPL events
  perf config: Refactor a duplicated code for obtaining config file name
  perf symbols: Allow user probes on versioned symbols
  perf symbols: Accept symbols starting at address 0
  tools lib string: Adopt prefixcmp() from perf and subcmd
  perf units: Move parse_tag_value() to units.[ch]
  perf ui gtk: Move gtk .so name to the only place where it is used
  perf tools: Move HAS_BOOL define to where perl headers are used
  perf memswap: Split the byteswap memory range wrappers from util.[ch]
  perf tools: Move event prototypes from util.h to event.h
  perf buildid: Move prototypes from util.h to build-id.h

perf tests kmod-path: Don't fail if compressed modules aren't supported

2017-05-04T13:05:55+00:00

__kmod_path__parse() uses is_supported_compression() to determine and
parse out compressed module file extensions.  On systems without zlib,
this test fails and __kmod_path__parse() continues to strcmp "ko" with
"gz".  Don't do this on those systems.

Signed-off-by: Kim Phillips 
Cc: Alexander Shishkin 
Cc: Jiri Olsa 
Cc: Peter Zijlstra 
Fixes: 3c8a67f50a1e ("perf tools: Add kmod_path__parse function")
Link: http://lkml.kernel.org/r/20170503131402.c66e314460026c80cd787b34@arm.com
Signed-off-by: Arnaldo Carvalho de Melo

perf annotate: Fix AArch64 comment char

2017-05-04T13:03:00+00:00

The commit 0fcb1da4aba "perf annotate: AArch64 support" blindly copied
the comment character from the original:

            https://lkml.org/lkml/2016/5/19/461

whereas that same commit shows objdump output utilizing the C++ style
"//" as the comment delimeter.  Since '/' doesn't occur elsewhere in
objdump output, we retain the single character check, but fix it to be
'/'.

Signed-off-by: Kim Phillips 
Cc: Alexander Shishkin 
Cc: Chris Riyder 
Cc: Peter Zijlstra 
Fixes: 0fcb1da4aba6 ("perf annotate: AArch64 support")
Link: http://lkml.kernel.org/r/20170503131356.be88f977094fb3fa0f49b99d@arm.com
Signed-off-by: Arnaldo Carvalho de Melo