kernel/git/stable/linux.git/tools/perf/builtin-trace.c, branch linux-4.3.y

perf trace: Add header with copyright and background info

2015-08-28T17:53:48+00:00

Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-5yqtfs728r1j1u8zmg8ufxwm@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Move vfs_getname storage to per thread area

2015-08-14T16:16:27+00:00

We were storing the vfs_getname payload (i.e. ptr->string) into the trace wide storage area (struct trace), so that we could use the last payload when setting up the fd->pathname per thread tables, oops, not a good idea for multi cpu tracing sessions... Fix it by moving it to the per thread area (struct thread_trace). Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-3j05ttqyaem7kh7oubvr1keo@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Beautify keyctl's option arg

2015-08-12T13:27:03+00:00

8.697 (0.103 ms): pool/2343 keyctl(option: GET_PERSISTENT, arg2: 1000, arg3: 4294967294, arg4: 140703061514067, arg5: 140703692383680) = 1023192809 8.763 (0.049 ms): pool/2343 keyctl(option: SEARCH, arg2: 1023192809, arg3: 140703745767772, arg4: 140703745767832, arg5: 4294967294) = 140224497 8.789 (0.016 ms): pool/2343 keyctl(option: SEARCH, arg2: 140224497, arg3: 140703745767814, arg4: 140703745767900) = 512300257 8.807 (0.011 ms): pool/2343 keyctl(option: READ, arg2: 512300257 ) = 13 8.822 (0.008 ms): pool/2343 keyctl(option: READ, arg2: 512300257, arg3: 140703061514000, arg4: 13 ) = 13 8.837 (0.007 ms): pool/2343 keyctl(option: READ, arg2: 140224497 ) = 4 8.852 (0.009 ms): pool/2343 keyctl(option: READ, arg2: 140224497, arg3: 140703061514000, arg4: 4 ) = 4 8.869 (0.010 ms): pool/2343 keyctl(option: SEARCH, arg2: 140224497, arg3: 140703745767772, arg4: 140703061514032) = -1 ENOKEY Required key not available 8.892 (0.017 ms): pool/2343 keyctl(option: DESCRIBE, arg2: 512300257 ) = 43 8.910 (0.012 ms): pool/2343 keyctl(option: DESCRIBE, arg2: 512300257, arg3: 140703061544384, arg4: 43) = 43 Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-013ab219irsxngyumrf5gp8s@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Use the FD beautifier for socket syscall fds

2015-08-12T13:27:03+00:00

But we really should have something like 'strace -yy' here... Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-eyrt1ypfq68u4ljagyk2nj1i@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Add missing clockid entries

2015-08-12T13:27:02+00:00

We were missing: CLOCK_BOOTTIME, CLOCK_REALTIME_ALARM, CLOCK_BOOTTIME_ALARM, CLOCK_SGI_CYCLE and CLOCK_TAI. Add them. Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Milian Wolff Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-d67rwqtwm9jyenwes98kr0cr@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Associate some more syscall args with the getname beautifier

2015-08-12T13:26:53+00:00

This time using 'trinity' to test these: fchmodat, futimesat, llistxattr, lremovexattr, lstat, mknodat, mq_unlink, stat and vmsplice. Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Milian Wolff Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-a1uqu249nwwh0ixrhm80k4a4@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Add total time column to summary.

2015-08-06T14:29:49+00:00

It is cumbersome to manually calculate the total time spent in a given syscall by multiplying the average value with the number of calls. Instead, we now do this directly inside perf trace. Note that this is also done by 'strace', which even adds a column with relative numbers - something we could do in the future. Example: perf trace -s find /some/folder > /dev/null Summary of events: find (19976), 700123 events, 100.0%, 0.000 msec syscall calls total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- --------- --------- --------- --------- ------ read 4 0.006 0.001 0.002 0.003 27.42% write 8046 9.617 0.001 0.001 0.035 0.56% open 34196 40.384 0.001 0.001 0.071 0.30% close 68375 57.104 0.001 0.001 0.076 0.25% stat 4 0.004 0.001 0.001 0.001 3.14% fstat 34189 27.518 0.001 0.001 0.060 0.34% mmap 13 0.029 0.001 0.002 0.003 10.74% mprotect 6 0.018 0.002 0.003 0.005 17.04% munmap 3 0.014 0.003 0.005 0.006 24.87% brk 87 0.490 0.001 0.006 0.016 6.50% ioctl 3 0.004 0.001 0.001 0.003 36.39% access 1 0.004 0.004 0.004 0.004 0.00% uname 1 0.001 0.001 0.001 0.001 0.00% getdents 68393 143.600 0.001 0.002 0.187 0.95% fchdir 68371 56.980 0.001 0.001 0.111 0.39% arch_prctl 1 0.001 0.001 0.001 0.001 0.00% openat 34184 41.737 0.001 0.001 0.102 0.41% newfstatat 34184 41.180 0.001 0.001 0.064 0.34% Signed-off-by: Milian Wolff Tested-by: Arnaldo Carvalho de Melo LPU-Reference: 1438853069-5902-1-git-send-email-milian.wolff@kdab.com Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Write to stderr by default

2015-08-05T19:52:23+00:00

Without this patch, it is cumbersome to read the trace output but ignoring the normal, potentially verbose, output of the debuggee. One common example is doing something like the following: perf trace -s find /tmp > /dev/null Without this patch, the trace summary will be lost. Now, it will still be printed at the end. This behavior is also applied by strace. Cc: Milian Wolff Cc: David Ahern Link: http://lkml.kernel.org/n/tip-tqnks6y2cnvm5f9g2dsfr7zl@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo

perf trace: Use vfs_getname syscall arg beautifier in more syscalls

2015-08-05T15:50:11+00:00

Those were covered and tested in this cset: access, chdir, chmod, chown, chroot, creat, getxattr, inotify_add_watch, lchown, lgetxattr, listxattr, lsetxattr, mkdir, mkdirat, mknod, rmdir, faccessat, newfstatat, openat, readlink, readlinkat, removexattr, setxattr, statfs, swapon, swapoff, truncate, unlinkat, utime, utimes, utimensat. E.g.: # trace -e statfs,access,mkdir mkdir /tmp/bla 0.285 (0.020 ms): mkdir/2799 access(filename: /etc/ld.so.preload, mode: R ) = -1 ENOENT No such file or directory 1.070 (0.032 ms): mkdir/2799 statfs(pathname: /sys/fs/selinux, buf: 0x7ffeafbdc930) = 0 1.087 (0.013 ms): mkdir/2799 statfs(pathname: /sys/fs/selinux, buf: 0x7ffeafbdc820) = 0 1.189 (0.014 ms): mkdir/2799 access(filename: /etc/selinux/config ) = 0 1.905 (0.610 ms): mkdir/2799 mkdir(pathname: /tmp/bla, mode: 511 ) = 0 # Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Milian Wolff Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-wbqtnlktquun3wtpjdz3okul@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo and an empty message aborts the commit.

perf trace: Deref sys_enter pointer args with contents from probe:vfs_getname

2015-08-05T13:52:45+00:00

To work like strace and dereference syscall pointer args we need to insert probes (or tracepoints) right after we copy those bytes from userspace. Since we're formatting the syscall args at raw_syscalls:sys_enter time, we need to have a formatter that just stores the position where, later, when we get the probe:vfs_getname, we can insert the pointer contents. Now, if a probe:vfs_getname with this format is in place: # perf probe -l probe:vfs_getname (on getname_flags:72@/home/git/linux/fs/namei.c with pathname) That was, in this case, put in place with: # perf probe 'vfs_getname=getname_flags:72 pathname=filename:string' Added new event: probe:vfs_getname (on getname_flags:72 with pathname=filename:string) You can now use it in all perf tools, such as: perf record -e probe:vfs_getname -aR sleep 1 # Then 'perf trace' will notice that and do the pointer -> contents expansion: # trace -e open touch /tmp/bla 0.165 (0.010 ms): touch/17752 open(filename: /etc/ld.so.cache, flags: CLOEXEC) = 3 0.195 (0.011 ms): touch/17752 open(filename: /lib64/libc.so.6, flags: CLOEXEC) = 3 0.512 (0.012 ms): touch/17752 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC) = 3 0.582 (0.012 ms): touch/17752 open(filename: /tmp/bla, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: 438) = 3 # Roughly equivalent to strace's output: # strace -rT -e open touch /tmp/bla 0.000000 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000039> 0.000317 open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 <0.000102> 0.001461 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 <0.000072> 0.000405 open("/tmp/bla", O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK, 0666) = 3 <0.000055> 0.000641 +++ exited with 0 +++ # Now we need to either look for at all syscalls that are marked as pointers and have some well known names ("filename", "pathname", etc) and set the arg formatter to the one used for the "open" syscall in this patch. This implementation works for syscalls with just a string being copied from userspace, for matching syscalls with more than one string being copied via the same probe/trace point (vfs_getname) we need to extend the vfs_getname probe spec to include the pointer too, but there are some problems with that in 'perf probe' or the kernel kprobes code, need to investigate before considering supporting multiple strings per syscall. Cc: Adrian Hunter Cc: Borislav Petkov Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Milian Wolff Cc: Namhyung Kim Cc: Stephane Eranian Link: http://lkml.kernel.org/n/tip-xvuwx6nuj8cf389kf9s2ue2s@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo