linux/tools/perf/builtin-script.c, branch v5.0

perf script: Fix crash when processing recorded stat data

2019-01-21T14:29:07Z

While updating perf to work with Python3 and Python2 I noticed that the stat-cpi script was dumping core. $ perf stat -e cycles,instructions record -o /tmp/perf.data /bin/false Performance counter stats for '/bin/false': 802,148 cycles 604,622 instructions 802,148 cycles 604,622 instructions 0.001445842 seconds time elapsed $ perf script -i /tmp/perf.data -s scripts/python/stat-cpi.py Segmentation fault (core dumped) ... ... rblist=rblist@entry=0xb2a200 , new_entry=new_entry@entry=0x7ffcb755c310) at util/rblist.c:33 ctx=, type=, create=, cpu=, evsel=) at util/stat-shadow.c:118 ctx=, type=, st=) at util/stat-shadow.c:196 count=count@entry=727442, cpu=cpu@entry=0, st=0xb2a200 ) at util/stat-shadow.c:239 config=config@entry=0xafeb40 , counter=counter@entry=0x133c6e0) at util/stat.c:372 ... ... The issue is that since 1fcd03946b52 perf_stat__update_shadow_stats now calls update_runtime_stat passing rt_stat rather than calling update_stats but perf_stat__init_shadow_stats has never been called to initialize rt_stat in the script path processing recorded stat data. Since I can't see any reason why perf_stat__init_shadow_stats() is presently initialized like it is in builtin-script.c::perf_sample__fprint_metric() [4bd1bef8bba2f] I'm proposing it instead be initialized once in __cmd_script Committer testing: After applying the patch: # perf script -i /tmp/perf.data -s tools/perf/scripts/python/stat-cpi.py 0.001970: cpu -1, thread -1 -> cpi 1.709079 (1075684/629394) # No segfault. Signed-off-by: Tony Jones Reviewed-by: Jiri Olsa Tested-by: Arnaldo Carvalho de Melo Tested-by: Ravi Bangoria Cc: Andi Kleen Cc: Jin Yao Fixes: 1fcd03946b52 ("perf stat: Update per-thread shadow stats") Link: http://lkml.kernel.org/r/20190120191414.12925-1-tonyj@suse.de Signed-off-by: Arnaldo Carvalho de Melo

perf script: Fix crash with printing mixed trace point and other events

2019-01-18T12:53:07Z

'perf script' crashes currently when printing mixed trace points and other events because the trace format does not handle events without trace meta data. Add a simple check to avoid that. % cat > test.c main() { printf("Hello world\n"); } ^D % gcc -g -o test test.c % sudo perf probe -x test 'test.c:3' % perf record -e '{cpu/cpu-cycles,period=10000/,probe_test:main}:S' ./test % perf script Committer testing: Before: # perf probe -x /lib64/libc-2.28.so malloc Added new event: probe_libc:malloc (on malloc in /usr/lib64/libc-2.28.so) You can now use it in all perf tools, such as: perf record -e probe_libc:malloc -aR sleep 1 # perf probe -l probe_libc:malloc (on __libc_malloc@malloc/malloc.c in /usr/lib64/libc-2.28.so) # perf record -e '{cpu/cpu-cycles,period=10000/,probe_libc:*}:S' sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.023 MB perf.data (40 samples) ] # perf script Segmentation fault (core dumped) ^C # After: # perf script | head -6 sleep 2888 94796.944981: 16198 cpu/cpu-cycles,period=10000/: ffffffff925dc04f get_random_u32+0x1f (/lib/modules/5.0.0-rc2+/build/vmlinux) sleep 2888 [-01] 94796.944981: probe_libc:malloc: sleep 2888 94796.944983: 4713 cpu/cpu-cycles,period=10000/: ffffffff922763af change_protection+0xcf (/lib/modules/5.0.0-rc2+/build/vmlinux) sleep 2888 [-01] 94796.944983: probe_libc:malloc: sleep 2888 94796.944986: 9934 cpu/cpu-cycles,period=10000/: ffffffff922777e0 move_page_tables+0x0 (/lib/modules/5.0.0-rc2+/build/vmlinux) sleep 2888 [-01] 94796.944986: probe_libc:malloc: # Signed-off-by: Andi Kleen Tested-by: Arnaldo Carvalho de Melo Acked-by: Jiri Olsa Link: http://lkml.kernel.org/r/20190117194834.21940-1-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

perf thread-stack: Fix thread stack processing for the idle task

2019-01-02T14:03:17Z

perf creates a single 'struct thread' to represent the idle task. That is because threads are identified by PID and TID, and the idle task always has PID == TID == 0. However, there are actually separate idle tasks for each CPU. That creates a problem for thread stack processing which assumes that each thread has a single stack, not one stack per CPU. Fix that by passing through the CPU number, and in the case of the idle "thread", pick the thread stack from an array based on the CPU number. Signed-off-by: Adrian Hunter Acked-by: Jiri Olsa Link: http://lkml.kernel.org/r/20181221120620.9659-8-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Fix LBR skid dump problems in brstackinsn

2018-12-28T19:33:02Z

This is a fix for another instance of the skid problem Milian recently found [1] The LBRs don't freeze at the exact same time as the PMI is triggered. The perf script brstackinsn code that dumps LBR assembler assumes that the last branch in the LBR leads to the sample point. But with skid it's possible that the CPU executes one or more branches before the sample, but which do not appear in the LBR. What happens then is either that the sample point is before the last LBR branch. In this case the dumper sees a negative length and ignores it. Or it the sample point is long after the last branch. Then the dumper sees a very long block and dumps it upto its block limit (16k bytes), which is noise in the output. On typical sample session this can happen regularly. This patch tries to detect and handle the situation. On the last block that is dumped by the LBR dumper we always stop on the first branch. If the block length is negative just scan forward to the first branch. Otherwise scan until a branch is found. The PT decoder already has a function that uses the instruction decoder to detect branches, so we can just reuse it here. Then when a terminating branch is found print an indication and stop dumping. This might miss a few instructions, but at least shows no runaway blocks. Signed-off-by: Andi Kleen Acked-by: Adrian Hunter Cc: Jiri Olsa Cc: Milian Wolff Link: http://lkml.kernel.org/r/20181120050617.4119-1-andi@firstfloor.org [ Resolved conflict with dd2e18e9ac20 ("perf tools: Support 'srccode' output") ] Signed-off-by: Arnaldo Carvalho de Melo

perf tools: Support 'srccode' output

2018-12-17T17:57:07Z

When looking at PT or brstackinsn traces with 'perf script' it can be very useful to see the source code. This adds a simple facility to print them with 'perf script', if the information is available through dwarf % perf record ... % perf script -F insn,ip,sym,srccode ... 4004c6 main 5 for (i = 0; i < 10000000; i++) 4004cd main 5 for (i = 0; i < 10000000; i++) 4004c6 main 5 for (i = 0; i < 10000000; i++) 4004cd main 5 for (i = 0; i < 10000000; i++) 4004cd main 5 for (i = 0; i < 10000000; i++) 4004cd main 5 for (i = 0; i < 10000000; i++) 4004cd main 5 for (i = 0; i < 10000000; i++) 4004cd main 5 for (i = 0; i < 10000000; i++) 4004b3 main 6 v++; % perf record -b ... % perf script -F insn,ip,sym,srccode,brstackinsn ... main+22: 0000000000400543 insn: e8 ca ff ff ff # PRED |18 f1(); f1: 0000000000400512 insn: 55 |10 { 0000000000400513 insn: 48 89 e5 0000000000400516 insn: b8 00 00 00 00 |11 f2(); 000000000040051b insn: e8 d6 ff ff ff # PRED f2: 00000000004004f6 insn: 55 |5 { 00000000004004f7 insn: 48 89 e5 00000000004004fa insn: 8b 05 2c 0b 20 00 |6 c = a / b; 0000000000400500 insn: 8b 0d 2a 0b 20 00 0000000000400506 insn: 99 0000000000400507 insn: f7 f9 0000000000400509 insn: 89 05 29 0b 20 00 000000000040050f insn: 90 |7 } 0000000000400510 insn: 5d 0000000000400511 insn: c3 # PRED f1+14: 0000000000400520 insn: b8 00 00 00 00 |12 f2(); 0000000000400525 insn: e8 cc ff ff ff # PRED f2: 00000000004004f6 insn: 55 |5 { 00000000004004f7 insn: 48 89 e5 00000000004004fa insn: 8b 05 2c 0b 20 00 |6 c = a / b; Not supported for callchains currently, would need some layout changes there. Committer notes: Fixed the build on Alpine Linux (3.4 .. 3.8) by addressing this warning: In file included from util/srccode.c:19:0: /usr/include/sys/fcntl.h:1:2: error: #warning redirecting incorrect #include to [-Werror=cpp] #warning redirecting incorrect #include to ^~~~~~~ cc1: all warnings being treated as errors Signed-off-by: Andi Kleen Tested-by: Jiri Olsa Link: http://lkml.kernel.org/r/20181204001848.24769-1-andi@firstfloor.org Signed-off-by: Arnaldo Carvalho de Melo

perf script: Use fallbacks for branch stacks

2018-12-17T17:54:18Z

Branch stacks do not necessarily have the same cpumode as the 'ip'. Use the fallback functions in those cases. This patch depends on patch "perf tools: Add fallback functions for cases where cpumode is insufficient". Signed-off-by: Adrian Hunter Cc: Andi Kleen Cc: David S. Miller Cc: Jiri Olsa Cc: Leo Yan Cc: Mathieu Poirier Cc: stable@vger.kernel.org # 4.19 Link: http://lkml.kernel.org/r/20181106210712.12098-4-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Share code and output format for uregs and iregs output

2018-11-21T15:00:32Z

The iregs output was missing the newline at end as well as the leading ABI output. This made it hard to compare the iregs and uregs values. Instead, use a single function to output the register values and use it for both, iregs and uregs, to ensure the output is consistent. Before: perf 7049 [-01] 1343.354347: 1 cycles:ppp: ffffffffa7bc21ce perf_event_exec+0x18e (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7ead3 setup_new_exec+0xf3 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7cd7be5 load_elf_binary+0x395 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7e540 search_binary_handler+0x80 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7f1aa __do_execve_file.isra.13+0x58a (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7f561 do_execve+0x21 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7f596 __x64_sys_execve+0x26 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7a041cb do_syscall_64+0x5b (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa840008c entry_SYSCALL_64+0x7c (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) AX:0x80000000 BX:0x0 CX:0x0 DX:0x7 SI:0xf DI:0x286 BP:0xffff95bc8213a460 SP:0xffffacbf0ba97d18 IP:0xffffffffa7bc21cd FLAGS:0x28e CS:0x10 SS:0x18 R8:0x2 R9:0x21440 R10:0x33816fb3b8c R11:0x1 R12:0xffff95bc8213a460 R13:0xffff95bc8213a400 R14:0xffff95bc8213a400 R15:0x1 ABI:2 AX:0xffffffffffffffda BX:0xffffffffffffffff CX:0x7f84ad85798b DX:0x560209699d50 SI:0x7ffe2c7a6820 DI:0x7ffe2c7a8c9b BP:0x7ffe2c7a20d0 SP:0x7ffe2c7a2058 IP:0x7f84ad85798b FLAGS:0x206 CS:0x33 SS:0x2b R8:0x7ffe2c7a2030 R9:0x7f84ae55f010 R10:0x8 R11:0x206 R12:0xffffffffffffffff R13:0xffffffffffffffff R14:0xffffffffffffffff R15:0xffffffffffffffff perf 7049 [-01] 1343.354363: 1 cycles:ppp: ... After: perf 7049 [-01] 1343.354347: 1 cycles:ppp: ffffffffa7bc21ce perf_event_exec+0x18e (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7ead3 setup_new_exec+0xf3 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7cd7be5 load_elf_binary+0x395 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7e540 search_binary_handler+0x80 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7f1aa __do_execve_file.isra.13+0x58a (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7f561 do_execve+0x21 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7c7f596 __x64_sys_execve+0x26 (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa7a041cb do_syscall_64+0x5b (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ffffffffa840008c entry_SYSCALL_64+0x7c (/lib/modules/4.20.0-rc1perf-devel-05115-gc0bc98f76e39-dirty/build/vmlinux) ABI:2 AX:0x80000000 BX:0x0 CX:0x0 DX:0x7 SI:0xf DI:0x286 BP:0xffff95bc8213a460 SP:0xffffacbf0ba97d18 IP:0xffffffffa7bc21cd FLAGS:0x28e CS:0x10 SS:0x18 R8:0x2 R9:0x21440 R10:0x33816fb3b8c R11:0x1 R12:0xffff95bc8213a460 R13:0xffff95bc8213a400 R14:0xffff95bc8213a400 R15:0x1 ABI:2 AX:0xffffffffffffffda BX:0xffffffffffffffff CX:0x7f84ad85798b DX:0x560209699d50 SI:0x7ffe2c7a6820 DI:0x7ffe2c7a8c9b BP:0x7ffe2c7a20d0 SP:0x7ffe2c7a2058 IP:0x7f84ad85798b FLAGS:0x206 CS:0x33 SS:0x2b R8:0x7ffe2c7a2030 R9:0x7f84ae55f010 R10:0x8 R11:0x206 R12:0xffffffffffffffff R13:0xffffffffffffffff R14:0xffffffffffffffff R15:0xffffffffffffffff perf 7049 [-01] 1343.354363: 1 cycles:ppp: ... Signed-off-by: Milian Wolff Acked-by: Jiri Olsa Link: http://lkml.kernel.org/r/20181107223437.9071-1-milian.wolff@kdab.com Signed-off-by: Arnaldo Carvalho de Melo

perf script: Add newline after uregs output

2018-11-21T15:00:31Z

This change makes it much easier to easily distinguish between consecutive samples by keeping the empty line between them, like we see when we do not enable uregs output. Before: cpp-inlining 28298 [-01] 54837.342780: 3068085 cycles:pp: 7ffff7c96709 __hypot_finite+0xa9 (/usr/lib/libm-2.28.so) ... ABI:2 AX:0x0 BX:0x40f56cf6 CX:0x294a3ae7 ... cpp-inlining 28298 [-01] 54837.344493: 2881929 cycles:pp: 7ffff7c96696 __hypot_finite+0x36 (/usr/lib/libm-2.28.so) ... ABI:2 AX:0x40d440c7 BX:0x40d440c7 CX:0x4d45e5da ... After: cpp-inlining 28298 [-01] 54837.342780: 3068085 cycles:pp: 7ffff7c96709 __hypot_finite+0xa9 (/usr/lib/libm-2.28.so) ... ABI:2 AX:0x0 BX:0x40f56cf6 CX:0x294a3ae7 ... cpp-inlining 28298 [-01] 54837.344493: 2881929 cycles:pp: 7ffff7c96696 __hypot_finite+0x36 (/usr/lib/libm-2.28.so) ... ABI:2 AX:0x40d440c7 BX:0x40d440c7 CX:0x4d45e5da ... Signed-off-by: Milian Wolff Cc: Jiri Olsa Link: http://lkml.kernel.org/r/20181107093705.16346-1-milian.wolff@kdab.com Signed-off-by: Arnaldo Carvalho de Melo

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