This patch adds PMU driver specific configuration to the parser
infrastructure by preceding any term with the '@' letter. As such doing
something like:
perf record -e some_event/@cfg1,@cfg2=config/ ...
will see 'cfg1' and 'cfg2=config' being added to the list of evsel
config terms. Token 'cfg1' and 'cfg2=config' are not processed in user
space and are meant to be interpreted by the PMU driver.
First the lexer/parser are supplemented with the required definitions to
recognise the driver specific configuration. From there they are simply
added to the list of event terms. The bulk of the work is done in
function "parse_events_add_pmu()" where driver config event terms are
added to a new list of driver config terms, which in turn spliced with
the event's new driver configuration list.
Signed-off-by: Mathieu Poirier <mathieu.poirier@linaro.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1473179837-3293-4-git-send-email-mathieu.poirier@linaro.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Ignore the buildid of running kernel when both of --definition and
--vmlinux is given because that kernel should be off-line.
This also skips post-processing of kprobe event for relocating symbol
and checking blacklist, because it can not be done on off-line kernel.
E.g. without this fix perf shows an error as below
----
$ perf probe --vmlinux=./vmlinux-arm --definition do_sys_open
./vmlinux-arm with build id 7a1f76dd56e9c4da707cd3d6333f50748141434b not found, continuing without symbols
Failed to find symbol do_sys_open in kernel
Error: Failed to add events.
----
with this fix, we can get the definition
----
$ perf probe --vmlinux=./vmlinux-arm --definition do_sys_open
p:probe/do_sys_open do_sys_open+0
----
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/147214228193.23638.12581984840822162131.stgit@devbox
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
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)
<SNIP>
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 <naohiro.aota@hgst.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Hemant Kumar <hemant@linux.vnet.ibm.com>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Wang Nan <wangnan0@huawei.com>
Link: http://lkml.kernel.org/r/1470710408-23515-1-git-send-email-naohiro.aota@hgst.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
When working with overwritable ring buffer there's a inconvenience
problem: if perf dumps data after a long period after it starts,
non-sample events may lost, which makes following 'perf report' unable
to identify proc name and mmap layout. For example:
# perf record -m 4 -e raw_syscalls:* -g --overwrite --switch-output \
dd if=/dev/zero of=/dev/null
send SIGUSR2 after dd runs long enough. The resuling perf.data lost
correct comm and mmap events:
# perf script -i perf.data.2016061522374354
perf 24478 [004] 2581325.601789: raw_syscalls:sys_exit: NR 0 = 512
^^^^
Should be 'dd'
27b2e8 syscall_slow_exit_work+0xfe2000e3 (/lib/modules/4.6.0-rc3+/build/vmlinux)
203cc7 do_syscall_64+0xfe200117 (/lib/modules/4.6.0-rc3+/build/vmlinux)
b18d83 return_from_SYSCALL_64+0xfe200000 (/lib/modules/4.6.0-rc3+/build/vmlinux)
7f47c417edf0 [unknown] ([unknown])
^^^^^^^^^^^^
Fail to unwind
This patch provides a '--tail-synthesize' option, allows perf to collect
system status when finalizing output file. In resuling output file, the
non-sample events reflect system status when dumping data.
After this patch:
# perf record -m 4 -e raw_syscalls:* -g --overwrite --switch-output --tail-synthesize \
dd if=/dev/zero of=/dev/null
# perf script -i perf.data.2016061600544998
dd 27364 [004] 2583244.994464: raw_syscalls:sys_enter: NR 1 (1, ...
^^
Correct comm
203a18 syscall_trace_enter_phase2+0xfe2001a8 ([kernel.kallsyms])
203aa5 syscall_trace_enter+0xfe200055 ([kernel.kallsyms])
203caa do_syscall_64+0xfe2000fa ([kernel.kallsyms])
b18d83 return_from_SYSCALL_64+0xfe200000 ([kernel.kallsyms])
d8e50 __GI___libc_write+0xffff01d9639f4010 (/tmp/oxygen_root-w00229757/lib64/libc-2.18.so)
^^^^^
Correct unwind
This option doesn't aim to solve this problem completely. If a process
terminates before SIGUSR2, we still lost its COMM and MMAP events. For
example, we can't unwind correctly from the final perf.data we get from
the previous example, because when perf collects the final output file
(when we press C-c), 'dd' has been terminated so its '/proc/<pid>/mmap'
becomes empty.
However, this is a cheaper choice. To completely solve this problem we
need to continously output non-sample events. To satisify the
requirement of daemonization, we need to merge them periodically. It is
possible but requires much more code and cycles.
Automatically select --tail-synthesize when --overwrite is provided.
Signed-off-by: Wang Nan <wangnan0@huawei.com>
Cc: He Kuang <hekuang@huawei.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Nilay Vaish <nilayvaish@gmail.com>
Cc: Zefan Li <lizefan@huawei.com>
Cc: pi3orama@163.com
Link: http://lkml.kernel.org/r/1468485287-33422-16-git-send-email-wangnan0@huawei.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
This patch allows following config terms and option:
Globally setting events to overwrite;
# perf record --overwrite ...
Set specific events to be overwrite or no-overwrite.
# perf record --event cycles/overwrite/ ...
# perf record --event cycles/no-overwrite/ ...
Add missing config terms and update the config term array size because
the longest string length has changed.
For overwritable events, it automatically selects attr.write_backward
since perf requires it to be backward for reading.
Test result:
# perf record --overwrite -e syscalls:*enter_nanosleep* usleep 1
[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0.011 MB perf.data (1 samples) ]
# perf evlist -v
syscalls:sys_enter_nanosleep: type: 2, size: 112, config: 0x134, { sample_period, sample_freq }: 1, sample_type: IP|TID|TIME|CPU|PERIOD|RAW, disabled: 1, inherit: 1, mmap: 1, comm: 1, enable_on_exec: 1, task: 1, sample_id_all: 1, exclude_guest: 1, mmap2: 1, comm_exec: 1, write_backward: 1
# Tip: use 'perf evlist --trace-fields' to show fields for tracepoint events
Signed-off-by: Wang Nan <wangnan0@huawei.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Nilay Vaish <nilayvaish@gmail.com>
Cc: Zefan Li <lizefan@huawei.com>
Cc: pi3orama@163.com
Link: http://lkml.kernel.org/r/1468485287-33422-14-git-send-email-wangnan0@huawei.com
Signed-off-by: He Kuang <hekuang@huawei.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Support a special SDT probe format which can omit the '%' prefix only if
the SDT group name starts with "sdt_". So, for example both of
"%sdt_libc:setjump" and "sdt_libc:setjump" are acceptable for perf probe
--add.
E.g. without this:
# perf probe -a sdt_libc:setjmp
Semantic error :There is non-digit char in line number.
...
With this:
# perf probe -a sdt_libc:setjmp
Added new event:
sdt_libc:setjmp (on %setjmp in /usr/lib64/libc-2.20.so)
You can now use it in all perf tools, such as:
perf record -e sdt_libc:setjmp -aR sleep 1
Suggested-by: Brendan Gregg <brendan.d.gregg@gmail.com>
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Ananth N Mavinakayanahalli <ananth@linux.vnet.ibm.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Hemant Kumar <hemant@linux.vnet.ibm.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/146831794674.17065.13359473252168740430.stgit@devbox
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
To improve usability, support %[PROVIDER:]SDTEVENT format to add new
probes on SDT and cached events.
e.g.
----
# perf probe -x /lib/libc-2.17.so %lll_lock_wait_private
Added new event:
sdt_libc:lll_lock_wait_private (on %lll_lock_wait_private in /usr/lib/libc-2.17.so)
You can now use it in all perf tools, such as:
perf record -e sdt_libc:lll_lock_wait_private -aR sleep 1
# perf probe -l | more
sdt_libc:lll_lock_wait_private (on __lll_lock_wait_private+21 in /usr/lib/libc-2.17.so)
----
Note that this is not only for SDT events, but also normal
events with event-name.
e.g. define "myevent" on cache (-n doesn't add the real probe)
----
# perf probe -x ./perf --cache -n --add 'myevent=dso__load $params'
----
Reuse the "myevent" from cache as below.
----
# perf probe -x ./perf %myevent
----
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Ananth N Mavinakayanahalli <ananth@linux.vnet.ibm.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Hemant Kumar <hemant@linux.vnet.ibm.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/146831788372.17065.3645054540325909346.stgit@devbox
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
perf buildid-cache --add <binary> scans given binary and add
the SDT events to probe cache. "sdt_" prefix is appended for
all SDT providers to avoid event-name clash with other pre-defined
events. It is possible to use the cached SDT events as other cached
events, via perf probe --add "sdt_<provider>:<event>=<event>".
e.g.
----
# perf buildid-cache --add /lib/libc-2.17.so
# perf probe --cache --list | head -n 5
/usr/lib/libc-2.17.so (a6fb821bdf53660eb2c29f778757aef294d3d392):
sdt_libc:setjmp=setjmp
sdt_libc:longjmp=longjmp
sdt_libc:longjmp_target=longjmp_target
sdt_libc:memory_heap_new=memory_heap_new
# perf probe -x /usr/lib/libc-2.17.so \
-a sdt_libc:memory_heap_new=memory_heap_new
Added new event:
sdt_libc:memory_heap_new (on memory_heap_new
in /usr/lib/libc-2.17.so)
You can now use it in all perf tools, such as:
perf record -e sdt_libc:memory_heap_new -aR sleep 1
# perf probe -l
sdt_libc:memory_heap_new (on new_heap+183 in /usr/lib/libc-2.17.so)
----
Note that SDT event entries in probe-cache file is somewhat different
from normal cached events. Normal one starts with "#", but SDTs are
starting with "%".
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Cc: Ananth N Mavinakayanahalli <ananth@linux.vnet.ibm.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Hemant Kumar <hemant@linux.vnet.ibm.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/146736025058.27797.13043265488541434502.stgit@devbox
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
'perf probe --del' removes caches when '--cache' is given. Note that
the delete pattern is not the same as for normal events.
If you cached probes with event name, --del "eventname" works as
expected. However, if you skipped it, the cached probes doesn't have
actual event name. In that case --del "probe-desc" is required (wildcard
is acceptable). For example a cache entry has the probe-desc "vfs_read
$params", you can remove it with --del 'vfs_read*'.
-----
# perf probe --cache --list
/[kernel.kallsyms] (1466a0a250b5d0070c6d0f03c5fed30b237970a1):
vfs_read $params
/usr/lib64/libc-2.17.so (c31ffe7942bfd77b2fca8f9bd5709d387a86d3bc):
getaddrinfo $params
# perf probe --cache --del vfs_read\*
Removed cached event: probe:vfs_read
# perf probe --cache --list
/[kernel.kallsyms] (1466a0a250b5d0070c6d0f03c5fed30b237970a1):
/usr/lib64/libc-2.17.so (c31ffe7942bfd77b2fca8f9bd5709d387a86d3bc):
getaddrinfo $params
-----
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Ananth N Mavinakayanahalli <ananth@linux.vnet.ibm.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Hemant Kumar <hemant@linux.vnet.ibm.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/146736021651.27797.10250879847070772920.stgit@devbox
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Based on patches from Andi Kleen.
When printing PT instruction traces with perf script it is rather useful
to see some indentation for the call tree. This patch adds a new
callindent field to perf script that prints spaces for the function call
stack depth.
We already have code to track the function call stack for PT, that we
can reuse with minor modifications.
The resulting output is not quite as nice as ftrace yet, but a lot
better than what was there before.
Note there are some corner cases when the thread stack gets code
confused and prints incorrect indentation. Even with that it is fairly
useful.
When displaying kernel code traces it is recommended to run as root, as
otherwise perf doesn't understand the kernel addresses properly, and may
not reset the call stack correctly on kernel boundaries.
Example output:
sudo perf-with-kcore record eg2 -a -e intel_pt// -- sleep 1
sudo perf-with-kcore script eg2 --ns -F callindent,time,comm,pid,sym,ip,addr,flags,cpu --itrace=cre | less
...
swapper 0 [000] 5830.389116586: call irq_exit ffffffff8104d620 smp_call_function_single_interrupt+0x30 => ffffffff8107e720 irq_exit
swapper 0 [000] 5830.389116586: call idle_cpu ffffffff8107e769 irq_exit+0x49 => ffffffff810a3970 idle_cpu
swapper 0 [000] 5830.389116586: return idle_cpu ffffffff810a39b7 idle_cpu+0x47 => ffffffff8107e76e irq_exit
swapper 0 [000] 5830.389116586: call tick_nohz_irq_exit ffffffff8107e7bd irq_exit+0x9d => ffffffff810f2fc0 tick_nohz_irq_exit
swapper 0 [000] 5830.389116919: call __tick_nohz_idle_enter ffffffff810f2fe0 tick_nohz_irq_exit+0x20 => ffffffff810f28d0 __tick_nohz_idle_enter
swapper 0 [000] 5830.389116919: call ktime_get ffffffff810f28f1 __tick_nohz_idle_enter+0x21 => ffffffff810e9ec0 ktime_get
swapper 0 [000] 5830.389116919: call read_tsc ffffffff810e9ef6 ktime_get+0x36 => ffffffff81035070 read_tsc
swapper 0 [000] 5830.389116919: return read_tsc ffffffff81035084 read_tsc+0x14 => ffffffff810e9efc ktime_get
swapper 0 [000] 5830.389116919: return ktime_get ffffffff810e9f46 ktime_get+0x86 => ffffffff810f28f6 __tick_nohz_idle_enter
swapper 0 [000] 5830.389116919: call sched_clock_idle_sleep_event ffffffff810f290b __tick_nohz_idle_enter+0x3b => ffffffff810a7380 sched_clock_idle_sleep_event
swapper 0 [000] 5830.389116919: call sched_clock_cpu ffffffff810a738b sched_clock_idle_sleep_event+0xb => ffffffff810a72e0 sched_clock_cpu
swapper 0 [000] 5830.389116919: call sched_clock ffffffff810a734d sched_clock_cpu+0x6d => ffffffff81035750 sched_clock
swapper 0 [000] 5830.389116919: call native_sched_clock ffffffff81035754 sched_clock+0x4 => ffffffff81035640 native_sched_clock
swapper 0 [000] 5830.389116919: return native_sched_clock ffffffff8103568c native_sched_clock+0x4c => ffffffff81035759 sched_clock
swapper 0 [000] 5830.389116919: return sched_clock ffffffff8103575c sched_clock+0xc => ffffffff810a7352 sched_clock_cpu
swapper 0 [000] 5830.389116919: return sched_clock_cpu ffffffff810a7356 sched_clock_cpu+0x76 => ffffffff810a7390 sched_clock_idle_sleep_event
swapper 0 [000] 5830.389116919: return sched_clock_idle_sleep_event ffffffff810a7391 sched_clock_idle_sleep_event+0x11 => ffffffff810f2910 __tick_nohz_idle_enter
...
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Acked-by: Andi Kleen <ak@linux.intel.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/1466689258-28493-4-git-send-email-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
The flags field is synthesized and may have a value when Instruction
Trace decoding. The flags are "bcrosyiABEx" which stand for branch,
call, return, conditional, system, asynchronous, interrupt, transaction
abort, trace begin, trace end, and in transaction, respectively.
Change the display so that known combinations of flags are printed more
nicely e.g.: "call" for "bc", "return" for "br", "jcc" for "bo", "jmp"
for "b", "int" for "bci", "iret" for "bri", "syscall" for "bcs",
"sysret" for "brs", "async" for "by", "hw int" for "bcyi", "tx abrt" for
"bA", "tr strt" for "bB", "tr end" for "bE".
However the "x" flag will be displayed separately in those cases e.g.
"jcc (x)" for a condition branch within a transaction.
Example:
perf record -e intel_pt//u ls
perf script --ns -F comm,cpu,pid,tid,time,ip,addr,sym,dso,symoff,flags
...
ls 3689/3689 [001] 2062.020965237: jcc 7f06a958847a _dl_sysdep_start+0xfa (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a9588450 _dl_sysdep_start+0xd0 (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020965237: jmp 7f06a9588461 _dl_sysdep_start+0xe1 (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a95885a0 _dl_sysdep_start+0x220 (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020965237: jmp 7f06a95885a4 _dl_sysdep_start+0x224 (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a9588470 _dl_sysdep_start+0xf0 (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020965904: call 7f06a95884c3 _dl_sysdep_start+0x143 (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a9589140 brk+0x0 (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020965904: syscall 7f06a958914a brk+0xa (/lib/x86_64-linux-gnu/ld-2.19.so) => 0 [unknown] ([unknown])
ls 3689/3689 [001] 2062.020966237: tr strt 0 [unknown] ([unknown]) => 7f06a958914c brk+0xc (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020966237: return 7f06a9589165 brk+0x25 (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a95884c8 _dl_sysdep_start+0x148 (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020966237: jcc 7f06a95884d7 _dl_sysdep_start+0x157 (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a95885f0 _dl_sysdep_start+0x270 (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020966237: call 7f06a95885f0 _dl_sysdep_start+0x270 (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a958ac50 strlen+0x0 (/lib/x86_64-linux-gnu/ld-2.19.so)
ls 3689/3689 [001] 2062.020966237: jcc 7f06a958ac6e strlen+0x1e (/lib/x86_64-linux-gnu/ld-2.19.so) => 7f06a958ac60 strlen+0x10 (/lib/x86_64-linux-gnu/ld-2.19.so)
...
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Acked-by: Andi Kleen <ak@linux.intel.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/1466689258-28493-2-git-send-email-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Add basic plumbing for TopDown in perf stat
TopDown is intended to replace the frontend cycles idle/ backend cycles
idle metrics in standard perf stat output. These metrics are not
reliable in many workloads, due to out of order effects.
This implements a new --topdown mode in perf stat (similar to
--transaction) that measures the pipe line bottlenecks using
standardized formulas. The measurement can be all done with 5 counters
(one fixed counter)
The result are four metrics:
FrontendBound, BackendBound, BadSpeculation, Retiring
that describe the CPU pipeline behavior on a high level.
The full top down methology has many hierarchical metrics. This
implementation only supports level 1 which can be collected without
multiplexing. A full implementation of top down on top of perf is
available in pmu-tools toplev. (http://github.com/andikleen/pmu-tools)
The current version works on Intel Core CPUs starting with Sandy Bridge,
and Atom CPUs starting with Silvermont. In principle the generic
metrics should be also implementable on other out of order CPUs.
TopDown level 1 uses a set of abstracted metrics which are generic to
out of order CPU cores (although some CPUs may not implement all of
them):
topdown-total-slots Available slots in the pipeline
topdown-slots-issued Slots issued into the pipeline
topdown-slots-retired Slots successfully retired
topdown-fetch-bubbles Pipeline gaps in the frontend
topdown-recovery-bubbles Pipeline gaps during recovery
from misspeculation
These metrics then allow to compute four useful metrics:
FrontendBound, BackendBound, Retiring, BadSpeculation.
Add a new --topdown options to enable events. When --topdown is
specified set up events for all topdown events supported by the kernel.
Add topdown-* as a special case to the event parser, as is needed for
all events containing -.
The actual code to compute the metrics is in follow-on patches.
v2: Use standard sysctl read function.
v3: Move x86 specific code to arch/
v4: Enable --metric-only implicitly for topdown.
v5: Add --single-thread option to not force per core mode
v6: Fix output order of topdown metrics
v7: Allow combining with -d
v8: Remove --single-thread again
v9: Rename functions, adding arch_ and topdown_.
v10: Expand man page and describe TopDown better
Paste intro into commit description.
Print error when malloc fails.
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Link: http://lkml.kernel.org/r/1464119559-17203-1-git-send-email-andi@firstfloor.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Without this patch, the last output doesn't have timestamp appended if
--timestamp-filename is not explicitly provided. For example:
# perf record -a --switch-output &
[1] 11224
# kill -s SIGUSR2 11224
[ perf record: dump data: Woken up 1 times ]
# [ perf record: Dump perf.data.2015122622372823 ]
# fg
perf record -a --switch-output
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.027 MB perf.data (540 samples) ]
# ls -l
total 836
-rw------- 1 root root 33256 Dec 26 22:37 perf.data <---- *Odd*
-rw------- 1 root root 817156 Dec 26 22:37 perf.data.2015122622372823
Signed-off-by: Wang Nan <wangnan0@huawei.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Zefan Li <lizefan@huawei.com>
Cc: pi3orama@163.com
Link: http://lkml.kernel.org/r/1461178794-40467-5-git-send-email-wangnan0@huawei.com
Signed-off-by: He Kuang <hekuang@huawei.com>
[ Updated man page, that also got an entry for --timestamp-filename ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Now, one can print the call chain for every encountered sys_exit event,
e.g.:
$ perf trace -e nanosleep --call-graph dwarf path/to/ex_sleep
1005.757 (1000.090 ms): ex_sleep/13167 nanosleep(...) = 0
syscall_slow_exit_work ([kernel.kallsyms])
syscall_return_slowpath ([kernel.kallsyms])
int_ret_from_sys_call ([kernel.kallsyms])
__nanosleep (/usr/lib/libc-2.23.so)
[unknown] (/usr/lib/libQt5Core.so.5.6.0)
QThread::sleep (/usr/lib/libQt5Core.so.5.6.0)
main (path/to/ex_sleep)
__libc_start_main (/usr/lib/libc-2.23.so)
_start (path/to/ex_sleep)
Note that it is advised to increase the number of mmap pages to prevent
event losses when using this new feature. Often, adding `-m 10M` to the
`perf trace` invocation is enough.
This feature is also available in strace when built with libunwind via
`strace -k`. Performance wise, this solution is much better:
$ time find path/to/linux &> /dev/null
real 0m0.051s
user 0m0.013s
sys 0m0.037s
$ time perf trace -m 800M --call-graph dwarf find path/to/linux &> /dev/null
real 0m2.624s
user 0m1.203s
sys 0m1.333s
$ time strace -k find path/to/linux &> /dev/null
real 0m35.398s
user 0m10.403s
sys 0m23.173s
Note that it is currently not possible to configure the print output.
Adding such a feature, similar to what is available in `perf script` via
its `--fields` knob can be added later on.
Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Wang Nan <wangnan0@huawei.com>
LPU-Reference: 1460115255-17648-1-git-send-email-milian.wolff@kdab.com
[ Split from a larger patch, do not print the IP, left align,
remove dup call symbol__init(), added man page entry ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
