kernel.git/tools/perf/Documentation/perf-script.txt, branch linux-5.6.y

perf script: Allow specifying event to switch off processing of other events

2019-08-15T15:24:16Z

Counterpart of --switch-on: # perf record -e sched:*,syscalls:sys_*_nanosleep sleep 1 [ perf record: Woken up 36 times to write data ] [ perf record: Captured and wrote 0.032 MB perf.data (10 samples) ] # # perf script :20918 20918 [002] 109866.143696: sched:sched_waking: comm=perf pid=20919 prio=120 target_cpu=001 :20918 20918 [002] 109866.143702: sched:sched_wakeup: perf:20919 [120] success=1 CPU:001 sleep 20919 [001] 109866.144081: sched:sched_process_exec: filename=/usr/bin/sleep pid=20919 old_pid=20919 sleep 20919 [001] 109866.144408: syscalls:sys_enter_nanosleep: rqtp: 0x7ffc2384fef0, rmtp: 0x00000000 sleep 20919 [001] 109866.144411: sched:sched_stat_runtime: comm=sleep pid=20919 runtime=521249 [ns] vruntime=202919398131 [n> sleep 20919 [001] 109866.144412: sched:sched_switch: sleep:20919 [120] S ==> swapper/1:0 [120] swapper 0 [001] 109867.144568: sched:sched_waking: comm=sleep pid=20919 prio=120 target_cpu=001 swapper 0 [001] 109867.144586: sched:sched_wakeup: sleep:20919 [120] success=1 CPU:001 sleep 20919 [001] 109867.144614: syscalls:sys_exit_nanosleep: 0x0 sleep 20919 [001] 109867.144753: sched:sched_process_exit: comm=sleep pid=20919 prio=120 # # perf script --switch-off syscalls:sys_exit_nanosleep :20918 20918 [002] 109866.143696: sched:sched_waking: comm=perf pid=20919 prio=120 target_cpu=001 :20918 20918 [002] 109866.143702: sched:sched_wakeup: perf:20919 [120] success=1 CPU:001 sleep 20919 [001] 109866.144081: sched:sched_process_exec: filename=/usr/bin/sleep pid=20919 old_pid=20919 sleep 20919 [001] 109866.144408: syscalls:sys_enter_nanosleep: rqtp: 0x7ffc2384fef0, rmtp: 0x00000000 sleep 20919 [001] 109866.144411: sched:sched_stat_runtime: comm=sleep pid=20919 runtime=521249 [ns] vruntime=202919398131 [n> sleep 20919 [001] 109866.144412: sched:sched_switch: sleep:20919 [120] S ==> swapper/1:0 [120] swapper 0 [001] 109867.144568: sched:sched_waking: comm=sleep pid=20919 prio=120 target_cpu=001 swapper 0 [001] 109867.144586: sched:sched_wakeup: sleep:20919 [120] success=1 CPU:001 sleep 20919 [001] 109867.144753: sched:sched_process_exit: comm=sleep pid=20919 prio=120 # # perf script --switch-on syscalls:sys_enter_nanosleep --switch-off syscalls:sys_exit_nanosleep sleep 20919 [001] 109866.144411: sched:sched_stat_runtime: comm=sleep pid=20919 runtime=521249 [ns] vruntime=202919398131 [n> sleep 20919 [001] 109866.144412: sched:sched_switch: sleep:20919 [120] S ==> swapper/1:0 [120] swapper 0 [001] 109867.144568: sched:sched_waking: comm=sleep pid=20919 prio=120 target_cpu=001 swapper 0 [001] 109867.144586: sched:sched_wakeup: sleep:20919 [120] success=1 CPU:001 # # perf script --switch-on syscalls:sys_enter_nanosleep --switch-off syscalls:sys_exit_nanosleep --show-on-off sleep 20919 [001] 109866.144408: syscalls:sys_enter_nanosleep: rqtp: 0x7ffc2384fef0, rmtp: 0x00000000 sleep 20919 [001] 109866.144411: sched:sched_stat_runtime: comm=sleep pid=20919 runtime=521249 [ns] vruntime=202919398131 [n> sleep 20919 [001] 109866.144412: sched:sched_switch: sleep:20919 [120] S ==> swapper/1:0 [120] swapper 0 [001] 109867.144568: sched:sched_waking: comm=sleep pid=20919 prio=120 target_cpu=001 swapper 0 [001] 109867.144586: sched:sched_wakeup: sleep:20919 [120] success=1 CPU:001 sleep 20919 [001] 109867.144614: syscalls:sys_exit_nanosleep: 0x0 # Now think about using this together with 'perf probe' to create custom on/off events in your app :-) Cc: Adrian Hunter Cc: Florian Weimer Cc: Jiri Olsa Cc: Namhyung Kim Cc: William Cohen Link: https://lkml.kernel.org/n/tip-li3j01c4tmj9kw6ydsl8swej@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Allow showing the --switch-on event

2019-08-15T15:24:08Z

One may want to see the --switch-on event as well, allow for that, using the previous cset example: # perf script --switch-on syscalls:sys_enter_nanosleep --show-on-off sleep 13638 [001] 108237.582286: syscalls:sys_enter_nanosleep: rqtp: 0x7fff1948ac40, rmtp: 0x00000000 sleep 13638 [001] 108237.582289: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=578104 [ns] vruntime=202889459556 [ns] sleep 13638 [001] 108237.582291: sched:sched_switch: sleep:13638 [120] S ==> swapper/1:0 [120] swapper 0 [001] 108238.582428: sched:sched_waking: comm=sleep pid=13638 prio=120 target_cpu=001 swapper 0 [001] 108238.582458: sched:sched_wakeup: sleep:13638 [120] success=1 CPU:001 sleep 13638 [001] 108238.582698: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=173915 [ns] vruntime=202889633471 [ns] sleep 13638 [001] 108238.582782: sched:sched_process_exit: comm=sleep pid=13638 prio=120 # # perf script --switch-on syscalls:sys_enter_nanosleep sleep 13638 [001] 108237.582289: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=578104 [ns] vruntime=202889459556 [ns] sleep 13638 [001] 108237.582291: sched:sched_switch: sleep:13638 [120] S ==> swapper/1:0 [120] swapper 0 [001] 108238.582428: sched:sched_waking: comm=sleep pid=13638 prio=120 target_cpu=001 swapper 0 [001] 108238.582458: sched:sched_wakeup: sleep:13638 [120] success=1 CPU:001 sleep 13638 [001] 108238.582698: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=173915 [ns] vruntime=202889633471 [ns] sleep 13638 [001] 108238.582782: sched:sched_process_exit: comm=sleep pid=13638 prio=120 # Signed-off-by: Arnaldo Carvalho de Melo Cc: Adrian Hunter Cc: Jiri Olsa Cc: Namhyung Kim Cc: William Cohen Cc: Florian Weimer Link: https://lkml.kernel.org/n/tip-0omwwoywj1v63gu8cz0tr0cy@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Allow specifying event to switch on processing of other events

2019-08-15T15:23:58Z

Sometime we want to only consider events after something happens, so allow discarding events till such events is found, e.g.: Record all scheduler tracepoints and the sys_enter_nanosleep syscall event for the 'sleep 1' workload: # perf record -e sched:*,syscalls:sys_enter_nanosleep sleep 1 [ perf record: Woken up 31 times to write data ] [ perf record: Captured and wrote 0.032 MB perf.data (10 samples) ] # So we have these events in the generated perf data file: # perf evlist sched:sched_kthread_stop sched:sched_kthread_stop_ret sched:sched_waking sched:sched_wakeup sched:sched_wakeup_new sched:sched_switch sched:sched_migrate_task sched:sched_process_free sched:sched_process_exit sched:sched_wait_task sched:sched_process_wait sched:sched_process_fork sched:sched_process_exec sched:sched_stat_wait sched:sched_stat_sleep sched:sched_stat_iowait sched:sched_stat_blocked sched:sched_stat_runtime sched:sched_pi_setprio sched:sched_move_numa sched:sched_stick_numa sched:sched_swap_numa sched:sched_wake_idle_without_ipi syscalls:sys_enter_nanosleep # Tip: use 'perf evlist --trace-fields' to show fields for tracepoint events # Then show all of the events that actually took place in this 'perf record' session: # perf script :13637 13637 [002] 108237.581529: sched:sched_waking: comm=perf pid=13638 prio=120 target_cpu=001 :13637 13637 [002] 108237.581537: sched:sched_wakeup: perf:13638 [120] success=1 CPU:001 sleep 13638 [001] 108237.581992: sched:sched_process_exec: filename=/usr/bin/sleep pid=13638 old_pid=13638 sleep 13638 [001] 108237.582286: syscalls:sys_enter_nanosleep: rqtp: 0x7fff1948ac40, rmtp: 0x00000000 sleep 13638 [001] 108237.582289: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=578104 [ns] vruntime=202889459556 [ns] sleep 13638 [001] 108237.582291: sched:sched_switch: sleep:13638 [120] S ==> swapper/1:0 [120] swapper 0 [001] 108238.582428: sched:sched_waking: comm=sleep pid=13638 prio=120 target_cpu=001 swapper 0 [001] 108238.582458: sched:sched_wakeup: sleep:13638 [120] success=1 CPU:001 sleep 13638 [001] 108238.582698: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=173915 [ns] vruntime=202889633471 [ns] sleep 13638 [001] 108238.582782: sched:sched_process_exit: comm=sleep pid=13638 prio=120 # Now lets see only the ones that took place after a certain "marker": # perf script --switch-on syscalls:sys_enter_nanosleep sleep 13638 [001] 108237.582289: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=578104 [ns] vruntime=202889459556 [ns] sleep 13638 [001] 108237.582291: sched:sched_switch: sleep:13638 [120] S ==> swapper/1:0 [120] swapper 0 [001] 108238.582428: sched:sched_waking: comm=sleep pid=13638 prio=120 target_cpu=001 swapper 0 [001] 108238.582458: sched:sched_wakeup: sleep:13638 [120] success=1 CPU:001 sleep 13638 [001] 108238.582698: sched:sched_stat_runtime: comm=sleep pid=13638 runtime=173915 [ns] vruntime=202889633471 [ns] sleep 13638 [001] 108238.582782: sched:sched_process_exit: comm=sleep pid=13638 prio=120 # Cc: Adrian Hunter Cc: Florian Weimer Cc: Jiri Olsa Cc: Namhyung Kim Cc: William Cohen Link: https://lkml.kernel.org/n/tip-f1oo0ufdhrkx6nhy2lj1ierm@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Improve man page description of metrics

2019-07-23T11:58:11Z

Clarify that a metric is based on events, not referring to itself. Also some improvements with the sentences. Signed-off-by: Andi Kleen Cc: Jiri Olsa Link: http://lkml.kernel.org/r/20190711181922.18765-3-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Fix --max-blocks man page description

2019-07-23T11:57:54Z

The --max-blocks description was using the old name brstackasm. Use brstackinsn instead. Signed-off-by: Andi Kleen Cc: Jiri Olsa Link: http://lkml.kernel.org/r/20190711181922.18765-1-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

perf time-utils: Add support for multiple explicit time intervals

2019-06-10T19:20:13Z

Currently only a single explicit time range is accepted. Add support for multiple ranges separated by spaces, which requires the string to be quoted. Update the time utils test accordingly. Signed-off-by: Adrian Hunter Cc: Jin Yao Cc: Jiri Olsa Link: http://lkml.kernel.org/r/20190604130017.31207-20-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo

perf time-utils: Fix --time documentation

2019-06-10T19:20:12Z

Correct some punctuation and spelling and correct the format to show that the time resolution is nanoseconds not microseconds. Signed-off-by: Adrian Hunter Cc: Jin Yao Cc: Jiri Olsa Link: http://lkml.kernel.org/r/20190604130017.31207-16-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Add output of IPC ratio

2019-06-05T12:47:56Z

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 Tested-by: Arnaldo Carvalho de Melo Cc: Jiri Olsa Link: http://lkml.kernel.org/r/20190520113728.14389-9-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Add --show-bpf-events to show eBPF related events

2019-05-28T21:37:44Z

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 Acked-by: Song Liu Tested-by: Arnaldo Carvalho de Melo Cc: Adrian Hunter Cc: Alexander Shishkin Cc: Andi Kleen Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Stanislav Fomichev Link: http://lkml.kernel.org/r/20190508132010.14512-11-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Support relative time

2019-03-19T19:52:03Z

When comparing time stamps in 'perf script' traces it can be annoying to work with the full perf time stamps. Add a --reltime option that displays time stamps relative to the trace start to make it easier to read the traces. Note: not currently supported for --time. Report an error in this case. Before: % perf script swapper 0 [000] 245402.891216: 1 cycles:ppp: ffffffffa0068814 native_write_msr+0x4 ([kernel.kallsyms]) swapper 0 [000] 245402.891223: 1 cycles:ppp: ffffffffa0068814 native_write_msr+0x4 ([kernel.kallsyms]) swapper 0 [000] 245402.891227: 5 cycles:ppp: ffffffffa0068814 native_write_msr+0x4 ([kernel.kallsyms]) swapper 0 [000] 245402.891231: 41 cycles:ppp: ffffffffa0068816 native_write_msr+0x6 ([kernel.kallsyms]) swapper 0 [000] 245402.891235: 355 cycles:ppp: ffffffffa000dd51 intel_bts_enable_local+0x21 ([kernel.kallsyms]) swapper 0 [000] 245402.891239: 3084 cycles:ppp: ffffffffa0a0150a end_repeat_nmi+0x48 ([kernel.kallsyms]) After: % perf script --reltime swapper 0 [000] 0.000000: 1 cycles:ppp: ffffffffa0068814 native_write_msr+0x4 ([kernel.kallsyms]) swapper 0 [000] 0.000006: 1 cycles:ppp: ffffffffa0068814 native_write_msr+0x4 ([kernel.kallsyms]) swapper 0 [000] 0.000010: 5 cycles:ppp: ffffffffa0068814 native_write_msr+0x4 ([kernel.kallsyms]) swapper 0 [000] 0.000014: 41 cycles:ppp: ffffffffa0068816 native_write_msr+0x6 ([kernel.kallsyms]) swapper 0 [000] 0.000018: 355 cycles:ppp: ffffffffa000dd51 intel_bts_enable_local+0x21 ([kernel.kallsyms]) swapper 0 [000] 0.000022: 3084 cycles:ppp: ffffffffa0a0150a end_repeat_nmi+0x48 ([kernel.kallsyms]) Committer notes: Do not use 'time' as the name of a variable, as this breaks the build on older glibcs: cc1: warnings being treated as errors builtin-script.c: In function 'perf_sample__fprintf_start': builtin-script.c:691: warning: declaration of 'time' shadows a global declaration /usr/include/time.h:187: warning: shadowed declaration is here Signed-off-by: Andi Kleen Tested-by: Arnaldo Carvalho de Melo Acked-by: Jiri Olsa LPU-Reference: 20190314225002.30108-8-andi@firstfloor.org Link: https://lkml.kernel.org/n/tip-bpahyi6pr9r399mvihu65fvc@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo