linux/tools/perf/builtin-script.c, branch v4.20

perf script: Support total cycles count

2018-10-24T18:29:56Z

For 'perf script' brstackinsn also print a running cycles count. This makes it easier to calculate cycle deltas for code sections measured with LBRs. % perf record -b -a sleep 1 % perf script -F +brstackinsn ... 00007f73ecc41083 insn: 74 06 # PRED 9 cycles [17] 1.11 IPC 00007f73ecc4108b insn: a8 10 00007f73ecc4108d insn: 74 71 # PRED 1 cycles [18] 1.00 IPC 00007f73ecc41100 insn: 48 8b 46 10 00007f73ecc41104 insn: 4c 8b 38 00007f73ecc41107 insn: 4d 85 ff 00007f73ecc4110a insn: 0f 84 b0 00 00 00 00007f73ecc41110 insn: 83 43 58 01 00007f73ecc41114 insn: 48 89 df 00007f73ecc41117 insn: e8 94 73 04 00 # PRED 6 cycles [24] 1.00 IPC Signed-off-by: Andi Kleen Acked-by: Jiri Olsa Cc: Andi Kleen Link: http://lkml.kernel.org/r/20180924170732.GA28040@tassilo.jf.intel.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Implement --graph-function

2018-10-24T18:29:55Z

Add a ftrace style --graph-function argument to 'perf script' that allows to print itrace function calls only below a given function. This makes it easier to find the code of interest in a large trace. % perf record -e intel_pt//k -a sleep 1 % perf script --graph-function group_sched_in --call-trace perf 900 [000] 194167.205652203: ([kernel.kallsyms]) group_sched_in perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: ([kernel.kallsyms]) event_sched_in.isra.107 perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_event_set_state.part.71 perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_event_update_time perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_pmu_disable perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_log_itrace_start perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_event_update_userpage perf 900 [000] 194167.205652203: ([kernel.kallsyms]) calc_timer_values perf 900 [000] 194167.205652203: ([kernel.kallsyms]) sched_clock_cpu perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: ([kernel.kallsyms]) arch_perf_update_userpage perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __fentry__ perf 900 [000] 194167.205652203: ([kernel.kallsyms]) using_native_sched_clock perf 900 [000] 194167.205652203: ([kernel.kallsyms]) sched_clock_stable perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_pmu_enable perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __x86_indirect_thunk_rax swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) group_sched_in swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) __x86_indirect_thunk_rax swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) event_sched_in.isra.107 swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) perf_event_set_state.part.71 swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) perf_event_update_time swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) perf_pmu_disable swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) perf_log_itrace_start swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) __x86_indirect_thunk_rax swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) perf_event_update_userpage swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) calc_timer_values swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) sched_clock_cpu swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) __x86_indirect_thunk_rax swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) arch_perf_update_userpage swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) __fentry__ swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) using_native_sched_clock swapper 0 [001] 194167.205660693: ([kernel.kallsyms]) sched_clock_stable Signed-off-by: Andi Kleen Tested-by: Arnaldo Carvalho de Melo Tested-by: Leo Yan Acked-by: Jiri Olsa Cc: Kim Phillips Link: http://lkml.kernel.org/r/20180920180540.14039-5-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

tools script: Add --call-trace and --call-ret-trace

2018-10-24T18:29:55Z

Add short cut options to print PT call trace and call-ret-trace, for calls and call and returns. Roughly corresponds to ftrace function tracer and function graph tracer. Just makes these common use cases nicer to use. % perf record -a -e intel_pt// sleep 1 % perf script --call-trace perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_pmu_enable perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: ([kernel.kallsyms]) event_filter_match perf 900 [000] 194167.205652203: ([kernel.kallsyms]) group_sched_in perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: ([kernel.kallsyms]) event_sched_in.isra.107 perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_event_set_state.part.71 perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_event_update_time perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_pmu_disable perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_log_itrace_start perf 900 [000] 194167.205652203: ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: ([kernel.kallsyms]) perf_event_update_userpage % perf script --call-ret-trace perf 900 [000] 194167.205652203: tr strt ([unknown]) pt_config perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) pt_config perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) pt_event_add perf 900 [000] 194167.205652203: call ([kernel.kallsyms]) perf_pmu_enable perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) perf_pmu_nop_void perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) event_sched_in.isra.107 perf 900 [000] 194167.205652203: call ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) perf_pmu_nop_int perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) group_sched_in perf 900 [000] 194167.205652203: call ([kernel.kallsyms]) event_filter_match perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) event_filter_match perf 900 [000] 194167.205652203: call ([kernel.kallsyms]) group_sched_in perf 900 [000] 194167.205652203: call ([kernel.kallsyms]) __x86_indirect_thunk_rax perf 900 [000] 194167.205652203: return ([kernel.kallsyms]) perf_pmu_nop_txn perf 900 [000] 194167.205652203: call ([kernel.kallsyms]) event_sched_in.isra.107 perf 900 [000] 194167.205652203: call ([kernel.kallsyms]) perf_event_set_state.part.71 Signed-off-by: Andi Kleen Tested-by: Arnaldo Carvalho de Melo Tested-by: Leo Yan Acked-by: Jiri Olsa Cc: Kim Phillips Link: http://lkml.kernel.org/r/20180920180540.14039-4-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Make itrace script default to all calls

2018-10-24T18:29:54Z

By default 'perf script' for itrace outputs sampled instructions or branches. In my experience this is confusing to users because it's hard to correlate with real program behavior. The sampling makes sense for tools like 'perf report' that actually sample to reduce the run time, but run time is normally not a problem for 'perf script'. It's better to give an accurate representation of the program flow. Default 'perf script' to output all calls for itrace. That's a much saner default. The old behavior can be still requested with 'perf script' --itrace=ibxwpe100000 v2: Fix ETM build failure v3: Really fix ETM build failure (Kim Phillips) Signed-off-by: Andi Kleen Acked-by: Jiri Olsa Cc: Kim Phillips Cc: Leo Yan Link: http://lkml.kernel.org/r/20180920180540.14039-3-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Add --insn-trace for instruction decoding

2018-10-24T18:29:50Z

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 Tested-by: Arnaldo Carvalho de Melo Acked-by: Jiri Olsa 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

perf script: Flush output stream after events in verbose mode

2018-10-22T17:27:11Z

When the perf script output is written to a terminal stream, the normal output of `perf script` would get buffered, but its debug output would be written directly. This made it quite hard to figure out where a given debug output is coming from. We can improve on this by flushing the output buffer after processing an event. To see the value, compare the following output for a `perf script -v` run: Before this patch: ``` unwind: reg 16, val 7faf7dfdc000 unwind: reg 7, val 7ffc80811e30 unwind: find_proc_info dso /usr/lib/ld-2.28.so unwind: reg 6, val 0 unwind: _start:ip = 0x7faf7dfdc000 (0x2000) unwind: reg 16, val 7faf7dfdc000 unwind: reg 7, val 7ffc80811e30 unwind: find_proc_info dso /usr/lib/ld-2.28.so unwind: reg 6, val 0 unwind: _start:ip = 0x7faf7dfdc000 (0x2000) unwind: reg 16, val 7faf7dfdc000 unwind: reg 7, val 7ffc80811e30 unwind: find_proc_info dso /usr/lib/ld-2.28.so unwind: reg 6, val 0 unwind: _start:ip = 0x7faf7dfdc000 (0x2000) unwind: reg 16, val 7faf7dfdc000 unwind: reg 7, val 7ffc80811e30 ... lots and lots of verbose debug output cpp-inlining 24617 90229.122036534: 1 cycles:uppp: 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so) cpp-inlining 24617 90229.122043974: 1 cycles:uppp: 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so) ... ``` After this patch: ``` ... unwind: reg 16, val 7faf7dfdc000 unwind: reg 7, val 7ffc80811e30 unwind: find_proc_info dso /usr/lib/ld-2.28.so unwind: reg 6, val 0 unwind: _start:ip = 0x7faf7dfdc000 (0x2000) cpp-inlining 24617 90229.122036534: 1 cycles:uppp: 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so) unwind: reg 16, val 7faf7dfdc000 unwind: reg 7, val 7ffc80811e30 unwind: find_proc_info dso /usr/lib/ld-2.28.so unwind: reg 6, val 0 unwind: _start:ip = 0x7faf7dfdc000 (0x2000) cpp-inlining 24617 90229.122043974: 1 cycles:uppp: 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so) ... ``` This new output format makes it much easier to use perf script output for debugging purposes, e.g. to investigate broken dwarf unwinding. Signed-off-by: Milian Wolff Acked-by: Jiri Olsa Link: http://lkml.kernel.org/r/20181021191424.16183-2-milian.wolff@kdab.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Allow extended console debug output

2018-10-22T15:37:53Z

The script tool isn't using a browser, yet use_browser wasn't set explicitly to zero. This in turn lead to confusing output such as: ``` $ perf script -vvv ... ... overlapping maps in /home/milian/foobar (disable tui for more info) ... ``` Explicitly set use_browser to 0 now, which gives us the extended debug information now in perf script as expected. Signed-off-by: Milian Wolff Acked-by: Jiri Olsa Tested-by: Arnaldo Carvalho de Melo Link: http://lkml.kernel.org/r/20181021191424.16183-1-milian.wolff@kdab.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Enhance sample flags for trace begin / end

2018-09-20T14:09:55Z

Allow for different combinations of sample flags with "trace begin" or "trace end". Previously, the Intel PT decoder would indicate begin / end by a branch from / to zero. That hides useful information, in particular when a trace ends with a call. Before remedying that, prepare 'perf script' to display sample flags with more combinations that include trace begin / end. In those cases display 'tr start' and 'tr end' separately. Signed-off-by: Adrian Hunter Cc: Andi Kleen Cc: Jiri Olsa Link: http://lkml.kernel.org/r/20180920130048.31432-2-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Print DSO for callindent

2018-09-19T18:25:51Z

Now that we don't need to print the IP/ADDR for callindent the DSO is also not printed. It's useful for some cases, so add an own DSO printout for callindent for the case when IP/ADDR is not enabled. Before: % perf script --itrace=cr -F +callindent,-ip,-sym,-symoff,-addr swapper 0 [000] 3377.917072: 1 branches: pt_config swapper 0 [000] 3377.917072: 1 branches: pt_config swapper 0 [000] 3377.917072: 1 branches: pt_event_add swapper 0 [000] 3377.917072: 1 branches: perf_pmu_enable swapper 0 [000] 3377.917072: 1 branches: perf_pmu_nop_void swapper 0 [000] 3377.917072: 1 branches: event_sched_in.isra.107 swapper 0 [000] 3377.917072: 1 branches: __x86_indirect_thunk_rax swapper 0 [000] 3377.917072: 1 branches: perf_pmu_nop_int swapper 0 [000] 3377.917072: 1 branches: group_sched_in swapper 0 [000] 3377.917072: 1 branches: event_filter_match swapper 0 [000] 3377.917072: 1 branches: event_filter_match swapper 0 [000] 3377.917072: 1 branches: group_sched_in After: swapper 0 [000] 3377.917072: 1 branches: ([unknown]) pt_config swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) pt_config swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) pt_event_add swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) perf_pmu_enable swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) perf_pmu_nop_void swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) event_sched_in.isra.107 swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) __x86_indirect_thunk_rax swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) perf_pmu_nop_int swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) group_sched_in swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) event_filter_match swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) event_filter_match swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) group_sched_in swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) __x86_indirect_thunk_rax swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) perf_pmu_nop_txn swapper 0 [000] 3377.917072: 1 branches: ([kernel.kallsyms]) event_sched_in.isra.107 (in the kernel case of course it's not very useful, but it's important with user programs where symbols are not unique) Signed-off-by: Andi Kleen Tested-by: Arnaldo Carvalho de Melo Cc: Adrian Hunter Cc: Jiri Olsa Cc: Kim Phillips Link: http://lkml.kernel.org/r/20180918123214.26728-6-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Allow sym and dso without ip, addr

2018-09-19T18:20:03Z

Currently sym and dso require printing ip and addr because the print function is tied to those outputs. With callindent it makes sense to print the symbol or dso without numerical IP or ADDR. So change the dependency check to only check the underlying attribute. Also the branch target output relies on the user_set flag to determine if the branch target should be implicitely printed. When modifying the fields with + or - also set user_set, so that ADDR can be removed. We also need to set wildcard_set to make the initial sanity check pass. This allows to remove a lot of noise in callindent output by dropping the numerical addresses, which are not all that useful. Before % perf script --itrace=cr -F +callindent swapper 0 [000] 156546.354971: 1 branches: pt_config 0 [unknown] ([unknown]) => ffffffff81010486 pt_config ([kernel.kallsyms]) swapper 0 [000] 156546.354971: 1 branches: pt_config ffffffff81010499 pt_config ([kernel.kallsyms]) => ffffffff8101063e pt_event_add ([kernel.kallsyms]) swapper 0 [000] 156546.354971: 1 branches: pt_event_add ffffffff81010635 pt_event_add ([kernel.kallsyms]) => ffffffff8115e687 event_sched_in.isra.107 ([kernel.kallsyms]) swapper 0 [000] 156546.354971: 1 branches: perf_pmu_enable ffffffff8115e726 event_sched_in.isra.107 ([kernel.kallsyms]) => ffffffff811579b0 perf_pmu_enable ([kernel.kallsyms]) swapper 0 [000] 156546.354971: 1 branches: perf_pmu_nop_void ffffffff81151730 perf_pmu_nop_void ([kernel.kallsyms]) => ffffffff8115e72b event_sched_in.isra.107 ([kernel.kallsyms]) swapper 0 [000] 156546.354971: 1 branches: event_sched_in.isra.107 ffffffff8115e737 event_sched_in.isra.107 ([kernel.kallsyms]) => ffffffff8115e7a5 group_sched_in ([kernel.kallsyms]) swapper 0 [000] 156546.354971: 1 branches: __x86_indirect_thunk_rax ffffffff8115e7f6 group_sched_in ([kernel.kallsyms]) => ffffffff81a03000 __x86_indirect_thunk_rax ([kernel.kallsyms]) After % perf script --itrace=cr -F +callindent,-ip,-sym,-symoff swapper 0 [000] 156546.354971: 1 branches: pt_config swapper 0 [000] 156546.354971: 1 branches: pt_config swapper 0 [000] 156546.354971: 1 branches: pt_event_add swapper 0 [000] 156546.354971: 1 branches: perf_pmu_enable swapper 0 [000] 156546.354971: 1 branches: perf_pmu_nop_void swapper 0 [000] 156546.354971: 1 branches: event_sched_in.isra.107 swapper 0 [000] 156546.354971: 1 branches: __x86_indirect_thunk_rax swapper 0 [000] 156546.354971: 1 branches: perf_pmu_nop_int swapper 0 [000] 156546.354971: 1 branches: group_sched_in swapper 0 [000] 156546.354971: 1 branches: event_filter_match swapper 0 [000] 156546.354971: 1 branches: event_filter_match swapper 0 [000] 156546.354971: 1 branches: group_sched_in Signed-off-by: Andi Kleen Tested-by: Arnaldo Carvalho de Melo Cc: Adrian Hunter Cc: Jiri Olsa Cc: Kim Phillips Link: http://lkml.kernel.org/r/20180918123214.26728-5-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo