linux-toradex.git/tools/perf, branch v4.8-rc2

perf probe ppc64le: Fix probe location when using DWARF

2016-08-09T15:14:29+00:00

Powerpc has Global Entry Point and Local Entry Point for functions.  LEP
catches call from both the GEP and the LEP. Symbol table of ELF contains
GEP and Offset from which we can calculate LEP, but debuginfo does not
have LEP info.

Currently, perf prioritize symbol table over dwarf to probe on LEP for
ppc64le. But when user tries to probe with function parameter, we fall
back to using dwarf(i.e. GEP) and when function called via LEP, probe
will never hit.

For example:

  $ objdump -d vmlinux
    ...
    do_sys_open():
    c0000000002eb4a0:       e8 00 4c 3c     addis   r2,r12,232
    c0000000002eb4a4:       60 00 42 38     addi    r2,r2,96
    c0000000002eb4a8:       a6 02 08 7c     mflr    r0
    c0000000002eb4ac:       d0 ff 41 fb     std     r26,-48(r1)

  $ sudo ./perf probe do_sys_open
  $ sudo cat /sys/kernel/debug/tracing/kprobe_events
    p:probe/do_sys_open _text+3060904

  $ sudo ./perf probe 'do_sys_open filename:string'
  $ sudo cat /sys/kernel/debug/tracing/kprobe_events
    p:probe/do_sys_open _text+3060896 filename_string=+0(%gpr4):string

For second case, perf probed on GEP. So when function will be called via
LEP, probe won't hit.

  $ sudo ./perf record -a -e probe:do_sys_open ls
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.195 MB perf.data ]

To resolve this issue, let's not prioritize symbol table, let perf
decide what it wants to use. Perf is already converting GEP to LEP when
it uses symbol table. When perf uses debuginfo, let it find LEP offset
form symbol table. This way we fall back to probe on LEP for all cases.

After patch:

  $ sudo ./perf probe 'do_sys_open filename:string'
  $ sudo cat /sys/kernel/debug/tracing/kprobe_events
    p:probe/do_sys_open _text+3060904 filename_string=+0(%gpr4):string

  $ sudo ./perf record -a -e probe:do_sys_open ls
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.197 MB perf.data (11 samples) ]

Signed-off-by: Ravi Bangoria 
Acked-by: Masami Hiramatsu 
Cc: Alexander Shishkin 
Cc: Ananth N Mavinakayanahalli 
Cc: Balbir Singh 
Cc: Namhyung Kim 
Cc: Naveen N. Rao 
Cc: Peter Zijlstra 
Cc: Wang Nan 
Link: http://lkml.kernel.org/r/1470723805-5081-2-git-send-email-ravi.bangoria@linux.vnet.ibm.com
Signed-off-by: Arnaldo Carvalho de Melo

perf probe: Add function to post process kernel trace events

2016-08-09T15:09:59+00:00

Instead of inline code, introduce function to post process kernel
probe trace events.

Signed-off-by: Ravi Bangoria 
Acked-by: Masami Hiramatsu 
Cc: Alexander Shishkin 
Cc: Ananth N Mavinakayanahalli 
Cc: Balbir Singh 
Cc: Namhyung Kim 
Cc: Naveen N. Rao 
Cc: Peter Zijlstra 
Cc: Wang Nan 
Link: http://lkml.kernel.org/r/1470723805-5081-1-git-send-email-ravi.bangoria@linux.vnet.ibm.com
Signed-off-by: Arnaldo Carvalho de Melo

perf probe: Support signedness casting

2016-08-09T13:52:22+00:00

The 'perf probe' tool detects a variable's type and use the detected
type to add a new probe. Then, kprobes prints its variable in
hexadecimal format if the variable is unsigned and prints in decimal if
it is signed.

We sometimes want to see unsigned variable in decimal format (i.e.
sector_t or size_t). In that case, we need to investigate the variable's
size manually to specify just signedness.

This patch add signedness casting support. By specifying "s" or "u" as a
type, perf-probe will investigate variable size as usual and use the
specified signedness.

E.g. without this:

  $ perf probe -a 'submit_bio bio->bi_iter.bi_sector'
  Added new event:
    probe:submit_bio     (on submit_bio with bi_sector=bio->bi_iter.bi_sector)
  You can now use it in all perf tools, such as:
          perf record -e probe:submit_bio -aR sleep 1
  $ cat trace_pipe|head
          dbench-9692  [003] d..1   971.096633: submit_bio: (submit_bio+0x0/0x140) bi_sector=0x3a3d00
          dbench-9692  [003] d..1   971.096685: submit_bio: (submit_bio+0x0/0x140) bi_sector=0x1a3d80
          dbench-9692  [003] d..1   971.096687: submit_bio: (submit_bio+0x0/0x140) bi_sector=0x3a3d80
...
  // need to investigate the variable size
  $ perf probe -a 'submit_bio bio->bi_iter.bi_sector:s64'
  Added new event:
    probe:submit_bio     (on submit_bio with bi_sector=bio->bi_iter.bi_sector:s64)
  You can now use it in all perf tools, such as:
        perf record -e probe:submit_bio -aR sleep 1

  With this:

  // just use "s" to cast its signedness
  $ perf probe -v -a 'submit_bio bio->bi_iter.bi_sector:s'
  Added new event:
    probe:submit_bio     (on submit_bio with bi_sector=bio->bi_iter.bi_sector:s)
  You can now use it in all perf tools, such as:
          perf record -e probe:submit_bio -aR sleep 1
  $ cat trace_pipe|head
          dbench-9689  [001] d..1  1212.391237: submit_bio: (submit_bio+0x0/0x140) bi_sector=128
          dbench-9689  [001] d..1  1212.391252: submit_bio: (submit_bio+0x0/0x140) bi_sector=131072
          dbench-9697  [006] d..1  1212.398611: submit_bio: (submit_bio+0x0/0x140) bi_sector=30208

  This commit also update perf-probe.txt to describe "types". Most parts
  are based on existing documentation: Documentation/trace/kprobetrace.txt

Committer note:

Testing using 'perf trace':

  # perf probe -a 'submit_bio bio->bi_iter.bi_sector'
  Added new event:
    probe:submit_bio     (on submit_bio with bi_sector=bio->bi_iter.bi_sector)

  You can now use it in all perf tools, such as:

	perf record -e probe:submit_bio -aR sleep 1

  # trace --no-syscalls --ev probe:submit_bio
      0.000 probe:submit_bio:(ffffffffac3aee00) bi_sector=0xc133c0)
   3181.861 probe:submit_bio:(ffffffffac3aee00) bi_sector=0x6cffb8)
   3181.881 probe:submit_bio:(ffffffffac3aee00) bi_sector=0x6cffc0)
   3184.488 probe:submit_bio:(ffffffffac3aee00) bi_sector=0x6cffc8)

   4717.927 probe:submit_bio:(ffffffffac3aee00) bi_sector=0x4dc7a88)
   4717.970 probe:submit_bio:(ffffffffac3aee00) bi_sector=0x4dc7880)
  ^C[root@jouet ~]#

Now, using this new feature:

[root@jouet ~]# perf probe -a 'submit_bio bio->bi_iter.bi_sector:s'
Added new event:
  probe:submit_bio     (on submit_bio with bi_sector=bio->bi_iter.bi_sector:s)

You can now use it in all perf tools, such as:

	perf record -e probe:submit_bio -aR sleep 1

  [root@jouet ~]# trace --no-syscalls --ev probe:submit_bio
     0.000 probe:submit_bio:(ffffffffac3aee00) bi_sector=7145704)
     0.017 probe:submit_bio:(ffffffffac3aee00) bi_sector=7145712)
     0.019 probe:submit_bio:(ffffffffac3aee00) bi_sector=7145720)
     2.567 probe:submit_bio:(ffffffffac3aee00) bi_sector=7145728)
  5631.919 probe:submit_bio:(ffffffffac3aee00) bi_sector=0)
  5631.941 probe:submit_bio:(ffffffffac3aee00) bi_sector=8)
  5631.945 probe:submit_bio:(ffffffffac3aee00) bi_sector=16)
  5631.948 probe:submit_bio:(ffffffffac3aee00) bi_sector=24)
  ^C#

With callchains:

  # trace --no-syscalls --ev probe:submit_bio/max-stack=10/
     0.000 probe:submit_bio:(ffffffffac3aee00) bi_sector=50662544)
                                       submit_bio+0xa8200001 ([kernel.kallsyms])
                                       submit_bh+0xa8200013 ([kernel.kallsyms])
                                       jbd2_journal_commit_transaction+0xa8200691 ([kernel.kallsyms])
                                       kjournald2+0xa82000ca ([kernel.kallsyms])
                                       kthread+0xa82000d8 ([kernel.kallsyms])
                                       ret_from_fork+0xa820001f ([kernel.kallsyms])
     0.023 probe:submit_bio:(ffffffffac3aee00) bi_sector=50662552)
                                       submit_bio+0xa8200001 ([kernel.kallsyms])
                                       submit_bh+0xa8200013 ([kernel.kallsyms])
                                       jbd2_journal_commit_transaction+0xa8200691 ([kernel.kallsyms])
                                       kjournald2+0xa82000ca ([kernel.kallsyms])
                                       kthread+0xa82000d8 ([kernel.kallsyms])
                                       ret_from_fork+0xa820001f ([kernel.kallsyms])
     0.027 probe:submit_bio:(ffffffffac3aee00) bi_sector=50662560)
                                       submit_bio+0xa8200001 ([kernel.kallsyms])
                                       submit_bh+0xa8200013 ([kernel.kallsyms])
                                       jbd2_journal_commit_transaction+0xa8200691 ([kernel.kallsyms])
                                       kjournald2+0xa82000ca ([kernel.kallsyms])
                                       kthread+0xa82000d8 ([kernel.kallsyms])
                                       ret_from_fork+0xa820001f ([kernel.kallsyms])
     2.593 probe:submit_bio:(ffffffffac3aee00) bi_sector=50662568)
                                       submit_bio+0xa8200001 ([kernel.kallsyms])
                                       submit_bh+0xa8200013 ([kernel.kallsyms])
                                       journal_submit_commit_record+0xa82001ac ([kernel.kallsyms])
                                       jbd2_journal_commit_transaction+0xa82012e8 ([kernel.kallsyms])
                                       kjournald2+0xa82000ca ([kernel.kallsyms])
                                       kthread+0xa82000d8 ([kernel.kallsyms])
                                       ret_from_fork+0xa820001f ([kernel.kallsyms])
  ^C#

Signed-off-by: Naohiro Aota 
Tested-by: Arnaldo Carvalho de Melo 
Cc: Alexander Shishkin 
Cc: Hemant Kumar 
Cc: Masami Hiramatsu 
Cc: Peter Zijlstra 
Cc: Wang Nan 
Link: http://lkml.kernel.org/r/1470710408-23515-1-git-send-email-naohiro.aota@hgst.com
Signed-off-by: Arnaldo Carvalho de Melo

perf stat: Avoid skew when reading events

2016-08-09T13:48:32+00:00

When we don't have a tracee (i.e. we're attaching to a task or CPU),
counters can still be running after our workload finishes, and can still
be running as we read their values. As we read events one-by-one, there
can be arbitrary skew between values of events, even within a group.
This means that ratios within an event group are not reliable.

This skew can be seen if measuring a group of identical events, e.g:

  # perf stat -a -C0 -e '{cycles,cycles}' sleep 1

To avoid this, we must stop groups from counting before we read the
values of any constituent events. This patch adds and makes use of a new
disable_counters() helper, which disables group leaders (and thus each
group as a whole). This mirrors the use of enable_counters() for
starting event groups in the absence of a tracee.

Closing a group leader splits the group, and without a disabled group
leader the newly split events will begin counting. Thus to ensure counts
are reliable we must defer closing group leaders until all counts have
been read. To do so this patch removes the event closing logic from the
read_counters() helper, explicitly closes the events using
perf_evlist__close(), which also aids legibility.

Signed-off-by: Mark Rutland 
Tested-by: Arnaldo Carvalho de Melo 
Cc: Alexander Shishkin 
Cc: Peter Zijlstra 
Link: http://lkml.kernel.org/r/1470747869-3567-1-git-send-email-mark.rutland@arm.com
Signed-off-by: Arnaldo Carvalho de Melo

perf probe: Fix module name matching

2016-08-09T13:48:09+00:00

If module is "module" then dso->short_name is "[module]".  Substring
comparing is't enough: "raid10" matches to "[raid1]".  This patch also
checks terminating zero in module name.

Signed-off-by: Konstantin Khlebnikov 
Acked-by: Masami Hiramatsu 
Link: http://lkml.kernel.org/r/147039975648.715620.12985971832789032159.stgit@buzz
Signed-off-by: Arnaldo Carvalho de Melo

perf probe: Adjust map->reloc offset when finding kernel symbol from map

2016-08-09T13:47:43+00:00

Adjust map->reloc offset for the unmapped address when finding
alternative symbol address from map, because KASLR can relocate the
kernel symbol address.

The same adjustment has been done when finding appropriate kernel symbol
address from map which was introduced by commit f90acac75713 ("perf
probe: Find given address from offline dwarf")

Reported-by: Arnaldo Carvalho de Melo 
Signed-off-by: Masami Hiramatsu 
Cc: Alexei Starovoitov 
Cc: Wang Nan 
Link: http://lkml.kernel.org/r/20160806192948.e366f3fbc4b194de600f8326@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo

perf hists: Trim libtraceevent trace_seq buffers

2016-08-09T13:46:56+00:00

When we use libtraceevent to format trace event fields into printable
strings to use in hist entries it is important to trim it from the
default 4 KiB it starts with to what is really used, to reduce the
memory footprint, so use realloc(seq.buffer, seq.len + 1) when returning
the seq.buffer formatted with the fields contents.

Reported-and-Tested-by: Wang Nan 
Cc: Adrian Hunter 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Namhyung Kim 
Link: http://lkml.kernel.org/n/tip-t3hl7uxmilrkigzmc90rlhk2@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo

perf script: Add 'bpf-output' field to usage message

2016-08-09T13:46:43+00:00

This adds the 'bpf-output' field to the perf script usage message, and docs.

Signed-off-by: Brendan Gregg 
Cc: Alexander Shishkin 
Cc: Alexei Starovoitov 
Cc: Peter Zijlstra 
Cc: Wang Nan 
Link: http://lkml.kernel.org/r/1470192469-11910-4-git-send-email-bgregg@netflix.com
Signed-off-by: Arnaldo Carvalho de Melo

Merge tag 'perf-core-for-mingo-20160803' of git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux into perf/urgent

2016-08-04T09:02:38+00:00

Pull perf/core improvements and fixes from Arnaldo Carvalho de Melo:

New features:

- Add --sample-cpu to 'perf record', to explicitely ask for sampling
  the CPU (Jiri Olsa)

Fixes:

- Fix processing of multi byte chunks in objdump output, fixing
  disassemble processing for annotation on at least ARM64 (Jan Stancek)

- Use SyS_epoll_wait in a BPF 'perf test' entry instead of sys_epoll_wait, that
  is not present in the DWARF info in vmlinux files (Arnaldo Carvalho de Melo)

- Add -wno-shadow when processing files using perl headers, fixing
  the build on Fedora Rawhide and Arch Linux (Namhyung Kim)

Infrastructure changes:

- Annotate prep work to better catch and report errors related to
  using objdump to disassemble DSOs (Arnaldo Carvalho de Melo)

- Add 'alloc', 'scnprintf' and 'and' methods for bitmap processing (Jiri Olsa)

- Add nested output resorting callback in hists processing (Jiri Olsa)

Signed-off-by: Arnaldo Carvalho de Melo 
Signed-off-by: Ingo Molnar

perf tests bpf: Use SyS_epoll_wait alias

2016-08-03T22:40:48+00:00

Something made the sys_epoll_wait() function alias not to be found in
the vmlinux DWARF info, being found only in /proc/kallsyms, which made
the BPF perf tests to fail:

  [root@jouet ~]# perf test BPF
  37: Test BPF filter                                          :
  37.1: Test basic BPF filtering                               : FAILED!
  37.2: Test BPF prologue generation                           : Skip
  37.3: Test BPF relocation checker                            : Skip
  [root@jouet ~]#

Using -v we can see it is failing to find DWARF info for the probed function,
sys_epoll_wait, which we can find in /proc/kallsyms but not in vmlinux with
CONFIG_DEBUG_INFO:

  [root@jouet ~]# grep -w sys_epoll_wait /proc/kallsyms
  ffffffffbd295b50 T sys_epoll_wait
  [root@jouet ~]#

  [root@jouet ~]# readelf -wi /lib/modules/4.7.0+/build/vmlinux | grep -w sys_epoll_wait
  [root@jouet ~]#

If we try to use perf probe:

[root@jouet ~]# perf probe sys_epoll_wait
Failed to find debug information for address ffffffffbd295b50
Probe point 'sys_epoll_wait' not found.
  Error: Failed to add events.
[root@jouet ~]#

It all works if we use SyS_epoll_wait, that is just an alias to the probed
function:

  [root@jouet ~]# grep -i sys_epoll_wait /proc/kallsyms
  ffffffffbd295b50 T SyS_epoll_wait
  ffffffffbd295b50 T sys_epoll_wait
  [root@jouet ~]#

So use it:

  [root@jouet ~]# perf test BPF
  37: Test BPF filter                                          :
  37.1: Test basic BPF filtering                               : Ok
  37.2: Test BPF prologue generation                           : Ok
  37.3: Test BPF relocation checker                            : Ok
  [root@jouet ~]#

Further info:

  [root@jouet ~]# gcc --version
  gcc (GCC) 6.1.1 20160621 (Red Hat 6.1.1-3)
  [acme@jouet linux]$ cat /etc/fedora-release
  Fedora release 24 (Twenty Four)

Investigation as to why it fails is still underway, but it was always
going from sys_epoll_wait to SyS_epoll_wait when looking up the DWARF
info in vmlinux, and this is what is breaking now.

Switching to use SyS_epoll_wait allows this test to proceed and test the
BPF code it was designed for, so lets have this in to allow passing this
test while we fix the root cause.

Cc: Adrian Hunter 
Cc: Alexei Starovoitov 
Cc: David Ahern 
Cc: Jiri Olsa 
Cc: Namhyung Kim 
Cc: Wang Nan 
Link: http://lkml.kernel.org/n/tip-7hekjp0bodwjbb419sl2b55h@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo