summaryrefslogtreecommitdiff
path: root/tools/perf/builtin-trace.c
AgeCommit message (Collapse)Author
2015-10-29perf trace: Add cmd string table to decode sys_bpf first argArnaldo Carvalho de Melo
# perf trace -e bpf perf record -e /tmp/foo.o -a 362.779 (0.130 ms): perf/3451 bpf(cmd: PROG_LOAD, uattr: 0x7ffe9a6825d0, size: 48) = 3 Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Alexei Starovoitov <ast@plumgrid.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-2b0nknu53baz9e0wj4thcdd8@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-09-15perf evsel: Propagate error info from tp_formatJiri Olsa
Propagate error info from tp_format via ERR_PTR to get it all the way down to the parse-event.c tracepoint adding routines. Following functions now return pointer with encoded error: - tp_format - trace_event__tp_format - perf_evsel__newtp_idx - perf_evsel__newtp This affects several other places in perf, that cannot use pointer check anymore, but must utilize the err.h interface, when getting error information from above functions list. Signed-off-by: Jiri Olsa <jolsa@kernel.org> Cc: David Ahern <dsahern@gmail.com> Cc: Matt Fleming <matt@codeblueprint.co.uk> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Raphael Beamonte <raphael.beamonte@gmail.com> Link: http://lkml.kernel.org/r/1441615087-13886-5-git-send-email-jolsa@kernel.org [ Add two missing ERR_PTR() and one IS_ERR() ] Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-09-04tools lib api fs: Move debugfs__strerror_open into tracing_path.c objectJiri Olsa
Moving debugfs__strerror_open out of api/fs/debugfs.c, because it's not debugfs specific. It'll be changed to consider tracefs mount as well in following patches. Renaming it into tracing_path__strerror_open_tp to fit into the namespace. No functional change is intended. Signed-off-by: Jiri Olsa <jolsa@kernel.org> Reviewed-by: Matt Fleming <matt.fleming@intel.com> Cc: Raphael Beamonte <raphael.beamonte@gmail.com> Cc: David Ahern <dsahern@gmail.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Steven Rostedt <rostedt@goodmis.org> Link: http://lkml.kernel.org/r/1441180605-24737-6-git-send-email-jolsa@kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-28perf trace: Add header with copyright and background infoArnaldo Carvalho de Melo
Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-5yqtfs728r1j1u8zmg8ufxwm@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-14perf trace: Move vfs_getname storage to per thread areaArnaldo Carvalho de Melo
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 <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-3j05ttqyaem7kh7oubvr1keo@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-12perf trace: Beautify keyctl's option argArnaldo Carvalho de Melo
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 <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-013ab219irsxngyumrf5gp8s@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-12perf trace: Use the FD beautifier for socket syscall fdsArnaldo Carvalho de Melo
But we really should have something like 'strace -yy' here... Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-eyrt1ypfq68u4ljagyk2nj1i@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-12perf trace: Add missing clockid entriesArnaldo Carvalho de Melo
We were missing: CLOCK_BOOTTIME, CLOCK_REALTIME_ALARM, CLOCK_BOOTTIME_ALARM, CLOCK_SGI_CYCLE and CLOCK_TAI. Add them. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <milian.wolff@kdab.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-d67rwqtwm9jyenwes98kr0cr@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-12perf trace: Associate some more syscall args with the getname beautifierArnaldo Carvalho de Melo
This time using 'trinity' to test these: fchmodat, futimesat, llistxattr, lremovexattr, lstat, mknodat, mq_unlink, stat and vmsplice. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <milian.wolff@kdab.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-a1uqu249nwwh0ixrhm80k4a4@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-06perf trace: Add total time column to summary.Milian Wolff
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 <milian.wolff@kdab.com> Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com> LPU-Reference: 1438853069-5902-1-git-send-email-milian.wolff@kdab.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-05perf trace: Write to stderr by defaultMilian Wolff
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 <milian.wolff@kdab.com> Cc: David Ahern <dsahern@gmail.com> Link: http://lkml.kernel.org/n/tip-tqnks6y2cnvm5f9g2dsfr7zl@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-05perf trace: Use vfs_getname syscall arg beautifier in more syscallsArnaldo Carvalho de Melo
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 <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <mail@milianw.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-wbqtnlktquun3wtpjdz3okul@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> and an empty message aborts the commit.
2015-08-05perf trace: Deref sys_enter pointer args with contents from probe:vfs_getnameArnaldo Carvalho de Melo
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 <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <mail@milianw.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-xvuwx6nuj8cf389kf9s2ue2s@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-05perf trace: Use a constant for the syscall formatting bufferArnaldo Carvalho de Melo
We were using it as a magic number, 1024, fix that. Eventually we need to stop doing it per line, and do it per arg, traversing the args at output time, to avoid the memmove() calls that will be used in the next cset to replace pointers present at raw_syscalls:sys_enter time with its contents that appear at probe:vfs_getname time, before raw_syscalls:sys_exit time. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <mail@milianw.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-4sz3wid39egay1pp8qmbur4u@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-05perf trace: Remember if the vfs_getname tracepoint/kprobe is in placeArnaldo Carvalho de Melo
So that we can later decide if we will store where to expand the pathname once we are handling vfs_getname or if we should instead just go on and straight away print the pointer. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <mail@milianw.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-ytxk5s5jpc50wahffmlxgxuw@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-08-05perf trace: Do not show syscall tracepoint filter in the --no-syscalls caseArnaldo Carvalho de Melo
We were accessing trace->syscalls.events members even when that struct wasn't initialized, i.e. --no-syscalls was specified on the command line, fix it to show that, still in debug mode, when we have an event qualifier list, i.e. when we actually are doing subset syscall tracing. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <mail@milianw.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Fixes: 19867b6186f3 ("perf trace: Use event filters for the event qualifier list") Link: http://lkml.kernel.org/n/tip-7980ym6vujgh3yiai0cqzc88@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-29perf python: Remove dependency on 'machine' methodsArnaldo Carvalho de Melo
The python binding still doesn't provide symbol resolving facilities, but the recent addition of the trace_event__register_resolver() function made it add as a dependency the machine__resolve_kernel_addr() method, that in turn drags all the symbol resolving code. The problem: [root@zoo ~]# perf test -v python 17: Try 'import perf' in python, checking link problems : --- start --- test child forked, pid 6853 Traceback (most recent call last): File "<stdin>", line 1, in <module> ImportError: /tmp/build/perf/python/perf.so: undefined symbol: machine__resolve_kernel_addr test child finished with -1 ---- end ---- Try 'import perf' in python, checking link problems: FAILED! [root@zoo ~]# Fix it by requiring this function to receive the resolver as a parameter, just like pevent_register_function_resolver(), i.e. do not explicitely refer to an object file not included in tools/perf/util/python-ext-sources. [root@zoo ~]# perf test python 17: Try 'import perf' in python, checking link problems : Ok [root@zoo ~]# Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Fixes: c3168b0db93a ("perf symbols: Provide libtraceevent callback to resolve kernel symbols") Link: http://lkml.kernel.org/n/tip-vxlhh95v2em9zdbgj3jm7xi5@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-23perf trace: Provide libtracevent with a kernel symbol resolverArnaldo Carvalho de Melo
So that beautifiers wanting to resolve kernel function addresses to names can do its work, now, for instance, the 'timer' tracepoints beautifiers works with 'perf trace', see the "function=tick..." part: # perf trace --event timer:hrtimer_start <SNIP> 0.000 timer:hrtimer_start:hrtimer=0xffff88026f3101c0 function=tick_sched_timer/0x0 expires=52098339000000 softexpires=52098339000000) 0.003 timer:hrtimer_start:hrtimer=0xffff88026f3101c0 function=tick_sched_timer/0x0 expires=52098339000000 softexpires=52098339000000) <SNIP> Reported-by: Thomas Gleixner <tglx@linutronix.de> Acked-by: David Ahern <dsahern@gmail.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Cc: Steven Rostedt <rostedt@goodmis.org> Link: http://lkml.kernel.org/n/tip-n4i0hxpbl1tnleiqkok47fw2@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-20perf trace: Support 'strace' syscall event groupsArnaldo Carvalho de Melo
I.e.: $ cat ~/share/perf-core/strace/groups/file access chmod creat execve faccessat getcwd lstat mkdir open openat quotactl readlink rename rmdir stat statfs symlink unlink $ Then, on a quiet desktop, try running this and then moving your mouse to see the deluge of mouse related activity: # 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 # # trace --ev probe:vfs_getname --filter-pids 2232 -e file 0.042 (0.042 ms): mousetweaks/2235 open(filename: 0x14e3910, mode: 438 ) ... 0.042 ( ): probe:vfs_getname:(ffffffff812230bc) pathname="/home/acme/.icons/Adwaita/cursors/xterm") 0.100 (0.100 ms): mousetweaks/2235 ... [continued]: open()) = -1 ENOENT No such file or directory 0.142 (0.018 ms): mousetweaks/2235 open(filename: 0x14c3c10, mode: 438 ) ... 0.142 ( ): probe:vfs_getname:(ffffffff812230bc) pathname="/home/acme/.icons/Adwaita/index.theme") 0.192 (0.069 ms): mousetweaks/2235 ... [continued]: open()) = -1 ENOENT No such file or directory 0.230 (0.017 ms): mousetweaks/2235 open(filename: 0x14c3c10, mode: 438 ) ... 0.230 ( ): probe:vfs_getname:(ffffffff812230bc) pathname="/usr/share/icons/Adwaita/cursors/xterm") 0.253 (0.041 ms): mousetweaks/2235 ... [continued]: open()) = 14 0.459 (0.008 ms): mousetweaks/2235 open(filename: 0x14e3910, mode: 438 ) ... 0.459 ( ): probe:vfs_getname:(ffffffff812230bc) pathname="/home/acme/.icons/Adwaita/cursors/left_side") 0.468 (0.017 ms): mousetweaks/2235 ... [continued]: open()) = -1 ENOENT No such file or directory Need to combine that raw_syscalls:sys_enter(open) + probe:vfs_getname + raw_syscalls:sys_exit(open) sequence... Now, if you're bored, please write some more syscall groups, like the ones in 'strace' and send it our way :-) Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Milian Wolff <mail@milianw.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-a42xklu59lcbxp7bbnic74a8@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-20perf strlist: Make dupstr be the default and part of an extensible config parmArnaldo Carvalho de Melo
So that we can pass more info to strlist__new() without having to change its function signature, just adding entries to the strlist_config struct with sensible defaults for when those fields are not specified. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-5uaaler4931i0s9sedxjquhq@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-06perf trace: Use event filters for the event qualifier listArnaldo Carvalho de Melo
We use raw_syscalls:sys_{enter,exit} events to show the syscalls, but were using a rather lazy/inneficient way to implement our 'strace -e' equivalent: filter out after reading the events in the ring buffer. Deflect more work to the kernel by appending a filter expression for that, that, together with the pid list, that is always present, if only to filter the tracer itself, reduces pressure on the ring buffer and otherwise use infrastructure already in place in the kernel to do early filtering. If we use it with -v we can see the filter passed to the kernel, for instance, for this contrieved case: # trace -v -e \!open,close,write,poll,recvfrom,select,recvmsg,writev,sendmsg,read,futex,epoll_wait,ioctl,eventfd --filter-pids 2189,2566,1398,2692,4475,4532 <SNIP> (common_pid != 2514 && common_pid != 1398 && common_pid != 2189 && common_pid != 2566 && common_pid != 2692 && common_pid != 4475 && common_pid != 4532) && (id != 3 && id != 232 && id != 284 && id != 202 && id != 16 && id != 2 && id != 7 && id != 0 && id != 45 && id != 47 && id != 23 && id != 46 && id != 1 && id != 20) 0.011 (0.011 ms): caribou/2295 eventfd2(flags: CLOEXEC|NONBLOCK) = 18 16.946 (0.019 ms): caribou/2295 eventfd2(flags: CLOEXEC|NONBLOCK) = 18 38.598 (0.167 ms): chronyd/794 socket(family: INET, type: DGRAM ) = 4 38.603 (0.002 ms): chronyd/794 fcntl(fd: 4<socket:[239307]>, cmd: GETFD) = 0 38.605 (0.001 ms): chronyd/794 fcntl(fd: 4<socket:[239307]>, cmd: SETFD, arg: 1) = 0 ^C # Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-ti2tg18atproqpguc2moinp6@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-06perf evlist: Make perf_evlist__set_filter use perf_evsel__set_filterArnaldo Carvalho de Melo
Instead of calling perf_evsel__apply_filter straight away, so that we can, in the next patches, expand the filter with more conditions before actually calling the ioctl to pass the end result filter to the kernel. Now we need to call perf_evlist__apply_filters() after the filter is completely setup, i.e. do the ioctl calls. The perf_evlist__apply_filters() method was already in place, because that is the model for the other tools that receives filters in the command line: go on setting then in the evsel->filter and only at the end, after parsing the whole command line, apply them. We get, as a bonus, a more expressive message that states which event, if any, failed to have the filter applied to, with an error message stating what happened. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-f429pgz75ryz7tpe6v74etre@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-06perf trace: Store the syscall ids for the event qualifiers in a tableArnaldo Carvalho de Melo
That we will use to set a filter on raw_syscalls:sys_{enter,exit} events. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-2acxrcxyu7tlolrfilpty38y@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-07-06perf trace: Remember what are the syscalls tracepoint evselsArnaldo Carvalho de Melo
We will need to set filters on then. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-u8hpgjpf3w8o1prnnjnwegwf@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-06-26perf trace: Validate syscall list passed via -e argumentArnaldo Carvalho de Melo
The 'trace' tool was accepting any names passed and just looking if syscalls returned via the raw_syscalls:* tracepoints were in that list, leading to it accepting perf events and then never finding any, as those are not valid syscall names, confusing users. Fix it by checking each entry in the list using audit_name_to_syscall, telling the user which entries are invalid and suggesting where to look for valid syscall names. E.g: [root@zoo ~]# trace -e open,foo,bar,close,baz Error: Invalid syscall bar, baz, foo Hint: try 'perf list syscalls:sys_enter_*' Hint: and: 'man syscalls' [root@zoo ~]# Reported-by: Flavio Leitner <fbl@redhat.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Link: http://lkml.kernel.org/n/tip-4g1i3m1z6fzsrznn2umi02wa@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-06-23perf thread_map: Don't access the array entries directlyJiri Olsa
Instead provide a method to set the array entries, and another to access the contents. Signed-off-by: Jiri Olsa <jolsa@kernel.org> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Andi Kleen <ak@linux.intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/r/1435012588-9007-2-git-send-email-jolsa@kernel.org [ Split providing the set/get accessors from transforming the entries structs ] Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-06-19perf tools: Configurable per thread proc map processing time outKan Liang
The time out to limit the individual proc map processing was hard code to 500ms. This patch introduce a new option --proc-map-timeout to make the time limit configurable. Signed-off-by: Kan Liang <kan.liang@intel.com> Cc: Andi Kleen <andi@firstfloor.org> Cc: David Ahern <dsahern@gmail.com> Cc: Ying Huang <ying.huang@intel.com> Link: http://lkml.kernel.org/r/1434549071-25611-2-git-send-email-kan.liang@intel.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-06-11trace: Beautify perf_event_open syscallArnaldo Carvalho de Melo
Syswide tracing and then running 'stat' and 'trace': $ perf trace -e perf_event_open 1034.649 (0.019 ms): perf/6133 perf_event_open(attr_uptr: 0x36f0360, pid: 16134, cpu: -1, group_fd: -1, flags: FD_CLOEXEC) = -1 EINVAL Invalid argument 1034.670 (0.008 ms): perf/6133 perf_event_open(attr_uptr: 0x36f0360, pid: 16134, cpu: -1, group_fd: -1) = -1 EINVAL Invalid argument 1034.681 (0.007 ms): perf/6133 perf_event_open(attr_uptr: 0x36f0360, pid: 16134, cpu: -1, group_fd: -1) = -1 EINVAL Invalid argument 1034.692 (0.007 ms): perf/6133 perf_event_open(attr_uptr: 0x36f0360, pid: 16134, cpu: -1, group_fd: -1) = -1 EINVAL Invalid argument 9986.983 (0.014 ms): trace/6139 perf_event_open(attr_uptr: 0x7ffd9c629320, pid: -1, group_fd: -1, flags: FD_CLOEXEC) = 3 9987.026 (0.016 ms): trace/6139 perf_event_open(attr_uptr: 0x37c7e70, pid: -1, group_fd: -1, flags: FD_CLOEXEC) = 3 9987.041 (0.008 ms): trace/6139 perf_event_open(attr_uptr: 0x37c7e70, pid: -1, group_fd: -1, flags: FD_CLOEXEC) = 3 9987.489 (0.092 ms): trace/6139 perf_event_open(attr_uptr: 0x3795ee0, pid: 16140, group_fd: -1, flags: FD_CLOEXEC) = 3 9987.536 (0.044 ms): trace/6139 perf_event_open(attr_uptr: 0x3795ee0, pid: 16140, cpu: 1, group_fd: -1, flags: FD_CLOEXEC) = 4 9987.580 (0.041 ms): trace/6139 perf_event_open(attr_uptr: 0x3795ee0, pid: 16140, cpu: 2, group_fd: -1, flags: FD_CLOEXEC) = 5 9987.620 (0.037 ms): trace/6139 perf_event_open(attr_uptr: 0x3795ee0, pid: 16140, cpu: 3, group_fd: -1, flags: FD_CLOEXEC) = 7 9987.659 (0.035 ms): trace/6139 perf_event_open(attr_uptr: 0x37975d0, pid: 16140, group_fd: -1, flags: FD_CLOEXEC) = 8 9987.692 (0.031 ms): trace/6139 perf_event_open(attr_uptr: 0x37975d0, pid: 16140, cpu: 1, group_fd: -1, flags: FD_CLOEXEC) = 9 9987.727 (0.032 ms): trace/6139 perf_event_open(attr_uptr: 0x37975d0, pid: 16140, cpu: 2, group_fd: -1, flags: FD_CLOEXEC) = 10 9987.761 (0.031 ms): trace/6139 perf_event_open(attr_uptr: 0x37975d0, pid: 16140, cpu: 3, group_fd: -1, flags: FD_CLOEXEC) = 11 Need to intercept perf_copy_attr() with a kprobe or with eBPF... Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Link: http://lkml.kernel.org/n/tip-njb105hab2i3t5dexym9lskl@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-05-14perf trace: Fix the build on older distrosArnaldo Carvalho de Melo
Such as RHEL5, where CLOEXEC, NONBLOCK flags are not present, use a ifdef+define approach instead to make it build on all distros. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Cc: Vinson Lee <vlee@twitter.com> Link: http://lkml.kernel.org/n/tip-pioazikk9d9oz5qdeor3eldu@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-05-12perf trace: Removed duplicated NULL testHe Kuang
No need to test trace.evlist against NULL twice. Signed-off-by: He Kuang <hekuang@huawei.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/r/1431347316-30401-2-git-send-email-hekuang@huawei.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-05-11Merge branch 'perf/urgent' into perf/core, to resolve conflictsIngo Molnar
Conflicts: tools/perf/builtin-kmem.c Signed-off-by: Ingo Molnar <mingo@kernel.org>
2015-05-08perf machine: Protect the machine->threads with a rwlockArnaldo Carvalho de Melo
In addition to using refcounts for the struct thread lifetime management, we need to protect access to machine->threads from concurrent access. That happens in 'perf top', where a thread processes events, inserting and deleting entries from that rb_tree while another thread decays hist_entries, that end up dropping references and ultimately deleting threads from the rb_tree and releasing its resources when no further hist_entry (or other data structures, like in 'perf sched') references it. So the rule is the same for refcounts + protected trees in the kernel, get the tree lock, find object, bump the refcount, drop the tree lock, return, use object, drop the refcount if no more use of it is needed, keep it if storing it in some other data structure, drop when releasing that data structure. I.e. pair "t = machine__find(new)_thread()" with a "thread__put(t)", and "perf_event__preprocess_sample(&al)" with "addr_location__put(&al)". The addr_location__put() one is because as we return references to several data structures, we may end up adding more reference counting for the other data structures and then we'll drop it at addr_location__put() time. Acked-by: David Ahern <dsahern@gmail.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-bs9rt4n0jw3hi9f3zxyy3xln@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-29perf trace: Clarify that -e is about syscalls, not perf events in generalArnaldo Carvalho de Melo
This comes from the desire of having -e/--expr to have the same meaning as for 'strace', while other perf tools use it for --event, which 'trace' honours, i.e. all perf tools have --event in common, but trace uses -e for strace's --expr. Clarify it in the --help output. Reported-by: David Ahern <dsahern@gmail.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-5j94bcsdmcbeu2xthnzsj60d@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-29perf trace: Fix --filter-pids OPTION descriptionArnaldo Carvalho de Melo
Cut't'paste error, fix it. Reported-by: David Ahern <dsahern@gmail.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-26abqh0wg9dci3fqcppyrpxy@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-23perf trace: Disable events and drain events when forked workload endsArnaldo Carvalho de Melo
We were not checking in the inner event processing loop if the forked workload had finished, which, on a busy system, may make it take a long time trying to drain events, entering a seemingly neverending loop, waiting for the system to get idle enough to make it drain the buffers. Fix it by disabling the events when 'done' is true, in the inner loop, to start draining what is in the buffers. Now: [root@ssdandy ~]# time trace --filter-pids 14003 -a sleep 1 | tail 996.748 ( 0.002 ms): sh/30296 rt_sigprocmask(how: SETMASK, nset: 0x7ffc83418160, sigsetsize: 8) = 0 996.751 ( 0.002 ms): sh/30296 rt_sigprocmask(how: BLOCK, nset: 0x7ffc834181f0, oset: 0x7ffc83418270, sigsetsize: 8) = 0 996.755 ( 0.002 ms): sh/30296 rt_sigaction(sig: INT, act: 0x7ffc83417f50, oact: 0x7ffc83417ff0, sigsetsize: 8) = 0 1004.543 ( 0.362 ms): tail/30198 ... [continued]: read()) = 4096 1004.548 ( 7.791 ms): sh/30296 wait4(upid: -1, stat_addr: 0x7ffc834181a0) ... 1004.975 ( 0.427 ms): tail/30198 read(buf: 0x7633f0, count: 8192) = 4096 1005.390 ( 0.410 ms): tail/30198 read(buf: 0x765410, count: 8192) = 4096 1005.743 ( 0.348 ms): tail/30198 read(buf: 0x7633f0, count: 8192) = 4096 1006.197 ( 0.449 ms): tail/30198 read(buf: 0x765410, count: 8192) = 4096 1006.492 ( 0.290 ms): tail/30198 read(buf: 0x7633f0, count: 8192) = 4096 real 0m1.219s user 0m0.704s sys 0m0.331s [root@ssdandy ~]# Reported-by: Michael Petlan <mpetlan@redhat.com> Suggested-by: Jiri Olsa <jolsa@redhat.com> Acked-by: Jiri Olsa <jolsa@redhat.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-p6kpn1b26qcbe47pufpw0tex@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-23perf trace: Enable events when doing system wide tracing and starting a workloadArnaldo Carvalho de Melo
commit f7aa222ff397 Author: Arnaldo Carvalho de Melo <acme@redhat.com> Date: Tue Feb 3 13:25:39 2015 -0300 perf trace: No need to enable evsels for workload started from perf The assumption was that whenever a workload is specified, the attr.enable_on_exec evsel flag would be set, but that is not happening when perf_record_opts.system_wide is set, for instance That resulted in both perf_evlist__enable() and attr.enable_on_exec being not called/set, which made the events to remain disabled while the workload runs, producing no output. Fix it, by calling perf_evlist__enable() in the 'trace' tool when forking and not targetting a workload started from trace v2: Test against !target__none(), as suggested by Namhyung Kim, that is what is used in perf_evsel__config() when deciding if the attr.enable_on_exec flag to be set. More work is needed to cover other cases such as opts->initial_delay. Acked-by: Jiri Olsa <jolsa@redhat.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-27z7169pvfxgj8upic636syv@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-04-02perf trace: Support using -f to override perf.data file ownershipYunlong Song
Enable perf trace to use perf.data when it is not owned by current user or root. Example: # perf trace record ls # chown Yunlong.Song:Yunlong.Song perf.data # ls -al perf.data -rw------- 1 Yunlong.Song Yunlong.Song 4153101 Apr 2 15:28 perf.data # id uid=0(root) gid=0(root) groups=0(root),64(pkcs11) Before this patch: # perf trace -i perf.data File perf.data not owned by current user or root (use -f to override) # perf trace -i perf.data -f Error: unknown switch `f' usage: perf trace [<options>] [<command>] or: perf trace [<options>] -- <command> [<options>] or: perf trace record [<options>] [<command>] or: perf trace record [<options>] -- <command> [<options>] --event <event> event selector. use 'perf list' to list available events --comm show the thread COMM next to its id --tool_stats show tool stats -e, --expr <expr> list of events to trace -o, --output <file> output file name -i, --input <file> Analyze events in file -p, --pid <pid> trace events on existing process id -t, --tid <tid> trace events on existing thread id --filter-pids <float> ... As shown above, the -f option does not work at all. After this patch: # perf trace -i perf.data File perf.data not owned by current user or root (use -f to override) # perf trace -i perf.data -f 0.056 ( 0.002 ms): ls/47325 brk( ... 0.108 ( 0.018 ms): ls/47325 mmap(len: 4096, prot: READ|WRITE, ... 0.145 ( 0.013 ms): ls/47325 access(filename: 0x7f31259a0eb0, ... 0.172 ( 0.008 ms): ls/47325 open(filename: 0x7fffeb9a0d00, ... 0.180 ( 0.004 ms): ls/47325 stat(filename: 0x7fffeb9a0d00, ... 0.185 ( 0.004 ms): ls/47325 open(filename: 0x7fffeb9a0d00, ... 0.189 ( 0.003 ms): ls/47325 stat(filename: 0x7fffeb9a0d00, ... 0.195 ( 0.004 ms): ls/47325 open(filename: 0x7fffeb9a0d00, ... 0.199 ( 0.002 ms): ls/47325 stat(filename: 0x7fffeb9a0d00, ... 0.205 ( 0.004 ms): ls/47325 open(filename: 0x7fffeb9a0d00, ... 0.211 ( 0.004 ms): ls/47325 stat(filename: 0x7fffeb9a0d00, ... 0.220 ( 0.007 ms): ls/47325 open(filename: 0x7f312599e8ff, ... ... ... As shown above, the -f option really works now. Signed-off-by: Yunlong Song <yunlong.song@huawei.com> Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/r/1427982439-27388-10-git-send-email-yunlong.song@huawei.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-03-26perf trace: Fix syscall enter formatting bugArnaldo Carvalho de Melo
commit e596663ebb28a068f5cca57f83285b7b293a2c83 Author: Arnaldo Carvalho de Melo <acme@redhat.com> Date: Fri Feb 13 13:22:21 2015 -0300 perf trace: Handle multiple threads better wrt syscalls being intermixed Introduced a bug where it considered the number of bytes output directly to the output file when formatting the syscall entry buffer that is stored to be finally printed at syscall exit, ending up leaving garbage at the start of syscalls that appeared while another syscall was being processed, in another thread. Fix it. Example of garbage in the output before this patch: 4280.102 ( 0.000 ms): lsmd/763 ... [continued]: select()) = 0 Timeout 4280.107 (275.250 ms): tuned/852 select(tvp: 0x7f41f7ffde50 ) ... 4280.109 ( 0.002 ms): lsmd/763 Xl�� ) = -10 4639.197 ( 0.000 ms): systemd-journa/542 ... [continued]: epoll_wait()) = 1 4639.202 (359.088 ms): lsmd/763 select(n: 6, inp: 0x7ffff21daad0, tvp: 0x7ffff21daac0) ... 4639.207 ( 0.005 ms): systemd-journa/542 Hn�� ) = 106 4639.221 ( 0.002 ms): systemd-journa/542 uname(name: 0x7ffdbaed8e00) = 0 4639.271 ( 0.008 ms): systemd-journa/542 ftruncate(fd: 11</run/log/journal/60cd52417cf440a4a80107518bbd3c20/system.journal>, length: 50331648) = 0 Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-9ckfe8mvsedgkg6y80gz1ul8@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-03-21perf trace: Handle legacy syscalls tracepointsArnaldo Carvalho de Melo
Currently the code skips the first field with the expectation that it is 'nr'. But older kernels do not have the 'nr' field: field:int nr; offset:8; size:4; signed:1; Change perf-trace to drop the field if it exists after parsing the format file. This fixes the off-by-one problem with older kernels (e.g., RHEL6). e.g, perf-trace shows this for write: 1.515 ( 0.006 ms): dd/4245 write(buf: 2</dev/pts/0>, count: 140733837536224 ) = 26 where 2 is really the fd, the huge number is really the buf address, etc. With this patch you get the more appropriate: 1.813 ( 0.003 ms): dd/6330 write(fd: 2</dev/pts/0>, buf: 0x7fff22fc81f0, count: 25) = 25 Based-on-a-patch-by: David Ahern <dsahern@gmail.com> Acked-by: David Ahern <dsahern@gmail.com> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-gvpdave4u2yq2jnzbcdznpvf@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-03-21perf trace: Fix summary_only optionDavid Ahern
The intent of the -s/--summary-only option is to just show a summary of the system calls and statistics without any of the individual events. Commit e596663ebb2 broke that by showing the interrupted lines: perf trace -i perf.data -s ... 0.741 ( 0.000 ms): sleep/31316 fstat(fd: 4, statbuf: 0x7ffc75ceb830 ) ... 0.744 ( 0.000 ms): sleep/31316 mmap(len: 100244, prot: READ, flags: PRIVATE, fd: 4 ) ... 0.747 ( 0.000 ms): perf/31315 write(fd: 3, buf: 0x7d4bb0, count: 8 ) ... ... Fix by checking for the summary only option. Signed-off-by: David Ahern <dsahern@gmail.com> Link: http://lkml.kernel.org/r/1426789383-19023-1-git-send-email-dsahern@gmail.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-03-19perf tools: Add the bash completion for listing subsubcommands of perf traceYunlong Song
The bash completion does not support listing subsubcommands for 'perf trace <TAB>', so fix it. Example: Before this patch: $ perf trace <TAB> $ As shown above, the subsubcommands of perf trace does not come out. After this patch: $ perf trace <TAB> record As shown above, the subsubcommands of perf trace can come out now. Signed-off-by: Yunlong Song <yunlong.song@huawei.com> Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/r/1426685758-25488-13-git-send-email-yunlong.song@huawei.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-03-11perf ordered_events: Shorten function signaturesArnaldo Carvalho de Melo
By keeping pointers to machines, evlist and tool in ordered_events. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-0c6huyaf59mqtm2ek9pmposl@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-03-03perf tools: Reference count struct threadArnaldo Carvalho de Melo
We need to do that to stop accumulating entries in the dead_threads linked list, i.e. we were keeping references to threads in struct hists that continue to exist even after a thread exited and was removed from the machine threads rbtree. We still keep the dead_threads list, but just for debugging, allowing us to iterate at any given point over the threads that still are referenced by things like struct hist_entry. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-3ejvfyed0r7ue61dkurzjux4@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-02-26perf trace: Fix SIGBUS failures due to misaligned accessesDavid Ahern
On Sparc64 perf-trace is failing in many spots due to extended load instructions being used on misaligned accesses. (gdb) run trace ls Starting program: /tmp/perf/perf trace ls [Thread debugging using libthread_db enabled] Detaching after fork from child process 169460. <ls output removed> Program received signal SIGBUS, Bus error. 0x000000000014f4dc in tp_field__u64 (field=0x4cc700, sample=0x7feffffa098) at builtin-trace.c:61 warning: Source file is more recent than executable. 61 TP_UINT_FIELD(64); (gdb) bt 0 0x000000000014f4dc in tp_field__u64 (field=0x4cc700, sample=0x7feffffa098) at builtin-trace.c:61 1 0x0000000000156ad4 in trace__sys_exit (trace=0x7feffffc268, evsel=0x4cc580, event=0xfffffc0104912000, sample=0x7feffffa098) at builtin-trace.c:1701 2 0x0000000000158c14 in trace__run (trace=0x7feffffc268, argc=1, argv=0x7fefffff360) at builtin-trace.c:2160 3 0x000000000015b78c in cmd_trace (argc=1, argv=0x7fefffff360, prefix=0x0) at builtin-trace.c:2609 4 0x0000000000107d94 in run_builtin (p=0x4549c8, argc=2, argv=0x7fefffff360) at perf.c:341 5 0x0000000000108140 in handle_internal_command (argc=2, argv=0x7fefffff360) at perf.c:400 6 0x0000000000108308 in run_argv (argcp=0x7feffffef2c, argv=0x7feffffef20) at perf.c:444 7 0x0000000000108728 in main (argc=2, argv=0x7fefffff360) at perf.c:559 (gdb) p *sample $1 = {ip = 4391276, pid = 169472, tid = 169472, time = 6303014583281250, addr = 0, id = 72082, stream_id = 18446744073709551615, period = 1, weight = 0, transaction = 0, cpu = 73, raw_size = 36, data_src = 84410401, flags = 0, insn_len = 0, raw_data = 0xfffffc010491203c, callchain = 0x0, branch_stack = 0x0, user_regs = {abi = 0, mask = 0, regs = 0x0, cache_regs = 0x7feffffa098, cache_mask = 0}, intr_regs = {abi = 0, mask = 0, regs = 0x0, cache_regs = 0x7feffffa098, cache_mask = 0}, user_stack = { offset = 0, size = 0, data = 0x0}, read = {time_enabled = 0, time_running = 0, {group = {nr = 0, values = 0x0}, one = {value = 0, id = 0}}}} (gdb) p *field $2 = {offset = 16, {integer = 0x14f4a8 <tp_field__u64>, pointer = 0x14f4a8 <tp_field__u64>}} sample->raw_data is guaranteed to not be 8-byte aligned because it is preceded by the size as a u3. So accessing raw data with an extended load instruction causes the SIGBUS. Resolve by using memcpy to a temporary variable of appropriate size. Signed-off-by: David Ahern <david.ahern@oracle.com> Cc: Peter Zijlstra <peterz@infradead.org> Link: http://lkml.kernel.org/r/1424376022-140608-1-git-send-email-david.ahern@oracle.com Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-02-24perf trace: Dump stack on segfaultsArnaldo Carvalho de Melo
[root@ssdandy ~]# perf trace --filter-pids 16348 0.000 ( 0.000 ms): tuned/1027 ... [continued]: select()) = 0 Timeout 793.770 ( 0.000 ms): lsmd/895 ... [continued]: select()) = 0 Timeout 793.775 (793.724 ms): tuned/1027 select(tvp: 0x7f7655556e50) ... perf: Segmentation fault Obtained 15 stack frames. perf(dump_stack+0x2e) [0x4ed330] perf(sighandler_dump_stack+0x2e) [0x4ed40f] /lib64/libc.so.6(+0x35640) [0x7fa2d5b69640] perf() [0x4c2d35] perf(machine__findnew_thread+0x39) [0x4c2ed6] perf() [0x454a4d] perf() [0x455f87] perf() [0x456556] perf(cmd_trace+0xa7e) [0x4580af] perf() [0x4867bd] perf() [0x486a1c] perf() [0x486b68] perf(main+0x23b) [0x486ec9] /lib64/libc.so.6(__libc_start_main+0xf5) [0x7fa2d5b55af5] perf() [0x41bd91] [ root@ssdandy ~]# Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-v38cbxcnm2yf5qn9u4y4n9ab@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-02-22perf trace: Separate routine that handles an event from the one that reads itArnaldo Carvalho de Melo
Because we need to use ordered_events in some cases, so we will need to first have them in a queue, order that queue, and then process the event. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Mike Galbraith <efault@gmx.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-cmkw9zgoh0z4r218957ftp1a@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-02-22perf trace: Introduce --filter-pidsArnaldo Carvalho de Melo
When tracing in X we get event loops due to the tracing activity, i.e. updates to a gnome-terminal that generate syscalls for X.org, etc. To get a more useful view of what is happening, syscall wise, system wide, we need to filter those, like in: # ps ax|egrep '981|2296|1519' | grep -v egrep 981 tty1 Ss+ 5:40 /usr/bin/Xorg :0 -background none ... 1519 ? Sl 2:22 /usr/bin/gnome-shell 2296 ? Sl 4:16 /usr/libexec/gnome-terminal-server # # trace -e write --filter-pids 981,2296,1519 0.385 ( 0.021 ms): goa-daemon/2061 write(fd: 1</dev/null>, buf: 0x7fbeb017b000, count: 136) = 136 0.922 ( 0.014 ms): goa-daemon/2061 write(fd: 1</dev/null>, buf: 0x7fbeb017b000, count: 140) = 140 5006.525 ( 0.029 ms): goa-daemon/2061 write(fd: 1</dev/null>, buf: 0x7fbeb017b000, count: 136) = 136 5007.235 ( 0.023 ms): goa-daemon/2061 write(fd: 1</dev/null>, buf: 0x7fbeb017b000, count: 140) = 140 5177.646 ( 0.018 ms): rtkit-daemon/782 write(fd: 5<anon_inode:[eventfd]>, buf: 0x7f7eea70be88, count: 8) = 8 8314.497 ( 0.004 ms): gsd-locate-poi/2084 write(fd: 5<anon_inode:[eventfd]>, buf: 0x7fffe96af7b0, count: 8) = 8 8314.518 ( 0.002 ms): gsd-locate-poi/2084 write(fd: 5<anon_inode:[eventfd]>, buf: 0x7fffe96af0e0, count: 8) = 8 ^C# When this option is used the tracer pid is also filtered. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Mike Galbraith <efault@gmx.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-f5qmiyy7c0uxdm21ncatpeek@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-02-22perf trace: Filter out the trace pid when no threads are specifiedArnaldo Carvalho de Melo
To avoid tracing the tracer. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Mike Galbraith <efault@gmx.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-shmwd1khzpaobr3i0j1ygapg@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-02-22perf trace: Only insert blank duration bracket when tracing syscallsArnaldo Carvalho de Melo
When printing just events, i.e. '--no-sys --ev some:events' it makes no sense to waste screen space. Before: # trace --no-sys --ev probe:* 84481.704 ( ): probe:vfs_getname:(ffffffff811ed023) pathname="/etc/services") 84481.892 ( ): probe:vfs_getname:(ffffffff811ed023) pathname="/etc/services") 84482.230 ( ): probe:vfs_getname:(ffffffff811ed023) pathname="/etc/resolv.conf") 84482.481 ( ): probe:vfs_getname:(ffffffff811ed023) pathname="/etc/hosts") 85097.725 ( ): probe:vfs_getname:(ffffffff811ed023) pathname="/root" # After: # trace --no-sys --ev probe:* 0.000 probe:vfs_getname:(ffffffff811ed023) pathname="/root") 1.711 probe:vfs_getname:(ffffffff811ed023) pathname="/etc/localtime") 2.103 probe:vfs_getname:(ffffffff811ed023) pathname="/etc/localtime") ^C# Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Mike Galbraith <efault@gmx.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-jhryxgnam8zecq0q0wsy6pyb@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2015-02-13perf trace: Support --events foo:bar --no-syscallsArnaldo Carvalho de Melo
I.e. support tracing just tracepoints, without strace like raw_syscalls:*. [acme@ssdandy linux]$ trace --no-sys --ev sched:*exec,sched:*switch,sched:*exit usleep 1 0.048 ( ): sched:sched_process_exec:filename=/usr/bin/usleep pid=27298 old_pid=27298) 0.369 ( ): sched:sched_switch:usleep:27298 [120] S ==> swapper/5:0 [120]) 0.452 ( ): sched:sched_process_exit:comm=usleep pid=27298 prio=120) [acme@ssdandy linux]$ TODO: remove that (...) thing when --no-syscalls is specified. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Borislav Petkov <bp@suse.de> Cc: David Ahern <dsahern@gmail.com> Cc: Don Zickus <dzickus@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Mike Galbraith <efault@gmx.de> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/n/tip-vn0hsixsbhm31b2rpj97r96k@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
generated by cgit v1.2.3 (git 2.0.4) at 2024-05-20 14:38:02 +0000