'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 wait
time (time between sched-out and next 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 wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
-------------- ------ -------------------- --------- --------- ---------
79371.874569 [0011] gcc[31949] 0.014 0.000 1.148
79371.874591 [0010] gcc[31951] 0.000 0.000 0.024
79371.874603 [0010] migration/10[59] 3.350 0.004 0.011
79371.874604 [0011] <idle> 1.148 0.000 0.035
79371.874723 [0005] <idle> 0.016 0.000 1.383
79371.874746 [0005] gcc[31949] 0.153 0.078 0.022
...
Times are in msec.usec.
Committer note:
Add above explanation as the 'perf sched timehist' entry for 'man
perf-sched'.
Signed-off-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <andi@firstfloor.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/20161116060634.28477-4-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Add setting feature that can add config variables with their values to a
config file (i.e. user or system config file) or modify config key-value
pairs in a config file. For the syntax examples:
perf config [<file-option>] [section.name[=value] ...]
e.g. You can set the ui.show-headers to false with
# perf config ui.show-headers=false
If you want to add or modify several config items, you can do like
# perf config annotate.show_nr_jumps=false kmem.default=slab
Committer notes:
Testing it:
$ perf config -l
top.children=true
report.children=false
$
$ perf config top.children=false
$ perf config -l
top.children=false
report.children=false
$
$ perf config kmem.default=slab
$ perf config -l
top.children=false
report.children=false
kmem.default=slab
$
Signed-off-by: Taeung Song <treeze.taeung@gmail.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Nambong Ha <over3025@gmail.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Wang Nan <wangnan0@huawei.com>
Cc: Wookje Kwon <aweee0@gmail.com>
Link: http://lkml.kernel.org/r/1478241862-31230-5-git-send-email-treeze.taeung@gmail.com
[ Combined patch with docs update with this one ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
In the perf wiki todo-list[1], there is an entry regarding initial-delay
and 'perf trace'; the following small patch tries to fulfill this point.
It has been generated against the branch tip/perf/core.
It has only been implemented in the "trace__run" case.
Ex.:
$ sudo strace -- ./perf trace --delay 5 sleep 1 2>&1
...
fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
ioctl(7, PERF_EVENT_IOC_ID, 0x7ffc8fd35718) = 0
ioctl(11, PERF_EVENT_IOC_SET_OUTPUT, 0x7) = 0
fcntl(11, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
ioctl(11, PERF_EVENT_IOC_ID, 0x7ffc8fd35718) = 0
write(6, "\0", 1) = 1
close(6) = 0
nanosleep({0, 5000000}, NULL) = 0 # DELAY OF 5 MS BEFORE ENABLING THE EVENTS
ioctl(3, PERF_EVENT_IOC_ENABLE, 0) = 0
ioctl(4, PERF_EVENT_IOC_ENABLE, 0) = 0
ioctl(5, PERF_EVENT_IOC_ENABLE, 0) = 0
ioctl(7, PERF_EVENT_IOC_ENABLE, 0) = 0
...
[1]: https://perf.wiki.kernel.org/index.php/Todo
Signed-off-by: Alexis Berlemont <alexis.berlemont@gmail.com>
Suggested-and-Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20161010054328.4028-2-alexis.berlemont@gmail.com
[ Add entry to the manpage, cut'n'pasted from stat's and record's ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Previously we were dropping the useful longer descriptions that some
events have in the event list completely. This patch makes them appear with
perf list.
Old perf list:
baclears:
baclears.all
[Counts the number of baclears]
vs new:
perf list -v:
...
baclears:
baclears.all
[The BACLEARS event counts the number of times the front end is
resteered, mainly when the Branch Prediction Unit cannot provide
a correct prediction and this is corrected by the Branch Address
Calculator at the front end. The BACLEARS.ANY event counts the
number of baclears for any type of branch]
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Signed-off-by: Sukadev Bhattiprolu <sukadev@linux.vnet.ibm.com>
Acked-by: Ingo Molnar <mingo@kernel.org>
Acked-by: Jiri Olsa <jolsa@redhat.com>
Cc: Madhavan Srinivasan <maddy@linux.vnet.ibm.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: linuxppc-dev@lists.ozlabs.org
Link: http://lkml.kernel.org/r/1473978296-20712-13-git-send-email-sukadev@linux.vnet.ibm.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
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>
