2010-11-17 01:45:39 +08:00
|
|
|
perf-script(1)
|
2010-05-05 22:23:27 +08:00
|
|
|
=============
|
2009-09-11 18:12:54 +08:00
|
|
|
|
|
|
|
NAME
|
|
|
|
----
|
2010-11-17 01:45:39 +08:00
|
|
|
perf-script - Read perf.data (created by perf record) and display trace output
|
2009-09-11 18:12:54 +08:00
|
|
|
|
|
|
|
SYNOPSIS
|
|
|
|
--------
|
|
|
|
[verse]
|
2010-11-17 01:45:39 +08:00
|
|
|
'perf script' [<options>]
|
|
|
|
'perf script' [<options>] record <script> [<record-options>] <command>
|
|
|
|
'perf script' [<options>] report <script> [script-args]
|
|
|
|
'perf script' [<options>] <script> <required-script-args> [<record-options>] <command>
|
|
|
|
'perf script' [<options>] <top-script> [script-args]
|
2009-09-11 18:12:54 +08:00
|
|
|
|
|
|
|
DESCRIPTION
|
|
|
|
-----------
|
|
|
|
This command reads the input file and displays the trace recorded.
|
|
|
|
|
2010-11-17 01:45:39 +08:00
|
|
|
There are several variants of perf script:
|
2009-12-15 16:53:40 +08:00
|
|
|
|
2010-11-17 01:45:39 +08:00
|
|
|
'perf script' to see a detailed trace of the workload that was
|
2009-12-15 16:53:40 +08:00
|
|
|
recorded.
|
|
|
|
|
2010-01-27 16:28:03 +08:00
|
|
|
You can also run a set of pre-canned scripts that aggregate and
|
|
|
|
summarize the raw trace data in various ways (the list of scripts is
|
2010-11-17 01:45:39 +08:00
|
|
|
available via 'perf script -l'). The following variants allow you to
|
2010-01-27 16:28:03 +08:00
|
|
|
record and run those scripts:
|
|
|
|
|
2010-11-17 01:45:39 +08:00
|
|
|
'perf script record <script> <command>' to record the events required
|
|
|
|
for 'perf script report'. <script> is the name displayed in the
|
|
|
|
output of 'perf script --list' i.e. the actual script name minus any
|
2010-11-10 22:19:35 +08:00
|
|
|
language extension. If <command> is not specified, the events are
|
|
|
|
recorded using the -a (system-wide) 'perf record' option.
|
2009-12-15 16:53:40 +08:00
|
|
|
|
2010-11-17 01:45:39 +08:00
|
|
|
'perf script report <script> [args]' to run and display the results
|
2010-11-10 22:19:35 +08:00
|
|
|
of <script>. <script> is the name displayed in the output of 'perf
|
2017-01-13 23:06:52 +08:00
|
|
|
script --list' i.e. the actual script name minus any language
|
2010-11-17 01:45:39 +08:00
|
|
|
extension. The perf.data output from a previous run of 'perf script
|
2009-12-15 16:53:40 +08:00
|
|
|
record <script>' is used and should be present for this command to
|
2010-11-10 22:19:35 +08:00
|
|
|
succeed. [args] refers to the (mainly optional) args expected by
|
|
|
|
the script.
|
|
|
|
|
2010-11-17 01:45:39 +08:00
|
|
|
'perf script <script> <required-script-args> <command>' to both
|
2010-11-10 22:19:35 +08:00
|
|
|
record the events required for <script> and to run the <script>
|
|
|
|
using 'live-mode' i.e. without writing anything to disk. <script>
|
2010-11-17 01:45:39 +08:00
|
|
|
is the name displayed in the output of 'perf script --list' i.e. the
|
2010-11-10 22:19:35 +08:00
|
|
|
actual script name minus any language extension. If <command> is
|
|
|
|
not specified, the events are recorded using the -a (system-wide)
|
|
|
|
'perf record' option. If <script> has any required args, they
|
|
|
|
should be specified before <command>. This mode doesn't allow for
|
|
|
|
optional script args to be specified; if optional script args are
|
2010-11-17 01:45:39 +08:00
|
|
|
desired, they can be specified using separate 'perf script record'
|
|
|
|
and 'perf script report' commands, with the stdout of the record step
|
2010-11-10 22:19:35 +08:00
|
|
|
piped to the stdin of the report script, using the '-o -' and '-i -'
|
|
|
|
options of the corresponding commands.
|
|
|
|
|
2010-11-17 01:45:39 +08:00
|
|
|
'perf script <top-script>' to both record the events required for
|
2010-11-10 22:19:35 +08:00
|
|
|
<top-script> and to run the <top-script> using 'live-mode'
|
|
|
|
i.e. without writing anything to disk. <top-script> is the name
|
2010-11-17 01:45:39 +08:00
|
|
|
displayed in the output of 'perf script --list' i.e. the actual
|
2010-11-10 22:19:35 +08:00
|
|
|
script name minus any language extension; a <top-script> is defined
|
|
|
|
as any script name ending with the string 'top'.
|
|
|
|
|
2010-11-17 01:45:39 +08:00
|
|
|
[<record-options>] can be passed to the record steps of 'perf script
|
2010-11-10 22:19:35 +08:00
|
|
|
record' and 'live-mode' variants; this isn't possible however for
|
2010-11-17 01:45:39 +08:00
|
|
|
<top-script> 'live-mode' or 'perf script report' variants.
|
2009-12-15 16:53:40 +08:00
|
|
|
|
2010-01-27 16:28:03 +08:00
|
|
|
See the 'SEE ALSO' section for links to language-specific
|
|
|
|
information on how to write and run your own trace scripts.
|
|
|
|
|
2009-09-11 18:12:54 +08:00
|
|
|
OPTIONS
|
|
|
|
-------
|
2010-11-10 22:19:35 +08:00
|
|
|
<command>...::
|
|
|
|
Any command you can specify in a shell.
|
|
|
|
|
2009-09-11 18:12:54 +08:00
|
|
|
-D::
|
2017-01-13 23:06:52 +08:00
|
|
|
--dump-raw-trace=::
|
2009-09-11 18:12:54 +08:00
|
|
|
Display verbose dump of the trace data.
|
|
|
|
|
2009-12-15 16:53:40 +08:00
|
|
|
-L::
|
|
|
|
--Latency=::
|
|
|
|
Show latency attributes (irqs/preemption disabled, etc).
|
|
|
|
|
|
|
|
-l::
|
|
|
|
--list=::
|
|
|
|
Display a list of available trace scripts.
|
|
|
|
|
2010-01-27 16:27:52 +08:00
|
|
|
-s ['lang']::
|
2009-11-25 15:15:51 +08:00
|
|
|
--script=::
|
|
|
|
Process trace data with the given script ([lang]:script[.ext]).
|
2010-01-27 16:27:52 +08:00
|
|
|
If the string 'lang' is specified in place of a script name, a
|
|
|
|
list of supported languages will be displayed instead.
|
2009-11-25 15:15:51 +08:00
|
|
|
|
|
|
|
-g::
|
|
|
|
--gen-script=::
|
2010-11-17 01:45:39 +08:00
|
|
|
Generate perf-script.[ext] starter script for given language,
|
2009-11-25 15:15:51 +08:00
|
|
|
using current perf.data.
|
|
|
|
|
2021-06-27 21:18:09 +08:00
|
|
|
--dlfilter=<file>::
|
|
|
|
Filter sample events using the given shared object file.
|
|
|
|
Refer linkperf:perf-dlfilter[1]
|
|
|
|
|
2021-06-27 21:18:12 +08:00
|
|
|
--dlarg=<arg>::
|
|
|
|
Pass 'arg' as an argument to the dlfilter. --dlarg may be repeated
|
|
|
|
to add more arguments.
|
|
|
|
|
2021-08-11 18:10:33 +08:00
|
|
|
--list-dlfilters::
|
2021-06-27 21:18:11 +08:00
|
|
|
Display a list of available dlfilters. Use with option -v (must come
|
|
|
|
before option --list-dlfilters) to show long descriptions.
|
|
|
|
|
2010-11-10 22:19:35 +08:00
|
|
|
-a::
|
|
|
|
Force system-wide collection. Scripts run without a <command>
|
|
|
|
normally use -a by default, while scripts run with a <command>
|
|
|
|
normally don't - this option allows the latter to be run in
|
|
|
|
system-wide mode.
|
|
|
|
|
2010-12-01 09:57:22 +08:00
|
|
|
-i::
|
|
|
|
--input=::
|
2011-12-07 17:02:54 +08:00
|
|
|
Input file name. (default: perf.data unless stdin is a fifo)
|
2010-12-01 09:57:22 +08:00
|
|
|
|
|
|
|
-d::
|
|
|
|
--debug-mode::
|
|
|
|
Do various checks like samples ordering and lost events.
|
2010-11-10 22:19:35 +08:00
|
|
|
|
2015-09-01 00:41:13 +08:00
|
|
|
-F::
|
2011-03-31 02:30:43 +08:00
|
|
|
--fields::
|
perf script: Support custom field selection for output
Allow a user to select which fields to print to stdout for event data.
Options include comm (command name), tid (thread id), pid (process id),
time (perf timestamp), cpu, event (for event name), and trace (for
trace data).
Default is set to maintain compatibility with current output; this
feature does alter output format slightly -- no '-' between command
and pid/tid.
Thanks to Frederic Weisbecker for detailed suggestions on this approach.
Examples (output compressed)
1. trace, default format
perf record -ga -e sched:sched_switch
perf script
swapper 0 [000] 537.037184: sched_switch: prev_comm=swapper prev_pid=0...
sshd 1675 [000] 537.037309: sched_switch: prev_comm=sshd prev_pid=1675...
netstat 1692 [001] 537.038664: sched_switch: prev_comm=netstat prev_pid=1692...
2. trace, custom format
perf record -ga -e sched:sched_switch
perf script -f comm,pid,time,trace <--- omitting cpu and event name
swapper 0 537.037184: prev_comm=swapper prev_pid=0 prev_prio=120 ...
sshd 1675 537.037309: prev_comm=sshd prev_pid=1675 prev_prio=120 ...
netstat 1692 537.038664: prev_comm=netstat prev_pid=1692 prev_prio=120 ...
Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
LKML-Reference: <1299734608-5223-5-git-send-email-daahern@cisco.com>
Signed-off-by: David Ahern <daahern@cisco.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2011-03-10 13:23:26 +08:00
|
|
|
Comma separated list of fields to print. Options are:
|
perf script: Add field option 'flags' to print sample flags
Instruction tracing will typically have access to information about the
instruction being executed for a particular ip sample. Some of that
information will be available in the 'flags' member of struct
perf_sample.
With the addition of transactions events synthesis to Instruction
Tracing options, there is a need to be able easily to see the flags
because they show whether the ip is at the start, commit or abort of a
tranasaction.
Consequently add an option to display the flags.
The flags are "bcrosyiABEx" which stand for branch, call, return,
conditional, system, asynchronous, interrupt, transaction abort, trace
begin, trace end, and in transaction, respectively.
Example using Intel PT:
perf script -fip,time,event,sym,addr,flags
...
1288.721584105: branches:u: bo 401146 main => 401152 main
1288.721584105: transactions: x 0 401164 main
1288.721584105: branches:u: bx 40117c main => 40119b main
1288.721584105: branches:u: box 4011a4 main => 40117e main
1288.721584105: branches:u: bcx 401187 main => 401094 g
...
1288.721591645: branches:u: bx 4010c4 g => 4010cb g
1288.721591645: branches:u: brx 4010cc g => 401189 main
1288.721591645: transactions: 0 4011a6 main
1288.721593199: branches:u: b 4011a9 main => 4011af main
1288.721593199: branches:u: bo 4011bc main => 40113e main
1288.721593199: branches:u: b 401150 main => 40115a main
1288.721593199: transactions: x 0 401164 main
1288.721593199: branches:u: bx 40117c main => 40119b main
1288.721593199: branches:u: box 4011a4 main => 40117e main
1288.721593199: branches:u: bcx 401187 main => 40105e f
...
1288.722284747: branches:u: brx 401093 f => 401189 main
1288.722284747: branches:u: box 4011a4 main => 40117e main
1288.722284747: branches:u: bcx 401187 main => 40105e f
1288.722285883: transactions: bA 0 401071 f
1288.722285883: branches:u: bA 401071 f => 40116a main
1288.722285883: branches:u: bE 40116a main => 0 [unknown]
1288.722297174: branches:u: bB 0 [unknown] => 40116a main
...
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/1428594864-29309-26-git-send-email-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-09 23:54:05 +08:00
|
|
|
comm, tid, pid, time, cpu, event, trace, ip, sym, dso, addr, symoff,
|
2020-12-17 02:57:57 +08:00
|
|
|
srcline, period, iregs, uregs, brstack, brstacksym, flags, bpf-output,
|
|
|
|
brstackinsn, brstackoff, callindent, insn, insnlen, synth, phys_addr,
|
2021-09-29 23:38:14 +08:00
|
|
|
metric, misc, srccode, ipc, data_page_size, code_page_size, ins_lat.
|
2017-05-26 16:17:22 +08:00
|
|
|
Field list can be prepended with the type, trace, sw or hw,
|
2011-03-10 13:23:28 +08:00
|
|
|
to indicate to which event type the field list applies.
|
2016-06-17 03:51:26 +08:00
|
|
|
e.g., -F sw:comm,tid,time,ip,sym and -F trace:time,cpu,trace
|
2011-03-10 13:23:27 +08:00
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
perf script -F <fields>
|
2011-03-31 02:30:43 +08:00
|
|
|
|
|
|
|
is equivalent to:
|
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
perf script -F trace:<fields> -F sw:<fields> -F hw:<fields>
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2011-03-31 02:30:43 +08:00
|
|
|
i.e., the specified fields apply to all event types if the type string
|
|
|
|
is not given.
|
2014-12-18 04:24:45 +08:00
|
|
|
|
perf script: Allow adding and removing fields
With 'perf script' it is common that we just want to add or remove a field.
Currently this requires figuring out the long list of default fields and
specifying them first, and then adding/removing the new field.
This patch adds a new + - syntax to merely add or remove fields,
that allows more succint and clearer command lines
For example to remove the comm field from PMU samples:
Previously
$ perf script -F tid,cpu,time,event,sym,ip,dso,period | head -1
swapper 0 [000] 504345.383126: 1 cycles: ffffffff90060c66 native_write_msr ([kernel.kallsyms])
with the new syntax
perf script -F -comm | head -1
0 [000] 504345.383126: 1 cycles: ffffffff90060c66 native_write_msr ([kernel.kallsyms])
The new syntax cannot be mixed with normal overriding.
v2: Fix example in description. Use tid vs pid. No functional changes.
v3: Don't skip initialization when user specified explicit type.
v4: Rebase. Remove empty line.
Committer testing:
# perf record -a usleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.748 MB perf.data (14 samples) ]
Without a explicit field list specified via -F, defaults to:
# perf script | head -2
perf 6338 [000] 18467.058607: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
swapper 0 [001] 18467.058617: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
#
Which is equivalent to:
# perf script -F comm,tid,cpu,time,period,event,ip,sym,dso | head -2
perf 6338 [000] 18467.058607: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
swapper 0 [001] 18467.058617: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
#
So if we want to remove the comm, as in your original example, we would have to
figure out the default field list and remove ' comm' from it:
# perf script -F tid,cpu,time,period,event,ip,sym,dso | head -2
6338 [000] 18467.058607: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
0 [001] 18467.058617: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
#
With your patch this becomes simpler, one can remove fields by prefixing them
with '-':
# perf script -F -comm | head -2
6338 [000] 18467.058607: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
0 [001] 18467.058617: 1 cycles: ffffffff89060c36 native_write_msr (/lib/modules/4.11.0-rc8+/build/vmlinux)
#
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Tested-by: Milian Wolff <milian.wolff@kdab.com>
Link: http://lkml.kernel.org/r/20170602154810.15875-1-andi@firstfloor.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2017-06-02 23:48:10 +08:00
|
|
|
In addition to overriding fields, it is also possible to add or remove
|
|
|
|
fields from the defaults. For example
|
|
|
|
|
|
|
|
-F -cpu,+insn
|
|
|
|
|
|
|
|
removes the cpu field and adds the insn field. Adding/removing fields
|
|
|
|
cannot be mixed with normal overriding.
|
|
|
|
|
2011-03-31 02:30:43 +08:00
|
|
|
The arguments are processed in the order received. A later usage can
|
|
|
|
reset a prior request. e.g.:
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
-F trace: -F comm,tid,time,ip,sym
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
The first -F suppresses trace events (field list is ""), but then the
|
2011-05-28 04:28:43 +08:00
|
|
|
second invocation sets the fields to comm,tid,time,ip,sym. In this case a
|
2011-03-31 02:30:43 +08:00
|
|
|
warning is given to the user:
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2011-03-31 02:30:43 +08:00
|
|
|
"Overriding previous field request for all events."
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2014-09-09 23:18:50 +08:00
|
|
|
Alternatively, consider the order:
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
-F comm,tid,time,ip,sym -F trace:
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
The first -F sets the fields for all events and the second -F
|
2011-03-31 02:30:43 +08:00
|
|
|
suppresses trace events. The user is given a warning message about
|
|
|
|
the override, and the result of the above is that only S/W and H/W
|
|
|
|
events are displayed with the given fields.
|
2014-12-18 04:24:45 +08:00
|
|
|
|
perf script: Allow +- operator for type specific fields option
Add support to add/remove fields for specific event types in -F option.
It's now possible to use '+-' after event type, like:
# cat > test.c
#include <stdio.h>
int main(void)
{
printf("Hello world\n");
while(1) {}
}
^D
# gcc -g -o test test.c
# perf probe -x test 'test.c:5'
# perf record -e '{cpu/cpu-cycles,period=10000/,probe_test:main}:S' ./test
...
# perf script -Ftrace:+period,-cpu
test 3859 396291.117343: 10275 cpu/cpu-cycles,period=10000/: 7f..
test 3859 396291.118234: 11041 cpu/cpu-cycles,period=10000/: ffffff..
test 3859 396291.118234: 1 probe_test:main:
test 3859 396291.118248: 8668 cpu/cpu-cycles,period=10000/: ffffff..
test 3859 396291.118263: 10139 cpu/cpu-cycles,period=10000/: ffffff..
Committer testing:
Couldn't make the test above work, but tested it with:
# perf probe -x hello main
Added new event:
probe_hello:main (on main in /home/acme/c/hello)
You can now use it in all perf tools, such as:
perf record -e probe_hello:main -aR sleep 1
# perf record -e probe_hello:main ./hello
hello, world
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.025 MB perf.data (1 samples) ]
# perf script
hello 21454 [002] 254116.874005: probe_hello:main: (401126)
#
# perf script -Ftrace:+period,-cpu
hello 21454 254116.874005: 1 probe_hello:main: (401126)
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20190220122800.864-4-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2019-02-20 20:27:57 +08:00
|
|
|
It's possible tp add/remove fields only for specific event type:
|
|
|
|
|
|
|
|
-Fsw:-cpu,-period
|
|
|
|
|
|
|
|
removes cpu and period from software events.
|
|
|
|
|
2011-03-31 02:30:43 +08:00
|
|
|
For the 'wildcard' option if a user selected field is invalid for an
|
|
|
|
event type, a message is displayed to the user that the option is
|
|
|
|
ignored for that type. For example:
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
$ perf script -F comm,tid,trace
|
2011-03-31 02:30:43 +08:00
|
|
|
'trace' not valid for hardware events. Ignoring.
|
|
|
|
'trace' not valid for software events. Ignoring.
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2011-03-31 02:30:43 +08:00
|
|
|
Alternatively, if the type is given an invalid field is specified it
|
|
|
|
is an error. For example:
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2016-06-17 03:51:26 +08:00
|
|
|
perf script -v -F sw:comm,tid,trace
|
2011-03-31 02:30:43 +08:00
|
|
|
'trace' not valid for software events.
|
2014-12-18 04:24:45 +08:00
|
|
|
|
2011-03-31 02:30:43 +08:00
|
|
|
At this point usage is displayed, and perf-script exits.
|
2014-12-18 04:24:45 +08:00
|
|
|
|
perf script: Add field option 'flags' to print sample flags
Instruction tracing will typically have access to information about the
instruction being executed for a particular ip sample. Some of that
information will be available in the 'flags' member of struct
perf_sample.
With the addition of transactions events synthesis to Instruction
Tracing options, there is a need to be able easily to see the flags
because they show whether the ip is at the start, commit or abort of a
tranasaction.
Consequently add an option to display the flags.
The flags are "bcrosyiABEx" which stand for branch, call, return,
conditional, system, asynchronous, interrupt, transaction abort, trace
begin, trace end, and in transaction, respectively.
Example using Intel PT:
perf script -fip,time,event,sym,addr,flags
...
1288.721584105: branches:u: bo 401146 main => 401152 main
1288.721584105: transactions: x 0 401164 main
1288.721584105: branches:u: bx 40117c main => 40119b main
1288.721584105: branches:u: box 4011a4 main => 40117e main
1288.721584105: branches:u: bcx 401187 main => 401094 g
...
1288.721591645: branches:u: bx 4010c4 g => 4010cb g
1288.721591645: branches:u: brx 4010cc g => 401189 main
1288.721591645: transactions: 0 4011a6 main
1288.721593199: branches:u: b 4011a9 main => 4011af main
1288.721593199: branches:u: bo 4011bc main => 40113e main
1288.721593199: branches:u: b 401150 main => 40115a main
1288.721593199: transactions: x 0 401164 main
1288.721593199: branches:u: bx 40117c main => 40119b main
1288.721593199: branches:u: box 4011a4 main => 40117e main
1288.721593199: branches:u: bcx 401187 main => 40105e f
...
1288.722284747: branches:u: brx 401093 f => 401189 main
1288.722284747: branches:u: box 4011a4 main => 40117e main
1288.722284747: branches:u: bcx 401187 main => 40105e f
1288.722285883: transactions: bA 0 401071 f
1288.722285883: branches:u: bA 401071 f => 40116a main
1288.722285883: branches:u: bE 40116a main => 0 [unknown]
1288.722297174: branches:u: bB 0 [unknown] => 40116a main
...
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/1428594864-29309-26-git-send-email-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-09 23:54:05 +08:00
|
|
|
The flags field is synthesized and may have a value when Instruction
|
2021-05-22 01:51:27 +08:00
|
|
|
Trace decoding. The flags are "bcrosyiABExgh" which stand for branch,
|
perf script: Add field option 'flags' to print sample flags
Instruction tracing will typically have access to information about the
instruction being executed for a particular ip sample. Some of that
information will be available in the 'flags' member of struct
perf_sample.
With the addition of transactions events synthesis to Instruction
Tracing options, there is a need to be able easily to see the flags
because they show whether the ip is at the start, commit or abort of a
tranasaction.
Consequently add an option to display the flags.
The flags are "bcrosyiABEx" which stand for branch, call, return,
conditional, system, asynchronous, interrupt, transaction abort, trace
begin, trace end, and in transaction, respectively.
Example using Intel PT:
perf script -fip,time,event,sym,addr,flags
...
1288.721584105: branches:u: bo 401146 main => 401152 main
1288.721584105: transactions: x 0 401164 main
1288.721584105: branches:u: bx 40117c main => 40119b main
1288.721584105: branches:u: box 4011a4 main => 40117e main
1288.721584105: branches:u: bcx 401187 main => 401094 g
...
1288.721591645: branches:u: bx 4010c4 g => 4010cb g
1288.721591645: branches:u: brx 4010cc g => 401189 main
1288.721591645: transactions: 0 4011a6 main
1288.721593199: branches:u: b 4011a9 main => 4011af main
1288.721593199: branches:u: bo 4011bc main => 40113e main
1288.721593199: branches:u: b 401150 main => 40115a main
1288.721593199: transactions: x 0 401164 main
1288.721593199: branches:u: bx 40117c main => 40119b main
1288.721593199: branches:u: box 4011a4 main => 40117e main
1288.721593199: branches:u: bcx 401187 main => 40105e f
...
1288.722284747: branches:u: brx 401093 f => 401189 main
1288.722284747: branches:u: box 4011a4 main => 40117e main
1288.722284747: branches:u: bcx 401187 main => 40105e f
1288.722285883: transactions: bA 0 401071 f
1288.722285883: branches:u: bA 401071 f => 40116a main
1288.722285883: branches:u: bE 40116a main => 0 [unknown]
1288.722297174: branches:u: bB 0 [unknown] => 40116a main
...
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/1428594864-29309-26-git-send-email-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-09 23:54:05 +08:00
|
|
|
call, return, conditional, system, asynchronous, interrupt,
|
2021-05-22 01:51:27 +08:00
|
|
|
transaction abort, trace begin, trace end, in transaction, VM-Entry, and VM-Exit
|
perf script: Print sample flags more nicely
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>
2016-06-23 21:40:56 +08:00
|
|
|
respectively. 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",
|
2021-05-22 01:51:27 +08:00
|
|
|
"tr end" for "bE", "vmentry" for "bcg", "vmexit" for "bch".
|
|
|
|
However the "x" flag will be displayed separately in those
|
perf script: Print sample flags more nicely
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>
2016-06-23 21:40:56 +08:00
|
|
|
cases e.g. "jcc (x)" for a condition branch within a transaction.
|
perf script: Add field option 'flags' to print sample flags
Instruction tracing will typically have access to information about the
instruction being executed for a particular ip sample. Some of that
information will be available in the 'flags' member of struct
perf_sample.
With the addition of transactions events synthesis to Instruction
Tracing options, there is a need to be able easily to see the flags
because they show whether the ip is at the start, commit or abort of a
tranasaction.
Consequently add an option to display the flags.
The flags are "bcrosyiABEx" which stand for branch, call, return,
conditional, system, asynchronous, interrupt, transaction abort, trace
begin, trace end, and in transaction, respectively.
Example using Intel PT:
perf script -fip,time,event,sym,addr,flags
...
1288.721584105: branches:u: bo 401146 main => 401152 main
1288.721584105: transactions: x 0 401164 main
1288.721584105: branches:u: bx 40117c main => 40119b main
1288.721584105: branches:u: box 4011a4 main => 40117e main
1288.721584105: branches:u: bcx 401187 main => 401094 g
...
1288.721591645: branches:u: bx 4010c4 g => 4010cb g
1288.721591645: branches:u: brx 4010cc g => 401189 main
1288.721591645: transactions: 0 4011a6 main
1288.721593199: branches:u: b 4011a9 main => 4011af main
1288.721593199: branches:u: bo 4011bc main => 40113e main
1288.721593199: branches:u: b 401150 main => 40115a main
1288.721593199: transactions: x 0 401164 main
1288.721593199: branches:u: bx 40117c main => 40119b main
1288.721593199: branches:u: box 4011a4 main => 40117e main
1288.721593199: branches:u: bcx 401187 main => 40105e f
...
1288.722284747: branches:u: brx 401093 f => 401189 main
1288.722284747: branches:u: box 4011a4 main => 40117e main
1288.722284747: branches:u: bcx 401187 main => 40105e f
1288.722285883: transactions: bA 0 401071 f
1288.722285883: branches:u: bA 401071 f => 40116a main
1288.722285883: branches:u: bE 40116a main => 0 [unknown]
1288.722297174: branches:u: bB 0 [unknown] => 40116a main
...
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/1428594864-29309-26-git-send-email-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-09 23:54:05 +08:00
|
|
|
|
perf script: Add callindent option
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>
2016-06-23 21:40:58 +08:00
|
|
|
The callindent field is synthesized and may have a value when
|
|
|
|
Instruction Trace decoding. For calls and returns, it will display the
|
|
|
|
name of the symbol indented with spaces to reflect the stack depth.
|
|
|
|
|
2016-10-07 21:42:27 +08:00
|
|
|
When doing instruction trace decoding insn and insnlen give the
|
|
|
|
instruction bytes and the instruction length of the current
|
|
|
|
instruction.
|
|
|
|
|
2017-05-26 16:17:22 +08:00
|
|
|
The synth field is used by synthesized events which may be created when
|
|
|
|
Instruction Trace decoding.
|
|
|
|
|
perf script: Add output of IPC ratio
Add field 'ipc' to display instructions-per-cycle.
Example:
perf record -e intel_pt/cyc/u ls
perf script --insn-trace --xed -F+ipc,-dso,-cpu,-tid
ls 2670177.697113434: 7f0dfdbcd090 _start+0x0 mov %rsp, %rdi IPC: 0.00 (1/877)
ls 2670177.697113434: 7f0dfdbcd093 _start+0x3 callq 0x7f0dfdbce030
ls 2670177.697113434: 7f0dfdbce030 _dl_start+0x0 pushq %rbp
ls 2670177.697113434: 7f0dfdbce031 _dl_start+0x1 mov %rsp, %rbp
ls 2670177.697113434: 7f0dfdbce034 _dl_start+0x4 pushq %r15
ls 2670177.697113434: 7f0dfdbce036 _dl_start+0x6 pushq %r14
ls 2670177.697113434: 7f0dfdbce038 _dl_start+0x8 pushq %r13
ls 2670177.697113434: 7f0dfdbce03a _dl_start+0xa pushq %r12
ls 2670177.697113434: 7f0dfdbce03c _dl_start+0xc mov %rdi, %r12
ls 2670177.697113434: 7f0dfdbce03f _dl_start+0xf pushq %rbx
ls 2670177.697113434: 7f0dfdbce040 _dl_start+0x10 sub $0x38, %rsp
ls 2670177.697113434: 7f0dfdbce044 _dl_start+0x14 rdtsc
ls 2670177.697113434: 7f0dfdbce046 _dl_start+0x16 mov %eax, %eax
ls 2670177.697113434: 7f0dfdbce048 _dl_start+0x18 shl $0x20, %rdx
ls 2670177.697113434: 7f0dfdbce04c _dl_start+0x1c or %rax, %rdx
ls 2670177.697114471: 7f0dfdbce04f _dl_start+0x1f movq 0x27e22(%rip), %rax IPC: 0.00 (15/1685)
ls 2670177.697116177: 7f0dfdbce056 _dl_start+0x26 movq %rdx, 0x27683(%rip) IPC: 0.00 (1/881)
Note, the IPC values are low due to page faults at the beginning of
execution. The additional cycles are due to the time to enter the
kernel, not the actual kernel page fault handler.
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Link: http://lkml.kernel.org/r/20190520113728.14389-9-adrian.hunter@intel.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2019-05-20 19:37:14 +08:00
|
|
|
The ipc (instructions per cycle) field is synthesized and may have a value when
|
|
|
|
Instruction Trace decoding.
|
|
|
|
|
2011-03-31 02:30:43 +08:00
|
|
|
Finally, a user may not set fields to none for all event types.
|
2016-06-17 03:51:26 +08:00
|
|
|
i.e., -F "" is not allowed.
|
2011-03-31 02:30:43 +08:00
|
|
|
|
2015-09-01 00:41:13 +08:00
|
|
|
The brstack output includes branch related information with raw addresses using the
|
2017-02-24 07:46:34 +08:00
|
|
|
/v/v/v/v/cycles syntax in the following order:
|
2015-09-01 00:41:13 +08:00
|
|
|
FROM: branch source instruction
|
|
|
|
TO : branch target instruction
|
|
|
|
M/P/-: M=branch target mispredicted or branch direction was mispredicted, P=target predicted or direction predicted, -=not supported
|
|
|
|
X/- : X=branch inside a transactional region, -=not in transaction region or not supported
|
|
|
|
A/- : A=TSX abort entry, -=not aborted region or not supported
|
2017-02-24 07:46:34 +08:00
|
|
|
cycles
|
2015-09-01 00:41:13 +08:00
|
|
|
|
|
|
|
The brstacksym is identical to brstack, except that the FROM and TO addresses are printed in a symbolic form if possible.
|
|
|
|
|
2017-02-24 07:46:34 +08:00
|
|
|
When brstackinsn is specified the full assembler sequences of branch sequences for each sample
|
|
|
|
is printed. This is the full execution path leading to the sample. This is only supported when the
|
|
|
|
sample was recorded with perf record -b or -j any.
|
|
|
|
|
perf script: Support -F brstackoff,dso
The idea here is to make AutoFDO easier in cloud environment with ASLR.
It's easiest to show how this is useful by example. I built a small test
akin to "while(1) { do_nothing(); }" where the do_nothing function is
loaded from a dso:
$ cat burncpu.cpp
#include <dlfcn.h>
int main() {
void* handle = dlopen("./dso.so", RTLD_LAZY);
if (!handle) return -1;
typedef void (*fp)();
fp do_nothing = (fp) dlsym(handle, "do_nothing");
while(1) {
do_nothing();
}
}
$ cat dso.cpp
extern "C" void do_nothing() {}
$ cat build.sh
#!/bin/bash
g++ -shared dso.cpp -o dso.so
g++ burncpu.cpp -o burncpu -ldl
I sampled the execution of this program with perf record -b.
Using the existing "brstack,dso", we get absolute addresses that are
affected by ASLR, and could be different on different hosts. The address
does not uniquely identify a branch/target in the binary:
$ perf script -F brstack,dso | sed 's/\/0 /\/0\n/g' | grep burncpu | grep dso.so | head -n 1
0x7f967139b6aa(/tmp/burncpu/dso.so)/0x4006b1(/tmp/burncpu/exe)/P/-/-/0
Using the existing "brstacksym,dso" is a little better, because the
symbol plus offset and dso name *does* uniquely identify a branch/target
in the binary. Ultimately, however, AutoFDO wants a simple offset into
the binary, so we'd have to undo all the work perf did to symbolize in
the first place:
$ perf script -F brstacksym,dso | sed 's/\/0 /\/0\n/g' | grep burncpu | grep dso.so | head -n 1
do_nothing+0x5(/tmp/burncpu/dso.so)/main+0x44(/tmp/burncpu/exe)/P/-/-/0
With the new "brstackoff,dso" we get what we need: a simple offset into a
specific dso/binary that uniquely identifies a branch/target:
$ perf script -F brstackoff,dso | sed 's/\/0 /\/0\n/g' | grep burncpu | grep dso.so | head -n 1
0x6aa(/tmp/burncpu/dso.so)/0x4006b1(/tmp/burncpu/exe)/P/-/-/0
Signed-off-by: Mark Santaniello <marksan@fb.com>
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/20170619163825.2012979-2-marksan@fb.com
[ Updated documentation about 'brstackoff' using text from above ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2017-06-20 00:38:25 +08:00
|
|
|
The brstackoff field will print an offset into a specific dso/binary.
|
|
|
|
|
perf script: Allow computing 'perf stat' style metrics
Add support for computing 'perf stat' style metrics in 'perf script'.
When using leader sampling we can get metrics for each sampling period
by computing formulas over the values of the different group members.
This allows things like fine grained IPC tracking through sampling, much
more fine grained than with 'perf stat'.
The metric is still averaged over the sampling period, it is not just
for the sampling point.
This patch adds a new metric output field for 'perf script' that uses
the existing 'perf stat' metrics infrastructure to compute any metrics
supported by 'perf stat'.
For example to sample IPC:
$ perf record -e '{ref-cycles,cycles,instructions}:S' -a sleep 1
$ perf script -F metric,ip,sym,time,cpu,comm
...
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: metric: 0.13 insn per cycle
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: metric: 0.23 insn per cycle
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: metric: 0.46 insn per cycle
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: metric: 0.45 insn per cycle
TopDown:
This requires disabling SMT if you have it enabled, because SMT would
require sampling per core, which is not supported.
$ perf record -e '{ref-cycles,topdown-fetch-bubbles,\
topdown-recovery-bubbles,\
topdown-slots-retired,topdown-total-slots,\
topdown-slots-issued}:S' -a sleep 1
$ perf script --header -I -F cpu,ip,sym,event,metric,period
...
[000] 121108 ref-cycles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 190350 topdown-fetch-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 2055 topdown-recovery-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 148729 topdown-slots-retired: ffffffff8165222e copy_user_enhanced_fast_string
[000] 144324 topdown-total-slots: ffffffff8165222e copy_user_enhanced_fast_string
[000] 160852 topdown-slots-issued: ffffffff8165222e copy_user_enhanced_fast_string
[000] metric: 33.0% frontend bound
[000] metric: 3.5% bad speculation
[000] metric: 25.8% retiring
[000] metric: 37.7% backend bound
[000] 112112 ref-cycles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 357222 topdown-fetch-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 3325 topdown-recovery-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 323553 topdown-slots-retired: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 270507 topdown-total-slots: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 341226 topdown-slots-issued: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] metric: 33.0% frontend bound
[000] metric: 2.9% bad speculation
[000] metric: 29.9% retiring
[000] metric: 34.2% backend bound
...
v2:
Use evsel->priv for new fields
Port to new base line, support fp output.
Handle stats in ->stats, not ->priv
Minor cleanups
Extra explanation about the use of the term 'averaging', from Andi in the
thread in the Link: tag below:
<quote Andi>
The current samples contains the sum of event counts for a sampling period.
EventA-1 EventA-2 EventA-3 EventA-4
EventB-1 EventB-2 EventC-3
gap with no events overflow
|-----------------------------------------------------------------|
period-start period-end
^ ^
| |
previous sample current sample
So EventA = 4 and EventB = 3 at the sample point
I generate a metric, let's say EventA / EventB. It applies to the whole period.
But the metric is over a longer time which does not have the same behavior. For
example the gap above doesn't have any events, while they are clustered at the
beginning and end of the sample period.
But we're summing everything together. The metric doesn't know that the gap is
different than the busy period.
That's what I'm trying to express with averaging.
</quote>
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Link: http://lkml.kernel.org/r/20171117214300.32746-4-andi@firstfloor.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2017-11-18 05:43:00 +08:00
|
|
|
With the metric option perf script can compute metrics for
|
|
|
|
sampling periods, similar to perf stat. This requires
|
2019-07-12 02:19:22 +08:00
|
|
|
specifying a group with multiple events defining metrics with the :S option
|
perf script: Allow computing 'perf stat' style metrics
Add support for computing 'perf stat' style metrics in 'perf script'.
When using leader sampling we can get metrics for each sampling period
by computing formulas over the values of the different group members.
This allows things like fine grained IPC tracking through sampling, much
more fine grained than with 'perf stat'.
The metric is still averaged over the sampling period, it is not just
for the sampling point.
This patch adds a new metric output field for 'perf script' that uses
the existing 'perf stat' metrics infrastructure to compute any metrics
supported by 'perf stat'.
For example to sample IPC:
$ perf record -e '{ref-cycles,cycles,instructions}:S' -a sleep 1
$ perf script -F metric,ip,sym,time,cpu,comm
...
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: metric: 0.13 insn per cycle
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: metric: 0.23 insn per cycle
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: metric: 0.46 insn per cycle
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: metric: 0.45 insn per cycle
TopDown:
This requires disabling SMT if you have it enabled, because SMT would
require sampling per core, which is not supported.
$ perf record -e '{ref-cycles,topdown-fetch-bubbles,\
topdown-recovery-bubbles,\
topdown-slots-retired,topdown-total-slots,\
topdown-slots-issued}:S' -a sleep 1
$ perf script --header -I -F cpu,ip,sym,event,metric,period
...
[000] 121108 ref-cycles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 190350 topdown-fetch-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 2055 topdown-recovery-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 148729 topdown-slots-retired: ffffffff8165222e copy_user_enhanced_fast_string
[000] 144324 topdown-total-slots: ffffffff8165222e copy_user_enhanced_fast_string
[000] 160852 topdown-slots-issued: ffffffff8165222e copy_user_enhanced_fast_string
[000] metric: 33.0% frontend bound
[000] metric: 3.5% bad speculation
[000] metric: 25.8% retiring
[000] metric: 37.7% backend bound
[000] 112112 ref-cycles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 357222 topdown-fetch-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 3325 topdown-recovery-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 323553 topdown-slots-retired: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 270507 topdown-total-slots: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 341226 topdown-slots-issued: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] metric: 33.0% frontend bound
[000] metric: 2.9% bad speculation
[000] metric: 29.9% retiring
[000] metric: 34.2% backend bound
...
v2:
Use evsel->priv for new fields
Port to new base line, support fp output.
Handle stats in ->stats, not ->priv
Minor cleanups
Extra explanation about the use of the term 'averaging', from Andi in the
thread in the Link: tag below:
<quote Andi>
The current samples contains the sum of event counts for a sampling period.
EventA-1 EventA-2 EventA-3 EventA-4
EventB-1 EventB-2 EventC-3
gap with no events overflow
|-----------------------------------------------------------------|
period-start period-end
^ ^
| |
previous sample current sample
So EventA = 4 and EventB = 3 at the sample point
I generate a metric, let's say EventA / EventB. It applies to the whole period.
But the metric is over a longer time which does not have the same behavior. For
example the gap above doesn't have any events, while they are clustered at the
beginning and end of the sample period.
But we're summing everything together. The metric doesn't know that the gap is
different than the busy period.
That's what I'm trying to express with averaging.
</quote>
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Link: http://lkml.kernel.org/r/20171117214300.32746-4-andi@firstfloor.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2017-11-18 05:43:00 +08:00
|
|
|
for perf record. perf will sample on the first event, and
|
2019-07-12 02:19:22 +08:00
|
|
|
print computed metrics for all the events in the group. Please note
|
perf script: Allow computing 'perf stat' style metrics
Add support for computing 'perf stat' style metrics in 'perf script'.
When using leader sampling we can get metrics for each sampling period
by computing formulas over the values of the different group members.
This allows things like fine grained IPC tracking through sampling, much
more fine grained than with 'perf stat'.
The metric is still averaged over the sampling period, it is not just
for the sampling point.
This patch adds a new metric output field for 'perf script' that uses
the existing 'perf stat' metrics infrastructure to compute any metrics
supported by 'perf stat'.
For example to sample IPC:
$ perf record -e '{ref-cycles,cycles,instructions}:S' -a sleep 1
$ perf script -F metric,ip,sym,time,cpu,comm
...
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: metric: 0.13 insn per cycle
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: metric: 0.23 insn per cycle
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: metric: 0.46 insn per cycle
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: metric: 0.45 insn per cycle
TopDown:
This requires disabling SMT if you have it enabled, because SMT would
require sampling per core, which is not supported.
$ perf record -e '{ref-cycles,topdown-fetch-bubbles,\
topdown-recovery-bubbles,\
topdown-slots-retired,topdown-total-slots,\
topdown-slots-issued}:S' -a sleep 1
$ perf script --header -I -F cpu,ip,sym,event,metric,period
...
[000] 121108 ref-cycles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 190350 topdown-fetch-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 2055 topdown-recovery-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 148729 topdown-slots-retired: ffffffff8165222e copy_user_enhanced_fast_string
[000] 144324 topdown-total-slots: ffffffff8165222e copy_user_enhanced_fast_string
[000] 160852 topdown-slots-issued: ffffffff8165222e copy_user_enhanced_fast_string
[000] metric: 33.0% frontend bound
[000] metric: 3.5% bad speculation
[000] metric: 25.8% retiring
[000] metric: 37.7% backend bound
[000] 112112 ref-cycles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 357222 topdown-fetch-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 3325 topdown-recovery-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 323553 topdown-slots-retired: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 270507 topdown-total-slots: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 341226 topdown-slots-issued: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] metric: 33.0% frontend bound
[000] metric: 2.9% bad speculation
[000] metric: 29.9% retiring
[000] metric: 34.2% backend bound
...
v2:
Use evsel->priv for new fields
Port to new base line, support fp output.
Handle stats in ->stats, not ->priv
Minor cleanups
Extra explanation about the use of the term 'averaging', from Andi in the
thread in the Link: tag below:
<quote Andi>
The current samples contains the sum of event counts for a sampling period.
EventA-1 EventA-2 EventA-3 EventA-4
EventB-1 EventB-2 EventC-3
gap with no events overflow
|-----------------------------------------------------------------|
period-start period-end
^ ^
| |
previous sample current sample
So EventA = 4 and EventB = 3 at the sample point
I generate a metric, let's say EventA / EventB. It applies to the whole period.
But the metric is over a longer time which does not have the same behavior. For
example the gap above doesn't have any events, while they are clustered at the
beginning and end of the sample period.
But we're summing everything together. The metric doesn't know that the gap is
different than the busy period.
That's what I'm trying to express with averaging.
</quote>
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Link: http://lkml.kernel.org/r/20171117214300.32746-4-andi@firstfloor.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2017-11-18 05:43:00 +08:00
|
|
|
that the metric computed is averaged over the whole sampling
|
2019-07-12 02:19:22 +08:00
|
|
|
period (since the last sample), not just for the sample point.
|
perf script: Allow computing 'perf stat' style metrics
Add support for computing 'perf stat' style metrics in 'perf script'.
When using leader sampling we can get metrics for each sampling period
by computing formulas over the values of the different group members.
This allows things like fine grained IPC tracking through sampling, much
more fine grained than with 'perf stat'.
The metric is still averaged over the sampling period, it is not just
for the sampling point.
This patch adds a new metric output field for 'perf script' that uses
the existing 'perf stat' metrics infrastructure to compute any metrics
supported by 'perf stat'.
For example to sample IPC:
$ perf record -e '{ref-cycles,cycles,instructions}:S' -a sleep 1
$ perf script -F metric,ip,sym,time,cpu,comm
...
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: 7fd65937d6cc [unknown]
alsa-sink-ALC32 [000] 42815.856074: metric: 0.13 insn per cycle
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: ffffffff81655df0 __schedule
swapper [000] 42815.857961: metric: 0.23 insn per cycle
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: ffffffff8165ad0e _raw_spin_unlock_irqrestore
qemu-system-x86 [000] 42815.858130: metric: 0.46 insn per cycle
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: ffffffffa080e5f2 vmx_vcpu_run
:4972 [000] 42815.858312: metric: 0.45 insn per cycle
TopDown:
This requires disabling SMT if you have it enabled, because SMT would
require sampling per core, which is not supported.
$ perf record -e '{ref-cycles,topdown-fetch-bubbles,\
topdown-recovery-bubbles,\
topdown-slots-retired,topdown-total-slots,\
topdown-slots-issued}:S' -a sleep 1
$ perf script --header -I -F cpu,ip,sym,event,metric,period
...
[000] 121108 ref-cycles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 190350 topdown-fetch-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 2055 topdown-recovery-bubbles: ffffffff8165222e copy_user_enhanced_fast_string
[000] 148729 topdown-slots-retired: ffffffff8165222e copy_user_enhanced_fast_string
[000] 144324 topdown-total-slots: ffffffff8165222e copy_user_enhanced_fast_string
[000] 160852 topdown-slots-issued: ffffffff8165222e copy_user_enhanced_fast_string
[000] metric: 33.0% frontend bound
[000] metric: 3.5% bad speculation
[000] metric: 25.8% retiring
[000] metric: 37.7% backend bound
[000] 112112 ref-cycles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 357222 topdown-fetch-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 3325 topdown-recovery-bubbles: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 323553 topdown-slots-retired: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 270507 topdown-total-slots: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] 341226 topdown-slots-issued: ffffffff8165aec8 _raw_spin_lock_irqsave
[000] metric: 33.0% frontend bound
[000] metric: 2.9% bad speculation
[000] metric: 29.9% retiring
[000] metric: 34.2% backend bound
...
v2:
Use evsel->priv for new fields
Port to new base line, support fp output.
Handle stats in ->stats, not ->priv
Minor cleanups
Extra explanation about the use of the term 'averaging', from Andi in the
thread in the Link: tag below:
<quote Andi>
The current samples contains the sum of event counts for a sampling period.
EventA-1 EventA-2 EventA-3 EventA-4
EventB-1 EventB-2 EventC-3
gap with no events overflow
|-----------------------------------------------------------------|
period-start period-end
^ ^
| |
previous sample current sample
So EventA = 4 and EventB = 3 at the sample point
I generate a metric, let's say EventA / EventB. It applies to the whole period.
But the metric is over a longer time which does not have the same behavior. For
example the gap above doesn't have any events, while they are clustered at the
beginning and end of the sample period.
But we're summing everything together. The metric doesn't know that the gap is
different than the busy period.
That's what I'm trying to express with averaging.
</quote>
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Link: http://lkml.kernel.org/r/20171117214300.32746-4-andi@firstfloor.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2017-11-18 05:43:00 +08:00
|
|
|
|
2018-01-08 00:03:52 +08:00
|
|
|
For sample events it's possible to display misc field with -F +misc option,
|
|
|
|
following letters are displayed for each bit:
|
|
|
|
|
2018-04-09 15:26:46 +08:00
|
|
|
PERF_RECORD_MISC_KERNEL K
|
|
|
|
PERF_RECORD_MISC_USER U
|
|
|
|
PERF_RECORD_MISC_HYPERVISOR H
|
|
|
|
PERF_RECORD_MISC_GUEST_KERNEL G
|
|
|
|
PERF_RECORD_MISC_GUEST_USER g
|
|
|
|
PERF_RECORD_MISC_MMAP_DATA* M
|
|
|
|
PERF_RECORD_MISC_COMM_EXEC E
|
|
|
|
PERF_RECORD_MISC_SWITCH_OUT S
|
|
|
|
PERF_RECORD_MISC_SWITCH_OUT_PREEMPT Sp
|
2018-01-08 00:03:52 +08:00
|
|
|
|
|
|
|
$ perf script -F +misc ...
|
|
|
|
sched-messaging 1414 K 28690.636582: 4590 cycles ...
|
|
|
|
sched-messaging 1407 U 28690.636600: 325620 cycles ...
|
|
|
|
sched-messaging 1414 K 28690.636608: 19473 cycles ...
|
|
|
|
misc field ___________/
|
|
|
|
|
2011-03-10 13:23:27 +08:00
|
|
|
-k::
|
|
|
|
--vmlinux=<file>::
|
|
|
|
vmlinux pathname
|
|
|
|
|
|
|
|
--kallsyms=<file>::
|
|
|
|
kallsyms pathname
|
|
|
|
|
|
|
|
--symfs=<directory>::
|
|
|
|
Look for files with symbols relative to this directory.
|
|
|
|
|
|
|
|
-G::
|
|
|
|
--hide-call-graph::
|
|
|
|
When printing symbols do not display call chain.
|
perf script: Support custom field selection for output
Allow a user to select which fields to print to stdout for event data.
Options include comm (command name), tid (thread id), pid (process id),
time (perf timestamp), cpu, event (for event name), and trace (for
trace data).
Default is set to maintain compatibility with current output; this
feature does alter output format slightly -- no '-' between command
and pid/tid.
Thanks to Frederic Weisbecker for detailed suggestions on this approach.
Examples (output compressed)
1. trace, default format
perf record -ga -e sched:sched_switch
perf script
swapper 0 [000] 537.037184: sched_switch: prev_comm=swapper prev_pid=0...
sshd 1675 [000] 537.037309: sched_switch: prev_comm=sshd prev_pid=1675...
netstat 1692 [001] 537.038664: sched_switch: prev_comm=netstat prev_pid=1692...
2. trace, custom format
perf record -ga -e sched:sched_switch
perf script -f comm,pid,time,trace <--- omitting cpu and event name
swapper 0 537.037184: prev_comm=swapper prev_pid=0 prev_prio=120 ...
sshd 1675 537.037309: prev_comm=sshd prev_pid=1675 prev_prio=120 ...
netstat 1692 537.038664: prev_comm=netstat prev_pid=1692 prev_prio=120 ...
Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
LKML-Reference: <1299734608-5223-5-git-send-email-daahern@cisco.com>
Signed-off-by: David Ahern <daahern@cisco.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2011-03-10 13:23:26 +08:00
|
|
|
|
2016-11-26 04:00:21 +08:00
|
|
|
--stop-bt::
|
|
|
|
Stop display of callgraph at these symbols
|
|
|
|
|
2011-11-14 02:30:08 +08:00
|
|
|
-C::
|
2011-07-04 19:57:50 +08:00
|
|
|
--cpu:: Only report samples for the list of CPUs provided. Multiple CPUs can
|
|
|
|
be provided as a comma-separated list with no space: 0,1. Ranges of
|
|
|
|
CPUs are specified with -: 0-2. Default is to report samples on all
|
|
|
|
CPUs.
|
|
|
|
|
2011-11-22 01:02:52 +08:00
|
|
|
-c::
|
|
|
|
--comms=::
|
|
|
|
Only display events for these comms. CSV that understands
|
|
|
|
file://filename entries.
|
|
|
|
|
2015-03-24 23:52:41 +08:00
|
|
|
--pid=::
|
|
|
|
Only show events for given process ID (comma separated list).
|
|
|
|
|
|
|
|
--tid=::
|
|
|
|
Only show events for given thread ID (comma separated list).
|
|
|
|
|
perf tools: Make perf.data more self-descriptive (v8)
The goal of this patch is to include more information about the host
environment into the perf.data so it is more self-descriptive. Overtime,
profiles are captured on various machines and it becomes hard to track
what was recorded, on what machine and when.
This patch provides a way to solve this by extending the perf.data file
with basic information about the host machine. To add those extensions,
we leverage the feature bits capabilities of the perf.data format. The
change is backward compatible with existing perf.data files.
We define the following useful new extensions:
- HEADER_HOSTNAME: the hostname
- HEADER_OSRELEASE: the kernel release number
- HEADER_ARCH: the hw architecture
- HEADER_CPUDESC: generic CPU description
- HEADER_NRCPUS: number of online/avail cpus
- HEADER_CMDLINE: perf command line
- HEADER_VERSION: perf version
- HEADER_TOPOLOGY: cpu topology
- HEADER_EVENT_DESC: full event description (attrs)
- HEADER_CPUID: easy-to-parse low level CPU identication
The small granularity for the entries is to make it easier to extend
without breaking backward compatiblity. Many entries are provided as
ASCII strings.
Perf report/script have been modified to print the basic information as
easy-to-parse ASCII strings. Extended information about CPU and NUMA
topology may be requested with the -I option.
Thanks to David Ahern for reviewing and testing the many versions of
this patch.
$ perf report --stdio
# ========
# captured on : Mon Sep 26 15:22:14 2011
# hostname : quad
# os release : 3.1.0-rc4-tip
# perf version : 3.1.0-rc4
# arch : x86_64
# nrcpus online : 4
# nrcpus avail : 4
# cpudesc : Intel(R) Core(TM)2 Quad CPU Q6600 @ 2.40GHz
# cpuid : GenuineIntel,6,15,11
# total memory : 8105360 kB
# cmdline : /home/eranian/perfmon/official/tip/build/tools/perf/perf record date
# event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, id = { 29, 30, 31,
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# ========
#
...
$ perf report --stdio -I
# ========
# captured on : Mon Sep 26 15:22:14 2011
# hostname : quad
# os release : 3.1.0-rc4-tip
# perf version : 3.1.0-rc4
# arch : x86_64
# nrcpus online : 4
# nrcpus avail : 4
# cpudesc : Intel(R) Core(TM)2 Quad CPU Q6600 @ 2.40GHz
# cpuid : GenuineIntel,6,15,11
# total memory : 8105360 kB
# cmdline : /home/eranian/perfmon/official/tip/build/tools/perf/perf record date
# event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, id = { 29, 30, 31,
# sibling cores : 0-3
# sibling threads : 0
# sibling threads : 1
# sibling threads : 2
# sibling threads : 3
# node0 meminfo : total = 8320608 kB, free = 7571024 kB
# node0 cpu list : 0-3
# ========
#
...
Reviewed-by: David Ahern <dsahern@gmail.com>
Tested-by: David Ahern <dsahern@gmail.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Robert Richter <robert.richter@amd.com>
Cc: Andi Kleen <ak@linux.intel.com>
Link: http://lkml.kernel.org/r/20110930134040.GA5575@quad
Signed-off-by: Stephane Eranian <eranian@google.com>
[ committer notes: Use --show-info in the tools as was in the docs, rename
perf_header_fprintf_info to perf_file_section__fprintf_info, fixup
conflict with f69b64f7 "perf: Support setting the disassembler style" ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2011-09-30 21:40:40 +08:00
|
|
|
-I::
|
|
|
|
--show-info::
|
|
|
|
Display extended information about the perf.data file. This adds
|
|
|
|
information which may be very large and thus may clutter the display.
|
|
|
|
It currently includes: cpu and numa topology of the host system.
|
|
|
|
It can only be used with the perf script report mode.
|
|
|
|
|
2012-01-30 12:43:20 +08:00
|
|
|
--show-kernel-path::
|
|
|
|
Try to resolve the path of [kernel.kallsyms]
|
|
|
|
|
2013-11-26 16:51:12 +08:00
|
|
|
--show-task-events
|
|
|
|
Display task related events (e.g. FORK, COMM, EXIT).
|
|
|
|
|
2013-11-26 16:54:26 +08:00
|
|
|
--show-mmap-events
|
|
|
|
Display mmap related events (e.g. MMAP, MMAP2).
|
|
|
|
|
perf script: Add script print support for namespace events
Introduce a new option to display events of type PERF_RECORD_NAMESPACES
and update perf-script documentation accordingly.
Shown below is output (trimmed) of perf script command with the newly
introduced option, on perf.data generated with perf record command using
--namespaces option.
$ perf script --show-namespace-events
swapper 0 [000] 0.000000: PERF_RECORD_NAMESPACES 1/1 - nr_namespaces: 7
[0/net: 3/0xf000001c, 1/uts: 3/0xeffffffe, 2/ipc: 3/0xefffffff, 3/pid: 3/0xeffffffc,
4/user: 3/0xeffffffd, 5/mnt: 3/0xf0000000, 6/cgroup: 3/0xeffffffb]
swapper 0 [000] 0.000000: PERF_RECORD_NAMESPACES 2/2 - nr_namespaces: 7
[0/net: 3/0xf000001c, 1/uts: 3/0xeffffffe, 2/ipc: 3/0xefffffff, 3/pid: 3/0xeffffffc,
4/user: 3/0xeffffffd, 5/mnt: 3/0xf0000000, 6/cgroup: 3/0xeffffffb]
Commiter notes:
Testing it:
Investigating that double PERF_RECORD_NAMESPACES for the 19155
pid/tid... Its more than that, there are two PERF_RECORD_COMM as well,
and with zeroed timestamps, so probably a synthesizing artifact...
# perf script --show-task --show-namespace
<SNIP>
perf 0 [000] 0.000000: PERF_RECORD_COMM: perf:19154/19154
perf 0 [000] 0.000000: PERF_RECORD_FORK(19155:19155):(19154:19154)
perf 0 [000] 0.000000: PERF_RECORD_NAMESPACES 19155/19155 - nr_namespaces: 7
[0/net: 3/0xf0000081, 1/uts: 3/0xeffffffe, 2/ipc: 3/0xefffffff, 3/pid: 3/0xeffffffc,
4/user: 3/0xeffffffd, 5/mnt: 3/0xf0000000, 6/cgroup: 3/0xeffffffb]
perf 0 [000] 0.000000: PERF_RECORD_COMM: perf:19155/19155
perf 0 [000] 0.000000: PERF_RECORD_COMM: perf:19155/19155
perf 0 [000] 0.000000: PERF_RECORD_NAMESPACES 19155/19155 - nr_namespaces: 7
[0/net: 3/0xf0000081, 1/uts: 3/0xeffffffe, 2/ipc: 3/0xefffffff, 3/pid: 3/0xeffffffc,
4/user: 3/0xeffffffd, 5/mnt: 3/0xf0000000, 6/cgroup: 3/0xeffffffb]
swapper 0 [000] 3110.881834: 1 cycles: ffffffffa7060bf6 native_write_msr (/lib/modules/4.11.0-rc1+/build/vmlinux)
<SNIP>
Signed-off-by: Hari Bathini <hbathini@linux.vnet.ibm.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Alexei Starovoitov <ast@fb.com>
Cc: Ananth N Mavinakayanahalli <ananth@linux.vnet.ibm.com>
Cc: Aravinda Prasad <aravinda@linux.vnet.ibm.com>
Cc: Brendan Gregg <brendan.d.gregg@gmail.com>
Cc: Daniel Borkmann <daniel@iogearbox.net>
Cc: Eric Biederman <ebiederm@xmission.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Sargun Dhillon <sargun@sargun.me>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/148891932627.25309.1941587059154176221.stgit@hbathini.in.ibm.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2017-03-08 04:42:06 +08:00
|
|
|
--show-namespace-events
|
|
|
|
Display namespace events i.e. events of type PERF_RECORD_NAMESPACES.
|
|
|
|
|
2015-07-21 17:44:06 +08:00
|
|
|
--show-switch-events
|
|
|
|
Display context switch events i.e. events of type PERF_RECORD_SWITCH or
|
|
|
|
PERF_RECORD_SWITCH_CPU_WIDE.
|
|
|
|
|
2018-01-08 00:03:53 +08:00
|
|
|
--show-lost-events
|
|
|
|
Display lost events i.e. events of type PERF_RECORD_LOST.
|
|
|
|
|
2018-02-07 02:17:59 +08:00
|
|
|
--show-round-events
|
|
|
|
Display finished round events i.e. events of type PERF_RECORD_FINISHED_ROUND.
|
|
|
|
|
perf script: Add --show-bpf-events to show eBPF related events
Add the --show-bpf-events command line option to show the eBPF related events:
PERF_RECORD_KSYMBOL
PERF_RECORD_BPF_EVENT
Usage:
# perf record -a
...
# perf script --show-bpf-events
...
swapper 0 [000] 0.000000: PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc0ef971d len 229 type 1 flags 0x0 name bpf_prog_2a142ef67aaad174
swapper 0 [000] 0.000000: PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 36
...
Committer testing:
# perf script --show-bpf-events | egrep -i 'PERF_RECORD_(BPF|KSY)'
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc029a6c3 len 229 type 1 flags 0x0 name bpf_prog_7be49e3934a125ba
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 47
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc029c1ae len 229 type 1 flags 0x0 name bpf_prog_2a142ef67aaad174
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 48
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc02ddd1c len 229 type 1 flags 0x0 name bpf_prog_7be49e3934a125ba
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 49
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc02dfc11 len 229 type 1 flags 0x0 name bpf_prog_2a142ef67aaad174
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 50
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc045da0a len 229 type 1 flags 0x0 name bpf_prog_7be49e3934a125ba
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 51
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc04ef4b4 len 229 type 1 flags 0x0 name bpf_prog_2a142ef67aaad174
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 52
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc09e15da len 229 type 1 flags 0x0 name bpf_prog_7be49e3934a125ba
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 53
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc0d2b1a3 len 229 type 1 flags 0x0 name bpf_prog_2a142ef67aaad174
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 54
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc0fd9850 len 381 type 1 flags 0x0 name bpf_prog_819967866022f1e1_sys_enter
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 179
0 PERF_RECORD_KSYMBOL ksymbol event with addr ffffffffc0feb1ec len 191 type 1 flags 0x0 name bpf_prog_c1bd85c092d6e4aa_sys_exit
0 PERF_RECORD_BPF_EVENT bpf event with type 1, flags 0, id 180
^C[root@quaco pt]# perf evlist
intel_pt//ku
dummy:u
#
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
Acked-by: Song Liu <songliubraving@fb.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stanislav Fomichev <sdf@google.com>
Link: http://lkml.kernel.org/r/20190508132010.14512-11-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2019-05-08 21:20:08 +08:00
|
|
|
--show-bpf-events
|
|
|
|
Display bpf events i.e. events of type PERF_RECORD_KSYMBOL and PERF_RECORD_BPF_EVENT.
|
|
|
|
|
2020-03-25 20:45:36 +08:00
|
|
|
--show-cgroup-events
|
|
|
|
Display cgroup events i.e. events of type PERF_RECORD_CGROUP.
|
|
|
|
|
2020-05-12 20:19:21 +08:00
|
|
|
--show-text-poke-events
|
|
|
|
Display text poke events i.e. events of type PERF_RECORD_TEXT_POKE and
|
|
|
|
PERF_RECORD_KSYMBOL.
|
|
|
|
|
2015-08-27 03:18:15 +08:00
|
|
|
--demangle::
|
|
|
|
Demangle symbol names to human readable form. It's enabled by default,
|
|
|
|
disable with --no-demangle.
|
|
|
|
|
|
|
|
--demangle-kernel::
|
|
|
|
Demangle kernel symbol names to human readable form (for C++ kernels).
|
|
|
|
|
2013-12-09 18:02:50 +08:00
|
|
|
--header
|
|
|
|
Show perf.data header.
|
|
|
|
|
|
|
|
--header-only
|
|
|
|
Show only perf.data header.
|
|
|
|
|
2015-04-09 23:53:56 +08:00
|
|
|
--itrace::
|
|
|
|
Options for decoding instruction tracing data. The options are:
|
|
|
|
|
2015-07-18 00:33:44 +08:00
|
|
|
include::itrace.txt[]
|
2015-04-09 23:53:56 +08:00
|
|
|
|
|
|
|
To disable decoding entirely, use --no-itrace.
|
|
|
|
|
2015-08-08 06:24:05 +08:00
|
|
|
--full-source-path::
|
|
|
|
Show the full path for source files for srcline output.
|
|
|
|
|
2016-04-15 05:15:18 +08:00
|
|
|
--max-stack::
|
|
|
|
Set the stack depth limit when parsing the callchain, anything
|
|
|
|
beyond the specified depth will be ignored. This is a trade-off
|
|
|
|
between information loss and faster processing especially for
|
|
|
|
workloads that can have a very long callchain stack.
|
|
|
|
Note that when using the --itrace option the synthesized callchain size
|
|
|
|
will override this value if the synthesized callchain size is bigger.
|
|
|
|
|
2016-05-19 22:34:06 +08:00
|
|
|
Default: 127
|
2016-04-15 05:15:18 +08:00
|
|
|
|
2015-09-25 21:15:36 +08:00
|
|
|
--ns::
|
|
|
|
Use 9 decimal places when displaying time (i.e. show the nanoseconds)
|
|
|
|
|
2016-03-24 20:52:19 +08:00
|
|
|
-f::
|
|
|
|
--force::
|
|
|
|
Don't do ownership validation.
|
|
|
|
|
perf script: Add option to specify time window of interest
Add option to allow user to control analysis window. e.g., collect data
for some amount of time and analyze a segment of interest within that
window.
Committer notes:
Testing it:
# perf evlist -v
cycles:ppp: size: 112, { sample_period, sample_freq }: 4000, sample_type: IP|TID|TIME|CALLCHAIN|CPU|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1, freq: 1, task: 1, precise_ip: 3, sample_id_all: 1, exclude_guest: 1, mmap2: 1, comm_exec: 1
#
# perf script --hide-call-graph | head -15
swapper 0 [0] 9693.370039: 1 cycles:ppp: ffffffffb90072ad x86_pmu_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370044: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370046: 7 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370048: 126 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370049: 2701 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370051: 58823 cycles:ppp: ffffffffb90cd2e0 idle_cpu (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370059: 1 cycles:ppp: ffffffffb91a713a ctx_resched (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370062: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370064: 13 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370065: 250 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370067: 5269 cycles:ppp: ffffffffb902fe79 sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370069: 114602 cycles:ppp: ffffffffb90c1c5a atomic_notifier_call_chain (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370076: 1 cycles:ppp: ffffffffb91a76c1 __perf_event_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370091: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370095: 3 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
#
# perf script --hide-call-graph --time ,9693.370048
swapper 0 [0] 9693.370039: 1 cycles:ppp: ffffffffb90072ad x86_pmu_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370044: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370046: 7 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
# perf script --hide-call-graph --time 9693.370064,9693.370076
swapper 0 [1] 9693.370064: 13 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370065: 250 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370067: 5269 cycles:ppp: ffffffffb902fe79 sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370069: 114602 cycles:ppp: ffffffffb90c1c5a atomic_notifier_call_chain (.../4.8.8-300.fc25.x86_64/vmlinux)
#
Signed-off-by: David Ahern <dsahern@gmail.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Namhyung Kim <namhyung@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1480439746-42695-4-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2016-11-30 01:15:43 +08:00
|
|
|
--time::
|
|
|
|
Only analyze samples within given time window: <start>,<stop>. Times
|
2019-06-04 21:00:13 +08:00
|
|
|
have the format seconds.nanoseconds. If start is not given (i.e. time
|
perf script: Add option to specify time window of interest
Add option to allow user to control analysis window. e.g., collect data
for some amount of time and analyze a segment of interest within that
window.
Committer notes:
Testing it:
# perf evlist -v
cycles:ppp: size: 112, { sample_period, sample_freq }: 4000, sample_type: IP|TID|TIME|CALLCHAIN|CPU|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1, freq: 1, task: 1, precise_ip: 3, sample_id_all: 1, exclude_guest: 1, mmap2: 1, comm_exec: 1
#
# perf script --hide-call-graph | head -15
swapper 0 [0] 9693.370039: 1 cycles:ppp: ffffffffb90072ad x86_pmu_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370044: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370046: 7 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370048: 126 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370049: 2701 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370051: 58823 cycles:ppp: ffffffffb90cd2e0 idle_cpu (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370059: 1 cycles:ppp: ffffffffb91a713a ctx_resched (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370062: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370064: 13 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370065: 250 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370067: 5269 cycles:ppp: ffffffffb902fe79 sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370069: 114602 cycles:ppp: ffffffffb90c1c5a atomic_notifier_call_chain (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370076: 1 cycles:ppp: ffffffffb91a76c1 __perf_event_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370091: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370095: 3 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
#
# perf script --hide-call-graph --time ,9693.370048
swapper 0 [0] 9693.370039: 1 cycles:ppp: ffffffffb90072ad x86_pmu_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370044: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370046: 7 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
# perf script --hide-call-graph --time 9693.370064,9693.370076
swapper 0 [1] 9693.370064: 13 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370065: 250 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370067: 5269 cycles:ppp: ffffffffb902fe79 sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370069: 114602 cycles:ppp: ffffffffb90c1c5a atomic_notifier_call_chain (.../4.8.8-300.fc25.x86_64/vmlinux)
#
Signed-off-by: David Ahern <dsahern@gmail.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Namhyung Kim <namhyung@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1480439746-42695-4-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2016-11-30 01:15:43 +08:00
|
|
|
string is ',x.y') then analysis starts at the beginning of the file. If
|
2019-06-04 21:00:13 +08:00
|
|
|
stop time is not given (i.e. time string is 'x.y,') then analysis goes
|
2019-06-04 21:00:17 +08:00
|
|
|
to end of file. Multiple ranges can be separated by spaces, which
|
|
|
|
requires the argument to be quoted e.g. --time "1234.567,1234.789 1235,"
|
perf script: Add option to specify time window of interest
Add option to allow user to control analysis window. e.g., collect data
for some amount of time and analyze a segment of interest within that
window.
Committer notes:
Testing it:
# perf evlist -v
cycles:ppp: size: 112, { sample_period, sample_freq }: 4000, sample_type: IP|TID|TIME|CALLCHAIN|CPU|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1, freq: 1, task: 1, precise_ip: 3, sample_id_all: 1, exclude_guest: 1, mmap2: 1, comm_exec: 1
#
# perf script --hide-call-graph | head -15
swapper 0 [0] 9693.370039: 1 cycles:ppp: ffffffffb90072ad x86_pmu_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370044: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370046: 7 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370048: 126 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370049: 2701 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370051: 58823 cycles:ppp: ffffffffb90cd2e0 idle_cpu (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370059: 1 cycles:ppp: ffffffffb91a713a ctx_resched (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370062: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370064: 13 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370065: 250 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370067: 5269 cycles:ppp: ffffffffb902fe79 sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370069: 114602 cycles:ppp: ffffffffb90c1c5a atomic_notifier_call_chain (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370076: 1 cycles:ppp: ffffffffb91a76c1 __perf_event_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370091: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
perf 5124 [2] 9693.370095: 3 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
#
# perf script --hide-call-graph --time ,9693.370048
swapper 0 [0] 9693.370039: 1 cycles:ppp: ffffffffb90072ad x86_pmu_enable (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370044: 1 cycles:ppp: ffffffffb900ca1b intel_pmu_handle_irq (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [0] 9693.370046: 7 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
# perf script --hide-call-graph --time 9693.370064,9693.370076
swapper 0 [1] 9693.370064: 13 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370065: 250 cycles:ppp: ffffffffb902fd93 native_sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370067: 5269 cycles:ppp: ffffffffb902fe79 sched_clock (.../4.8.8-300.fc25.x86_64/vmlinux)
swapper 0 [1] 9693.370069: 114602 cycles:ppp: ffffffffb90c1c5a atomic_notifier_call_chain (.../4.8.8-300.fc25.x86_64/vmlinux)
#
Signed-off-by: David Ahern <dsahern@gmail.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Namhyung Kim <namhyung@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1480439746-42695-4-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2016-11-30 01:15:43 +08:00
|
|
|
|
2019-06-04 21:00:13 +08:00
|
|
|
Also support time percent with multiple time ranges. Time string is
|
perf script: Remove the time slices number limitation
Previously it was only allowed to use at most 10 time slices in 'perf
script --time'.
This patch removes this limitation.
For example, following command line is OK (12 time slices)
perf script --time 1%/1,1%/2,1%/3,1%/4,1%/5,1%/6,1%/7,1%/8,1%/9,1%/10,1%/11,1%/12
Signed-off-by: Jin Yao <yao.jin@linux.intel.com>
Suggested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Reviewed-by: Jiri Olsa <jolsa@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Kan Liang <kan.liang@intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1515596433-24653-9-git-send-email-yao.jin@linux.intel.com
[ No need to check for NULL to call free, use zfree ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2018-01-10 23:00:33 +08:00
|
|
|
'a%/n,b%/m,...' or 'a%-b%,c%-%d,...'.
|
2017-12-08 21:13:46 +08:00
|
|
|
|
|
|
|
For example:
|
perf script: Remove the time slices number limitation
Previously it was only allowed to use at most 10 time slices in 'perf
script --time'.
This patch removes this limitation.
For example, following command line is OK (12 time slices)
perf script --time 1%/1,1%/2,1%/3,1%/4,1%/5,1%/6,1%/7,1%/8,1%/9,1%/10,1%/11,1%/12
Signed-off-by: Jin Yao <yao.jin@linux.intel.com>
Suggested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Reviewed-by: Jiri Olsa <jolsa@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Kan Liang <kan.liang@intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1515596433-24653-9-git-send-email-yao.jin@linux.intel.com
[ No need to check for NULL to call free, use zfree ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2018-01-10 23:00:33 +08:00
|
|
|
Select the second 10% time slice:
|
2017-12-08 21:13:46 +08:00
|
|
|
perf script --time 10%/2
|
|
|
|
|
perf script: Remove the time slices number limitation
Previously it was only allowed to use at most 10 time slices in 'perf
script --time'.
This patch removes this limitation.
For example, following command line is OK (12 time slices)
perf script --time 1%/1,1%/2,1%/3,1%/4,1%/5,1%/6,1%/7,1%/8,1%/9,1%/10,1%/11,1%/12
Signed-off-by: Jin Yao <yao.jin@linux.intel.com>
Suggested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Reviewed-by: Jiri Olsa <jolsa@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Kan Liang <kan.liang@intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1515596433-24653-9-git-send-email-yao.jin@linux.intel.com
[ No need to check for NULL to call free, use zfree ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2018-01-10 23:00:33 +08:00
|
|
|
Select from 0% to 10% time slice:
|
2017-12-08 21:13:46 +08:00
|
|
|
perf script --time 0%-10%
|
|
|
|
|
perf script: Remove the time slices number limitation
Previously it was only allowed to use at most 10 time slices in 'perf
script --time'.
This patch removes this limitation.
For example, following command line is OK (12 time slices)
perf script --time 1%/1,1%/2,1%/3,1%/4,1%/5,1%/6,1%/7,1%/8,1%/9,1%/10,1%/11,1%/12
Signed-off-by: Jin Yao <yao.jin@linux.intel.com>
Suggested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Reviewed-by: Jiri Olsa <jolsa@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Kan Liang <kan.liang@intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1515596433-24653-9-git-send-email-yao.jin@linux.intel.com
[ No need to check for NULL to call free, use zfree ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2018-01-10 23:00:33 +08:00
|
|
|
Select the first and second 10% time slices:
|
2017-12-08 21:13:46 +08:00
|
|
|
perf script --time 10%/1,10%/2
|
|
|
|
|
perf script: Remove the time slices number limitation
Previously it was only allowed to use at most 10 time slices in 'perf
script --time'.
This patch removes this limitation.
For example, following command line is OK (12 time slices)
perf script --time 1%/1,1%/2,1%/3,1%/4,1%/5,1%/6,1%/7,1%/8,1%/9,1%/10,1%/11,1%/12
Signed-off-by: Jin Yao <yao.jin@linux.intel.com>
Suggested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Reviewed-by: Jiri Olsa <jolsa@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Kan Liang <kan.liang@intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1515596433-24653-9-git-send-email-yao.jin@linux.intel.com
[ No need to check for NULL to call free, use zfree ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2018-01-10 23:00:33 +08:00
|
|
|
Select from 0% to 10% and 30% to 40% slices:
|
2017-12-08 21:13:46 +08:00
|
|
|
perf script --time 0%-10%,30%-40%
|
|
|
|
|
2017-02-24 07:46:34 +08:00
|
|
|
--max-blocks::
|
2019-07-12 02:19:20 +08:00
|
|
|
Set the maximum number of program blocks to print with brstackinsn for
|
2017-02-24 07:46:34 +08:00
|
|
|
each sample.
|
|
|
|
|
2019-03-15 06:50:00 +08:00
|
|
|
--reltime::
|
|
|
|
Print time stamps relative to trace start.
|
|
|
|
|
perf script: Introduce --deltatime option
For some kind of analysis a deltatime output is more human friendly and
reduce the cognitive load for further analysis.
The following output demonstrate the new option "deltatime": calculate
the time difference in relation to the previous event.
$ perf script --deltatime
test 2525 [001] 0.000000: sdt_libev:ev_add: (5635e72a5ebd)
test 2525 [001] 0.000091: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 1.000051: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000685: sdt_libev:ev_add: (5635e72a5ebd)
test 2525 [001] 0.000048: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 1.000104: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.003895: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 0.996034: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000058: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 1.000004: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000064: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 0.999934: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000056: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 0.999930: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
Committer testing:
So go from default output to --reltime and then this new --deltatime, to
contrast the various timestamp presentation modes for a random perf.data file I
had laying around:
[root@five ~]# perf script --reltime | head
perf 442394 [000] 0.000000: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000002: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000004: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000006: 128 cycles: ffffffff972415a1 perf_event_update_userpage+0x1 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000009: 2597 cycles: ffffffff97463785 cap_task_setscheduler+0x5 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000036: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000038: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000040: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000041: 224 cycles: ffffffff9700a53a perf_ibs_handle_irq+0x1da (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000044: 4439 cycles: ffffffff97120d85 put_prev_entity+0x45 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
[root@five ~]# perf script --deltatime | head
perf 442394 [000] 0.000000: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000002: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000001: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000001: 128 cycles: ffffffff972415a1 perf_event_update_userpage+0x1 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000002: 2597 cycles: ffffffff97463785 cap_task_setscheduler+0x5 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000027: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000002: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000001: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000001: 224 cycles: ffffffff9700a53a perf_ibs_handle_irq+0x1da (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000002: 4439 cycles: ffffffff97120d85 put_prev_entity+0x45 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
[root@five ~]# perf script | head
perf 442394 [000] 7600.157861: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157864: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157866: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157867: 128 cycles: ffffffff972415a1 perf_event_update_userpage+0x1 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157870: 2597 cycles: ffffffff97463785 cap_task_setscheduler+0x5 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157897: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157900: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157901: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157903: 224 cycles: ffffffff9700a53a perf_ibs_handle_irq+0x1da (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157906: 4439 cycles: ffffffff97120d85 put_prev_entity+0x45 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
[root@five ~]#
Andi suggested we better implement it as a new field, i.e. -F deltatime, like:
[root@five ~]# perf script -F deltatime
Invalid field requested.
Usage: perf script [<options>]
or: perf script [<options>] record <script> [<record-options>] <command>
or: perf script [<options>] report <script> [script-args]
or: perf script [<options>] <script> [<record-options>] <command>
or: perf script [<options>] <top-script> [script-args]
-F, --fields <str> comma separated output fields prepend with 'type:'. +field to add and -field to remove.Valid types: hw,sw,trace,raw,synth. Fields: comm,tid,pid,time,cpu,event,trace,ip,sym,dso,addr,symoff,srcline,period,iregs,uregs,brstack,brstacksym,flags,bpf-output,brstackinsn,brstackoff,callindent,insn,insnlen,synth,phys_addr,metric,misc,ipc
[root@five ~]#
I.e. we have -F for maximum flexibility:
[root@five ~]# perf script -F comm,pid,cpu,time | head
perf 442394 [000] 7600.157861:
perf 442394 [000] 7600.157864:
perf 442394 [000] 7600.157866:
perf 442394 [000] 7600.157867:
perf 442394 [000] 7600.157870:
perf 442394 [001] 7600.157897:
perf 442394 [001] 7600.157900:
perf 442394 [001] 7600.157901:
perf 442394 [001] 7600.157903:
perf 442394 [001] 7600.157906:
[root@five ~]#
But since we already have --reltime, having --deltatime, documented one after
the other is sensible.
Signed-off-by: Hagen Paul Pfeifer <hagen@jauu.net>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Link: http://lore.kernel.org/lkml/20200204173709.489161-1-hagen@jauu.net
[ Added 'perf script' man page entry for --deltatime ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2020-02-05 01:37:09 +08:00
|
|
|
--deltatime::
|
|
|
|
Print time stamps relative to previous event.
|
|
|
|
|
2017-10-26 21:30:20 +08:00
|
|
|
--per-event-dump::
|
|
|
|
Create per event files with a "perf.data.EVENT.dump" name instead of
|
|
|
|
printing to stdout, useful, for instance, for generating flamegraphs.
|
|
|
|
|
perf script: Add --inline option for debugging
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<std::linear_congruential_engine<unsigned long, 16807ul, 0ul, 2147483647ul>, double>::operator()
std::uniform_real_distribution<double>::operator()<std::linear_congruential_engine<unsigned long, 16807ul, 0ul, 2147483647ul> >
std::uniform_real_distribution<double>::operator()<std::linear_congruential_engine<unsigned long, 16807ul, 0ul, 2147483647ul> >
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 <milian.wolff@kdab.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jin Yao <yao.jin@linux.intel.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Milian Wolff <milian.wolff@kdab.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-5-namhyung@kernel.org
Signed-off-by: Ingo Molnar <mingo@kernel.org>
2017-05-24 14:21:26 +08:00
|
|
|
--inline::
|
|
|
|
If a callgraph address belongs to an inlined function, the inline stack
|
2017-10-19 19:38:36 +08:00
|
|
|
will be printed. Each entry has function name and file/line. Enabled by
|
|
|
|
default, disable with --no-inline.
|
perf script: Add --inline option for debugging
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<std::linear_congruential_engine<unsigned long, 16807ul, 0ul, 2147483647ul>, double>::operator()
std::uniform_real_distribution<double>::operator()<std::linear_congruential_engine<unsigned long, 16807ul, 0ul, 2147483647ul> >
std::uniform_real_distribution<double>::operator()<std::linear_congruential_engine<unsigned long, 16807ul, 0ul, 2147483647ul> >
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 <milian.wolff@kdab.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jin Yao <yao.jin@linux.intel.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Milian Wolff <milian.wolff@kdab.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: kernel-team@lge.com
Link: http://lkml.kernel.org/r/20170524062129.32529-5-namhyung@kernel.org
Signed-off-by: Ingo Molnar <mingo@kernel.org>
2017-05-24 14:21:26 +08:00
|
|
|
|
perf script: Add --insn-trace for instruction decoding
Add a --insn-trace short hand option for decoding and disassembling
instruction streams for intel_pt. This automatically pipes the output
into the xed disassembler to generate disassembled instructions. This
just makes this use model much nicer to use.
Before
% perf record -e intel_pt// ...
% perf script --itrace=i0ns --ns -F +insn,-event,-period | xed -F insn: -A -64
swapper 0 [000] 17276.429606186: ffffffff81010486 pt_config ([kernel.kallsyms]) nopl %eax, (%rax,%rax,1)
swapper 0 [000] 17276.429606186: ffffffff8101048b pt_config ([kernel.kallsyms]) add $0x10, %rsp
swapper 0 [000] 17276.429606186: ffffffff8101048f pt_config ([kernel.kallsyms]) popq %rbx
swapper 0 [000] 17276.429606186: ffffffff81010490 pt_config ([kernel.kallsyms]) popq %rbp
swapper 0 [000] 17276.429606186: ffffffff81010491 pt_config ([kernel.kallsyms]) popq %r12
swapper 0 [000] 17276.429606186: ffffffff81010493 pt_config ([kernel.kallsyms]) popq %r13
swapper 0 [000] 17276.429606186: ffffffff81010495 pt_config ([kernel.kallsyms]) popq %r14
swapper 0 [000] 17276.429606186: ffffffff81010497 pt_config ([kernel.kallsyms]) popq %r15
swapper 0 [000] 17276.429606186: ffffffff81010499 pt_config ([kernel.kallsyms]) retq
swapper 0 [000] 17276.429606186: ffffffff8101063e pt_event_add ([kernel.kallsyms]) cmpl $0x1, 0x1b0(%rbx)
swapper 0 [000] 17276.429606186: ffffffff81010645 pt_event_add ([kernel.kallsyms]) mov $0xffffffea, %eax
swapper 0 [000] 17276.429606186: ffffffff8101064a pt_event_add ([kernel.kallsyms]) mov $0x0, %edx
swapper 0 [000] 17276.429606186: ffffffff8101064f pt_event_add ([kernel.kallsyms]) popq %rbx
swapper 0 [000] 17276.429606186: ffffffff81010650 pt_event_add ([kernel.kallsyms]) cmovnz %edx, %eax
swapper 0 [000] 17276.429606186: ffffffff81010653 pt_event_add ([kernel.kallsyms]) jmp 0xffffffff81010635
swapper 0 [000] 17276.429606186: ffffffff81010635 pt_event_add ([kernel.kallsyms]) retq
swapper 0 [000] 17276.429606186: ffffffff8115e687 event_sched_in.isra.107 ([kernel.kallsyms]) test %eax, %eax
Now:
% perf record -e intel_pt// ...
% perf script --insn-trace --xed
... same output ...
XED needs to be installed with:
$ git clone https://github.com/intelxed/mbuild.git mbuild
$ git clone https://github.com/intelxed/xed
$ cd xed
$ ./mfile.py
$ ./mfile.py examples
$ sudo ./mfile.py --prefix=/usr/local install
$ sudo cp obj/examples/xed /usr/local/bin
$ xed | head -3
ERROR: required argument(s) were missing
Copyright (C) 2017, Intel Corporation. All rights reserved.
XED version: [v10.0-328-g7d62c8c49b7b]
$
Signed-off-by: Andi Kleen <ak@linux.intel.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Link: http://lkml.kernel.org/r/20180920180540.14039-2-andi@firstfloor.org
[ Fixed up whitespace damage, added the 'mfile.py examples + cp obj/examples/xed ... ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2018-09-21 02:05:36 +08:00
|
|
|
--insn-trace::
|
|
|
|
Show instruction stream for intel_pt traces. Combine with --xed to
|
|
|
|
show disassembly.
|
|
|
|
|
|
|
|
--xed::
|
|
|
|
Run xed disassembler on output. Requires installing the xed disassembler.
|
|
|
|
|
2020-04-03 01:41:30 +08:00
|
|
|
-S::
|
|
|
|
--symbols=symbol[,symbol...]::
|
|
|
|
Only consider the listed symbols. Symbols are typically a name
|
|
|
|
but they may also be hexadecimal address.
|
|
|
|
|
2021-02-07 16:09:35 +08:00
|
|
|
The hexadecimal address may be the start address of a symbol or
|
|
|
|
any other address to filter the trace records
|
|
|
|
|
2020-04-03 01:41:30 +08:00
|
|
|
For example, to select the symbol noploop or the address 0x4007a0:
|
|
|
|
perf script --symbols=noploop,0x4007a0
|
|
|
|
|
2021-02-07 16:09:35 +08:00
|
|
|
Support filtering trace records by symbol name, start address of
|
|
|
|
symbol, any hexadecimal address and address range.
|
|
|
|
|
|
|
|
The comparison order is:
|
|
|
|
|
|
|
|
1. symbol name comparison
|
|
|
|
2. symbol start address comparison.
|
|
|
|
3. any hexadecimal address comparison.
|
|
|
|
4. address range comparison (see --addr-range).
|
|
|
|
|
|
|
|
--addr-range::
|
|
|
|
Use with -S or --symbols to list traced records within address range.
|
|
|
|
|
|
|
|
For example, to list the traced records within the address range
|
|
|
|
[0x4007a0, 0x0x4007a9]:
|
|
|
|
perf script -S 0x4007a0 --addr-range 10
|
|
|
|
|
2021-01-25 07:27:50 +08:00
|
|
|
--dsos=::
|
|
|
|
Only consider symbols in these DSOs.
|
|
|
|
|
2018-09-21 02:05:38 +08:00
|
|
|
--call-trace::
|
|
|
|
Show call stream for intel_pt traces. The CPUs are interleaved, but
|
|
|
|
can be filtered with -C.
|
|
|
|
|
|
|
|
--call-ret-trace::
|
|
|
|
Show call and return stream for intel_pt traces.
|
|
|
|
|
2018-09-21 02:05:39 +08:00
|
|
|
--graph-function::
|
|
|
|
For itrace only show specified functions and their callees for
|
|
|
|
itrace. Multiple functions can be separated by comma.
|
|
|
|
|
2019-08-15 03:20:13 +08:00
|
|
|
--switch-on EVENT_NAME::
|
|
|
|
Only consider events after this event is found.
|
|
|
|
|
2019-08-15 03:51:28 +08:00
|
|
|
--switch-off EVENT_NAME::
|
|
|
|
Stop considering events after this event is found.
|
|
|
|
|
2019-08-15 03:40:58 +08:00
|
|
|
--show-on-off-events::
|
2019-08-15 03:51:28 +08:00
|
|
|
Show the --switch-on/off events too.
|
2019-08-15 03:40:58 +08:00
|
|
|
|
2020-03-20 04:25:14 +08:00
|
|
|
--stitch-lbr::
|
|
|
|
Show callgraph with stitched LBRs, which may have more complete
|
|
|
|
callgraph. The perf.data file must have been obtained using
|
|
|
|
perf record --call-graph lbr.
|
|
|
|
Disabled by default. In common cases with call stack overflows,
|
|
|
|
it can recreate better call stacks than the default lbr call stack
|
|
|
|
output. But this approach is not full proof. There can be cases
|
|
|
|
where it creates incorrect call stacks from incorrect matches.
|
|
|
|
The known limitations include exception handing such as
|
|
|
|
setjmp/longjmp will have calls/returns not match.
|
|
|
|
|
2009-09-11 18:12:54 +08:00
|
|
|
SEE ALSO
|
|
|
|
--------
|
2010-11-17 01:45:39 +08:00
|
|
|
linkperf:perf-record[1], linkperf:perf-script-perl[1],
|
2021-06-27 21:18:09 +08:00
|
|
|
linkperf:perf-script-python[1], linkperf:perf-intel-pt[1],
|
|
|
|
linkperf:perf-dlfilter[1]
|