kernel/tools/perf/Documentation/perf-trace.txt, branch linux-4.17.y

perf trace: Show only failing syscalls

2018-04-02T10:57:37Z

For instance: # perf probe "vfs_getname=getname_flags:72 pathname=result->name:string" Added new event: probe:vfs_getname (on getname_flags:72 with pathname=result->name:string) You can now use it in all perf tools, such as: perf record -e probe:vfs_getname -aR sleep 1 # perf trace --failure sleep 1 0.043 ( 0.010 ms): sleep/10978 access(filename: /etc/ld.so.preload, mode: R) = -1 ENOENT No such file or directory For reference, here are all the syscalls in this case: # perf trace sleep 1 ? ( ): sleep/10976 ... [continued]: execve()) = 0 0.027 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d04000 0.044 ( 0.010 ms): sleep/10976 access(filename: /etc/ld.so.preload, mode: R) = -1 ENOENT No such file or directory 0.057 ( 0.006 ms): sleep/10976 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3 0.064 ( 0.002 ms): sleep/10976 fstat(fd: 3, statbuf: 0x7fffac22b370) = 0 0.067 ( 0.003 ms): sleep/10976 mmap(len: 111457, prot: READ, flags: PRIVATE, fd: 3) = 0x7feec8615000 0.071 ( 0.001 ms): sleep/10976 close(fd: 3) = 0 0.080 ( 0.007 ms): sleep/10976 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC) = 3 0.088 ( 0.002 ms): sleep/10976 read(fd: 3, buf: 0x7fffac22b538, count: 832) = 832 0.092 ( 0.001 ms): sleep/10976 fstat(fd: 3, statbuf: 0x7fffac22b3d0) = 0 0.094 ( 0.002 ms): sleep/10976 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7feec8613000 0.099 ( 0.004 ms): sleep/10976 mmap(len: 3889792, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7feec8057000 0.104 ( 0.007 ms): sleep/10976 mprotect(start: 0x7feec8203000, len: 2097152) = 0 0.112 ( 0.005 ms): sleep/10976 mmap(addr: 0x7feec8403000, len: 24576, prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 1753088) = 0x7feec8403000 0.120 ( 0.003 ms): sleep/10976 mmap(addr: 0x7feec8409000, len: 14976, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED) = 0x7feec8409000 0.128 ( 0.001 ms): sleep/10976 close(fd: 3) = 0 0.139 ( 0.001 ms): sleep/10976 arch_prctl(option: 4098, arg2: 140663540761856) = 0 0.186 ( 0.004 ms): sleep/10976 mprotect(start: 0x7feec8403000, len: 16384, prot: READ) = 0 0.204 ( 0.003 ms): sleep/10976 mprotect(start: 0x55bdc0ec3000, len: 4096, prot: READ) = 0 0.209 ( 0.004 ms): sleep/10976 mprotect(start: 0x7feec8631000, len: 4096, prot: READ) = 0 0.214 ( 0.010 ms): sleep/10976 munmap(addr: 0x7feec8615000, len: 111457) = 0 0.269 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d04000 0.271 ( 0.002 ms): sleep/10976 brk(brk: 0x55bdc2d25000) = 0x55bdc2d25000 0.274 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d25000 0.278 ( 0.007 ms): sleep/10976 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC) = 3 0.288 ( 0.001 ms): sleep/10976 fstat(fd: 3, statbuf: 0x7feec8408aa0) = 0 0.290 ( 0.003 ms): sleep/10976 mmap(len: 113045344, prot: READ, flags: PRIVATE, fd: 3) = 0x7feec1488000 0.297 ( 0.001 ms): sleep/10976 close(fd: 3) = 0 0.325 (1000.193 ms): sleep/10976 nanosleep(rqtp: 0x7fffac22c0b0) = 0 1000.560 ( 0.006 ms): sleep/10976 close(fd: 1) = 0 1000.573 ( 0.005 ms): sleep/10976 close(fd: 2) = 0 1000.596 ( ): sleep/10976 exit_group() # And can be done systemwide, etc, with backtraces: # perf trace --max-stack=16 --failure sleep 1 0.048 ( 0.015 ms): sleep/11092 access(filename: /etc/ld.so.preload, mode: R) = -1 ENOENT No such file or directory __access (inlined) dl_main (/usr/lib64/ld-2.26.so) # Or for some specific syscalls: # perf trace --max-stack=16 -e openat --failure cat /tmp/rien cat: /tmp/rien: No such file or directory 0.251 ( 0.012 ms): cat/11106 openat(dfd: CWD, filename: /tmp/rien) = -1 ENOENT No such file or directory __libc_open64 (inlined) main (/usr/bin/cat) __libc_start_main (/usr/lib64/libc-2.26.so) _start (/usr/bin/cat) # Look for inotify* syscalls that fail, system wide, for 2 seconds, with backtraces: # perf trace -a --max-stack=16 --failure -e inotify* sleep 2 819.165 ( 0.058 ms): gmain/1724 inotify_add_watch(fd: 8, pathname: /home/acme/~, mask: 16789454) = -1 ENOENT No such file or directory __GI_inotify_add_watch (inlined) _ik_watch (/usr/lib64/libgio-2.0.so.0.5400.3) _ip_start_watching (/usr/lib64/libgio-2.0.so.0.5400.3) im_scan_missing (/usr/lib64/libgio-2.0.so.0.5400.3) g_timeout_dispatch (/usr/lib64/libglib-2.0.so.0.5400.3) g_main_context_dispatch (/usr/lib64/libglib-2.0.so.0.5400.3) g_main_context_iterate.isra.23 (/usr/lib64/libglib-2.0.so.0.5400.3) g_main_context_iteration (/usr/lib64/libglib-2.0.so.0.5400.3) glib_worker_main (/usr/lib64/libglib-2.0.so.0.5400.3) g_thread_proxy (/usr/lib64/libglib-2.0.so.0.5400.3) start_thread (/usr/lib64/libpthread-2.26.so) __GI___clone (inlined) # Cc: Adrian Hunter Cc: David Ahern Cc: Jiri Olsa Cc: Namhyung Kim Cc: Wang Nan Link: https://lkml.kernel.org/n/tip-8f7d3mngaxvi7tlzloz3n7cs@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Support setting cgroups as targets

2018-03-07T13:22:26Z

One can set a cgroup as a default cgroup to be used by all events or set cgroups with the 'perf stat' and 'perf record' behaviour, i.e. '-G A' will be the cgroup for events defined so far in the command line. Here in my main machine, with a kvm instance running a rhel6 guinea pig I have: # ls -la /sys/fs/cgroup/perf_event/ | grep drw drwxr-xr-x. 14 root root 360 Mar 6 12:04 .. drwxr-xr-x. 3 root root 0 Mar 6 15:05 machine.slice # So I can go ahead and use that cgroup hierarchy, say lets see what syscalls are being emitted by threads in that 'machine.slice' hierarchy that are taking more than 100ms: # perf trace --duration 100 -G machine.slice 0.188 (249.850 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 250.274 (249.743 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 500.224 (249.755 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 750.097 (249.934 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 1000.244 (249.780 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 1250.197 (249.796 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 1500.124 (249.859 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 1750.076 (172.900 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 902.570 (1021.116 ms): qemu-system-x8/23667 ppoll(ufds: 0x558151e03180, nfds: 74, tsp: 0x7ffc00cd0900, sigsetsize: 8) = 1 1923.825 (305.133 ms): qemu-system-x8/23667 ppoll(ufds: 0x558151e03180, nfds: 74, tsp: 0x7ffc00cd0900, sigsetsize: 8) = 1 2000.172 (229.002 ms): CPU 0/KVM/23744 ioctl(fd: 16, cmd: KVM_RUN) = 0 ^C # If we look inside that cgroup hierarchy we get: # ls -la /sys/fs/cgroup/perf_event/machine.slice/ | grep drw drwxr-xr-x. 3 root root 0 Mar 6 15:05 . drwxr-xr-x. 2 root root 0 Mar 6 16:16 machine-qemu\x2d2\x2drhel6.sandy.scope # There is just one, but lets say there were more and we would want to see 5 seconds worth of syscall summary for the threads in that cgroup: # perf trace --summary -G machine.slice/machine-qemu\\x2d2\\x2drhel6.sandy.scope/ -a sleep 5 Summary of events: qemu-system-x86 (23667), 143858 events, 24.2% syscall calls total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- --------- --------- --------- --------- ------ ppoll 28492 4348.631 0.000 0.153 11.616 1.05% futex 19661 140.801 0.001 0.007 2.993 3.20% read 18440 68.084 0.001 0.004 1.653 4.33% ioctl 5387 24.768 0.002 0.005 0.134 1.62% CPU 0/KVM (23744), 449455 events, 75.8% syscall calls total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- --------- --------- --------- --------- ------ ioctl 148364 3401.812 0.000 0.023 11.801 1.15% futex 36131 404.127 0.001 0.011 7.377 2.63% writev 29452 339.688 0.003 0.012 1.740 1.36% write 11315 45.992 0.001 0.004 0.105 1.10% # See the documentation about how to set more than one cgroup for different events in the same command line. Cc: Adrian Hunter Cc: Alexander Shishkin Cc: David Ahern Cc: Hendrik Brueckner Cc: Jiri Olsa Cc: Namhyung Kim Cc: Ravi Bangoria Cc: Stephane Eranian Cc: Thomas Richter Cc: Wang Nan Link: https://lkml.kernel.org/n/tip-t126jh4occqvu0xdqlcjygex@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Add --print-sample

2018-01-25T09:37:29Z

To help with debugging, like the interrupted out of order issue that will be dealt with in the next patch in this series, changing the code to deal with: raw_syscalls:sys_enter 411967179.269 Timer 9609/9626 [2] raw_syscalls:sys_enter 411967179.213 file:// Content 9609/9609 [3] 328.038 (18446744073709.496 ms): Timer/9626 futex(uaddr: 0x7fc0d4027044, op: WAIT|PRIV, utime: 0x7fc0b0ffdb50 ) ... raw_syscalls:sys_exit 411967179.225 file:// Content 9609/9609 [3] 327.982 ( 0.012 ms): file:// Conten/9609 futex(uaddr: 0x7fc0d4027040, op: WAKE|PRIV, val: 1 ) = 1 That long duration is the bug. Cc: Adrian Hunter Cc: David Ahern Cc: Jiri Olsa Cc: Namhyung Kim Cc: Wang Nan Link: https://lkml.kernel.org/n/tip-fljqiibjn7wet24jd1ed7abc@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Document missing option, colons

2017-11-16T17:50:05Z

Add missing --force option to the man page. Signed-off-by: Sihyeon Jang Cc: Jiri Olsa Cc: Namhyung Kim Link: http://lkml.kernel.org/r/1510842367-11011-2-git-send-email-uneedsihyeon@gmail.com Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Support syscall name globbing

2017-09-01T17:45:58Z

So now we can use: # perf trace -e pkey_* 532.784 ( 0.006 ms): pkey/16018 pkey_alloc(init_val: DISABLE_WRITE) = -1 EINVAL Invalid argument 532.795 ( 0.004 ms): pkey/16018 pkey_mprotect(start: 0x7f380d0a6000, len: 4096, prot: READ|WRITE, pkey: -1) = 0 532.801 ( 0.002 ms): pkey/16018 pkey_free(pkey: -1 ) = -1 EINVAL Invalid argument ^C[root@jouet ~]# Or '-e epoll*', '-e *msg*', etc. Combining syscall names with perf events, tracepoints, etc, continues to be valid, i.e. this is possible: # perf probe -L sys_nanosleep 0 SYSCALL_DEFINE2(nanosleep, struct timespec __user *, rqtp, struct timespec __user *, rmtp) { struct timespec64 tu; 5 if (get_timespec64(&tu, rqtp)) 6 return -EFAULT; if (!timespec64_valid(&tu)) 9 return -EINVAL; 11 current->restart_block.nanosleep.type = rmtp ? TT_NATIVE : TT_NONE; 12 current->restart_block.nanosleep.rmtp = rmtp; 13 return hrtimer_nanosleep(&tu, HRTIMER_MODE_REL, CLOCK_MONOTONIC); } # perf probe my_probe="sys_nanosleep:12 rmtp" Added new event: probe:my_probe (on sys_nanosleep:12 with rmtp) You can now use it in all perf tools, such as: perf record -e probe:my_probe -aR sleep 1 # # perf trace -e probe:my_probe/max-stack=5/,*sleep sleep 1 0.427 ( 0.003 ms): sleep/16690 nanosleep(rqtp: 0x7ffefc245090) ... 0.430 ( ): probe:my_probe:(ffffffffbd112923) rmtp=0) sys_nanosleep ([kernel.kallsyms]) do_syscall_64 ([kernel.kallsyms]) return_from_SYSCALL_64 ([kernel.kallsyms]) __nanosleep_nocancel (/usr/lib64/libc-2.25.so) 0.427 (1000.208 ms): sleep/16690 ... [continued]: nanosleep()) = 0 # Cc: Adrian Hunter Cc: Jiri Olsa Cc: Namhyung Kim Cc: Wang Nan Link: http://lkml.kernel.org/n/tip-elycoi8wy6y0w9dkj7ox1mzz@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Add usage of --no-syscalls in man page

2017-04-13T13:54:04Z

perf trace supports --no-syscalls option but it's not listed in the man page. (Though, I see an example using --no-syscalls in EXAMPLES section.) Committer note: The --no-syscalls option tells 'perf trace' not to automagically ask for raw_syscalls:sys_{enter,exit} to then format it in a strace like way. This become more used as 'perf trace' got support for arbitrary events, such as tracepoints, so more and more we use: # perf trace --no-syscalls -e nmi:* 0.000 nmi:nmi_handler:perf_event_nmi_handler() delta_ns: 36649 handled: 1) 0.019 nmi:nmi_handler:nmi_cpu_backtrace_handler() delta_ns: 2907 handled: 0) 0.676 nmi:nmi_handler:perf_event_nmi_handler() delta_ns: 9401 handled: 1) 0.680 nmi:nmi_handler:nmi_cpu_backtrace_handler() delta_ns: 288 handled: 0) 0.701 nmi:nmi_handler:perf_event_nmi_handler() delta_ns: 4977 handled: 1) 0.703 nmi:nmi_handler:nmi_cpu_backtrace_handler() delta_ns: 67 handled: 0) 0.736 nmi:nmi_handler:perf_event_nmi_handler() delta_ns: 8549 handled: 1) ^C# Signed-off-by: Ravi Bangoria Cc: Alexander Shishkin Cc: Alexis Berlemont Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1492063332-5745-1-git-send-email-ravi.bangoria@linux.vnet.ibm.com Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Allow specifying list of syscalls and events in -e/--expr/--event

2017-01-11T19:48:01Z

Makes it easier to specify both events and syscalls (to be formatter strace-like), i.e. previously one would have to do: # perf trace -e nanosleep --event sched:sched_switch usleep 1 Now it is possible to do: # perf trace -e nanosleep,sched:sched_switch usleep 1 0.000 ( 0.021 ms): usleep/17962 nanosleep(rqtp: 0x7ffdedd61ec0) ... 0.021 ( ): sched:sched_switch:usleep:17962 [120] S ==> swapper/1:0 [120]) 0.000 ( 0.066 ms): usleep/17962 ... [continued]: nanosleep()) = 0 # The old style --expr and using both -e and --event continues to work. Cc: Adrian Hunter Cc: David Ahern Cc: Jiri Olsa Cc: Milian Wolff Cc: Namhyung Kim Cc: Wang Nan Link: http://lkml.kernel.org/n/tip-ieg6bakub4657l9e6afn85r4@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Implement --delay

2016-10-24T14:07:43Z

In the perf wiki todo-list[1], there is an entry regarding initial-delay and 'perf trace'; the following small patch tries to fulfill this point. It has been generated against the branch tip/perf/core. It has only been implemented in the "trace__run" case. Ex.: $ sudo strace -- ./perf trace --delay 5 sleep 1 2>&1 ... fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 ioctl(7, PERF_EVENT_IOC_ID, 0x7ffc8fd35718) = 0 ioctl(11, PERF_EVENT_IOC_SET_OUTPUT, 0x7) = 0 fcntl(11, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 ioctl(11, PERF_EVENT_IOC_ID, 0x7ffc8fd35718) = 0 write(6, "\0", 1) = 1 close(6) = 0 nanosleep({0, 5000000}, NULL) = 0 # DELAY OF 5 MS BEFORE ENABLING THE EVENTS ioctl(3, PERF_EVENT_IOC_ENABLE, 0) = 0 ioctl(4, PERF_EVENT_IOC_ENABLE, 0) = 0 ioctl(5, PERF_EVENT_IOC_ENABLE, 0) = 0 ioctl(7, PERF_EVENT_IOC_ENABLE, 0) = 0 ... [1]: https://perf.wiki.kernel.org/index.php/Todo Signed-off-by: Alexis Berlemont Suggested-and-Tested-by: Arnaldo Carvalho de Melo Cc: Alexander Shishkin Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/20161010054328.4028-2-alexis.berlemont@gmail.com [ Add entry to the manpage, cut'n'pasted from stat's and record's ] Signed-off-by: Arnaldo Carvalho de Melo

perf tools: Fix usage of max_stack sysctl

2016-05-20T14:43:56Z

We cannot limit processing stacks from the current value of the sysctl, as we may be processing perf.data files, possibly from other machines. Instead use the old PERF_MAX_STACK_DEPTH, the sysctl default, that can be overriden using --max-stack or equivalent. Cc: Adrian Hunter Cc: Alexander Shishkin Cc: Alexei Starovoitov Cc: Brendan Gregg Cc: David Ahern Cc: Frederic Weisbecker Cc: He Kuang Cc: Jiri Olsa Cc: Masami Hiramatsu Cc: Milian Wolff Cc: Namhyung Kim Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Thomas Gleixner Cc: Vince Weaver Cc: Wang Nan Cc: Zefan Li Fixes: 4cb93446c587 ("perf tools: Set the maximum allowed stack from /proc/sys/kernel/perf_event_max_stack") Link: http://lkml.kernel.org/n/tip-eqeutsr7n7wy0c36z24ytvii@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf tools: Set the maximum allowed stack from /proc/sys/kernel/perf_event_max_stack

2016-04-27T13:29:07Z

There is an upper limit to what tooling considers a valid callchain, and it was tied to the hardcoded value in the kernel, PERF_MAX_STACK_DEPTH (127), now that this can be tuned via a sysctl, make it read it and use that as the upper limit, falling back to PERF_MAX_STACK_DEPTH for kernels where this sysctl isn't present. Cc: Adrian Hunter Cc: Brendan Gregg Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Milian Wolff Cc: Namhyung Kim Cc: Wang Nan Link: http://lkml.kernel.org/n/tip-yjqsd30nnkogvj5oyx9ghir9@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo