- 08 Apr, 2016 3 commits
-
-
Arnaldo Carvalho de Melo authored
When reading the syscall tracepoint /format file, look for arguments of type "mode_t" and attach a beautifier: [root@jouet ~]# cat ~/bin/tp_with_fields_of_type #!/bin/bash grep -w $1 /sys/kernel/tracing/events/syscalls/*/format | sed -r 's%.*sys_enter_(.*)/format.*%\1%g' | paste -d, -s # tp_with_fields_of_type umode_t chmod,creat,fchmodat,fchmod,mkdirat,mkdir,mknodat,mknod,mq_open,openat,open # Testing it: #define S_ISUID 0004000 #define S_ISGID 0002000 #define S_ISVTX 0001000 #define S_IRWXU 0000700 #define S_IRUSR 0000400 #define S_IWUSR 0000200 #define S_IXUSR 0000100 #define S_IRWXG 0000070 #define S_IRGRP 0000040 #define S_IWGRP 0000020 #define S_IXGRP 0000010 #define S_IRWXO 0000007 #define S_IROTH 0000004 #define S_IWOTH 0000002 #define S_IXOTH 0000001 # for mode in 4000 2000 1000 700 400 200 100 70 40 20 10 7 4 2 1 ; do \ echo -n $mode '->' ; trace --no-inherit -e chmod,fchmodat,fchmod chmod $mode x; \ done 4000 -> 0.338 ( 0.012 ms): fchmodat(dfd: CWD, filename: x, mode: ISUID) = 0 2000 -> 0.438 ( 0.015 ms): fchmodat(dfd: CWD, filename: x, mode: ISGID) = 0 1000 -> 0.677 ( 0.040 ms): fchmodat(dfd: CWD, filename: x, mode: ISVTX) = 0 700 -> 0.394 ( 0.013 ms): fchmodat(dfd: CWD, filename: x, mode: IRWXU) = 0 400 -> 0.337 ( 0.010 ms): fchmodat(dfd: CWD, filename: x, mode: IRUSR) = 0 200 -> 0.259 ( 0.008 ms): fchmodat(dfd: CWD, filename: x, mode: IWUSR) = 0 100 -> 0.249 ( 0.008 ms): fchmodat(dfd: CWD, filename: x, mode: IXUSR) = 0 70 -> 0.266 ( 0.008 ms): fchmodat(dfd: CWD, filename: x, mode: IRWXG) = 0 40 -> 0.329 ( 0.009 ms): fchmodat(dfd: CWD, filename: x, mode: IRGRP) = 0 20 -> 0.250 ( 0.009 ms): fchmodat(dfd: CWD, filename: x, mode: IWGRP) = 0 10 -> 0.259 ( 0.008 ms): fchmodat(dfd: CWD, filename: x, mode: IXGRP) = 0 7 -> 0.249 ( 0.009 ms): fchmodat(dfd: CWD, filename: x, mode: IRWXO) = 0 4 -> 0.278 ( 0.011 ms): fchmodat(dfd: CWD, filename: x, mode: IROTH) = 0 2 -> 0.276 ( 0.009 ms): fchmodat(dfd: CWD, filename: x, mode: IWOTH) = 0 1 -> 0.250 ( 0.008 ms): fchmodat(dfd: CWD, filename: x, mode: IXOTH) = 0 # # trace --no-inherit -e chmod,fchmodat,fchmod chmod 7777 x 0.258 ( 0.011 ms): fchmodat(dfd: CWD, filename: x, mode: IALLUGO) = 0 # trace --no-inherit -e chmod,fchmodat,fchmod chmod 7770 x 0.258 ( 0.008 ms): fchmodat(dfd: CWD, filename: x, mode: ISUID|ISGID|ISVTX|IRWXU|IRWXG) = 0 # trace --no-inherit -e chmod,fchmodat,fchmod chmod 777 x 0.293 ( 0.012 ms): fchmodat(dfd: CWD, filename: x, mode: IRWXUGO # Now lets see if check by using the tracepoint for that specific syscall, instead of raw_syscalls:sys_enter as 'trace' does for its strace fu: # trace --no-inherit --ev syscalls:sys_enter_fchmodat -e fchmodat chmod 666 x 0.255 ( ): syscalls:sys_enter_fchmodat:dfd: 0xffffffffffffff9c, filename: 0x55db32a3f0f0, mode: 0x000001b6) 0.268 ( 0.012 ms): fchmodat(dfd: CWD, filename: x, mode: IRUGO|IWUGO ) = 0 # Perfect, 0x1bc == 0666. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-18e8zfgbkj83xo87yoom43kd@git.kernel.orgSigned-off-by:Arnaldo Carvalho de Melo <acme@redhat.com>
-
Jiri Olsa authored
Andreas reported following command produces no output: # cat test.py #!/usr/bin/env python def stat__krava(cpu, thread, time, val, ena, run): print "event %s cpu %d, thread %d, time %d, val %d, ena %d, run %d" % \ ("krava", cpu, thread, time, val, ena, run) # perf stat -a -I 1000 -e cycles,"cpu/config=0x6530160,name=krava/" record | perf script -s test.py ^C # The reason is that 'perf script' does not process event update events and will never get the event name update thus the python callback is never called. The fix is just to add already existing callback we use in 'perf stat report'. Committer note: After the patch: # perf stat -a -I 1000 -e cycles,"cpu/config=0x6530160,name=krava/" record | perf script -s test.py event krava cpu -1, thread -1, time 1000239179, val 1789051, ena 4000690920, run 4000690920 event krava cpu -1, thread -1, time 2000479061, val 2391338, ena 4000879596, run 4000879596 event krava cpu -1, thread -1, time 3000740802, val 1939121, ena 4000977209, run 4000977209 event krava cpu -1, thread -1, time 4001006730, val 2356115, ena 4001000489, run 4001000489 ^C # Reported-by:Andreas Hollmann <hollmann@in.tum.de> Signed-off-by:
Jiri Olsa <jolsa@kernel.org> Tested-by:
-
Jiri Olsa authored
Milian reported issue with thread::priv, which was double booked by perf trace and DWARF unwind code. So using those together is impossible at the moment. Moving DWARF unwind private data into separate variable so perf trace can keep using thread::priv. Reported-and-Tested-by:
Milian Wolff <milian.wolff@kdab.com> Signed-off-by:
-
- 07 Apr, 2016 1 commit
-
-
Jiri Olsa authored
To be used in cases for both sides trim. Signed-off-by:
-
- 06 Apr, 2016 11 commits
-
-
Arnaldo Carvalho de Melo authored
When reading the syscall tracepoint /format file, look for arguments of type "pid_t" and attach the PID beautifier, that will do a lookup on the threads it knows, i.e. the ones that came from PERF_RECORD_COMM events and add the COMM after the pid in such args: Excerpt of a system wide trace for syscalls with pid_t args: 55602.977 ( 0.006 ms): bash/12122 setpgid(pid: 24347 (bash), pgid: 24347 (bash)) = 0 55603.024 ( 0.004 ms): bash/24347 setpgid(pid: 24347 (bash), pgid: 24347 (bash)) = 0 55691.527 (88.397 ms): bash/12122 wait4(upid: -1, stat_addr: 0x7ffe0cee1720, options: UNTRACED|CONTINUED) ... 55692.479 ( 0.952 ms): git/24347 wait4(upid: 24368, stat_addr: 0x7ffe030d5724) ... 55694.549 ( 2.070 ms): pre-commit/24368 wait4(upid: -1, stat_addr: 0x7ffc94f4fc10) = 24369 (pre-commit) 55694.575 ( 0.002 ms): pre-commit/24368 wait4(upid: -1, stat_addr: 0x7ffc94f4f650, options: NOHANG) = -1 ECHILD No child processes 55695.934 ( 0.010 ms): pre-commit/24368 wait4(upid: -1, stat_addr: 0x7ffc94f4f2d0, options: NOHANG) = 24370 (git) 55695.937 ( 0.001 ms): pre-commit/24368 wait4(upid: -1, stat_addr: 0x7ffc94f4f2d0, options: NOHANG) = -1 ECHILD No child processes 55717.963 ( 0.000 ms): pre-commit/24371 ... [continued]: wait4()) = 24372 55717.978 (21.468 ms): :24371/24371 wait4(upid: -1, stat_addr: 0x7ffc94f4f230) ... 55718.087 ( 0.109 ms): pre-commit/24371 wait4(upid: -1, stat_addr: 0x7ffc94f4f230) = 24373 (tr) 55718.187 ( 0.096 ms): pre-commit/24371 wait4(upid: -1, stat_addr: 0x7ffc94f4f230) = 24374 (wc) 55718.218 ( 0.002 ms): pre-commit/24371 wait4(upid: -1, stat_addr: 0x7ffc94f4eed0, options: NOHANG) = -1 ECHILD No child processes 55718.367 ( 0.005 ms): pre-commit/24368 wait4(upid: -1, stat_addr: 0x7ffc94f4f1d0, options: NOHANG) = 24371 (pre-commit) 55718.369 ( 0.001 ms): pre-commit/24368 wait4(upid: -1, stat_addr: 0x7ffc94f4f1d0, options: NOHANG) = -1 ECHILD No child processes 55741.021 (49.494 ms): git/24347 ... [continued]: wait4()) = 24368 (pre-commit) 74146.427 (18319.601 ms): git/24347 wait4(upid: 24375 (git), stat_addr: 0x7ffe030d6824) ... 74149.036 ( 0.891 ms): bash/24391 wait4(upid: -1, stat_addr: 0x7ffe0cee0560) = 24393 (sed) Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-75yl9hzjhb020iadc81gdj8t@git.kernel.orgSigned-off-by:
-
Arnaldo Carvalho de Melo authored
Showing the COMM for that return, if available. # trace -e getpid,getppid,set_tid_address 490.007 ( 0.005 ms): sh/8250 getpid(...) = 8250 (sh) 490.014 ( 0.001 ms): sh/8250 getppid(...) = 7886 (make) 491.156 ( 0.004 ms): install/8251 set_tid_address(tidptr: 0x7f204a9d4ad0) = 8251 (install) ^C Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-psbpplqupatom9x4uohbxid5@git.kernel.orgSigned-off-by: -
Arnaldo Carvalho de Melo authored
Starting with clone, waitid and wait4: # trace -e waitid,wait4 1.385 ( 1.385 ms): bash/12122 wait4(upid: -1, stat_addr: 0x7ffe0cee1720, options: UNTRACED|CONTINUED) = 1210 (ls) 1.426 ( 0.002 ms): bash/12122 wait4(upid: -1, stat_addr: 0x7ffe0cee1150, options: NOHANG|UNTRACED|CONTINUED) = 0 3.293 ( 0.604 ms): bash/1211 wait4(upid: -1, stat_addr: 0x7ffe0cee0560 ) = 1214 (sed) 3.342 ( 0.002 ms): bash/1211 wait4(upid: -1, stat_addr: 0x7ffe0cee01d0, options: NOHANG ) = -1 ECHILD No child processes 3.576 ( 0.016 ms): bash/12122 wait4(upid: -1, stat_addr: 0x7ffe0cee0550, options: NOHANG|UNTRACED|CONTINUED) = 1211 (bash) ^C# trace -e clone 0.027 ( 0.000 ms): systemd/1 ... [continued]: clone()) = 1227 (systemd) 0.050 ( 0.000 ms): systemd/1227 ... [continued]: clone()) = 0 ^C[root@jouet ~]# Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-lyf5d3y5j15wikjb6pe6ukoi@git.kernel.orgSigned-off-by: -
Arnaldo Carvalho de Melo authored
# trace -e waitid,wait4 0.557 ( 0.557 ms): bash/27335 wait4(upid: -1, stat_addr: 0x7ffd02f449f0) = 27336 1.250 ( 0.685 ms): bash/27335 wait4(upid: -1, stat_addr: 0x7ffd02f449f0) = 27337 1.312 ( 0.002 ms): bash/27335 wait4(upid: -1, stat_addr: 0x7ffd02f44690, options: NOHANG) = -1 ECHILD No child processes 1.550 ( 0.015 ms): bash/3856 wait4(upid: -1, stat_addr: 0x7ffd02f44990, options: NOHANG|UNTRACED|CONTINUED) = 27335 1.552 ( 0.001 ms): bash/3856 wait4(upid: -1, stat_addr: 0x7ffd02f44990, options: NOHANG|UNTRACED|CONTINUED) = 0 # Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-i5vlo5n5jv0amt8bkyicmdxh@git.kernel.orgSigned-off-by:
-
Arnaldo Carvalho de Melo authored
$ trace -e sched_setscheduler chrt -f 1 usleep 1 chrt: failed to set pid 0's policy: Operation not permitted 0.005 ( 0.005 ms): chrt/19189 sched_setscheduler(policy: FIFO, param: 0x7ffec5273d70) = -1 EPERM Operation not permitted $ Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-i5vlo5n5jv0amt8bkyicmdxh@git.kernel.orgSigned-off-by: -
Andi Kleen authored
Document some features for specifying events in the perf list manpage: - Event groups - Leader sampling - How to specify raw PMU events in the new syntax - Global versus per process PMUs. - Access restrictions - Fix Intel SDM URL v2: Lots of new content. address review feedback. Signed-off-by:
Andi Kleen <ak@linux.intel.com> Acked-by:
-
Jiri Olsa authored
Link: http://lkml.kernel.org/n/tip-yk6brsq3opuotr9by18xlkr8@git.kernel.orgSigned-off-by:
-
Arnaldo Carvalho de Melo authored
This ended up triggering these warnings when building on Ubuntu 12.04.5: util/scripting-engines/trace-event-perl.c: In function 'perl_process_callchain': util/scripting-engines/trace-event-perl.c:293:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:294:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:295:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:297:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:309:4: error: value computed is not used [-Werror=unused-value] cc1: all warnings being treated as errors mv: cannot stat `/tmp/build/perf/util/scripting-engines/.trace-event-perl.o.tmp': No such file or directory make[4]: *** [/tmp/build/perf/util/scripting-engines/trace-event-perl.o] Error 1 Fix it by doing error checking when building the perl data structures related to callchains. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Dima Kogan <dima@secretsauce.net> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@gmail.com> Fixes: f7380c12 ("perf script perl: Perl scripts now get a backtrace, like the python ones") Signed-off-by:
-
Arnaldo Carvalho de Melo authored
If not, tell the user that: config/Makefile:273: Old libdw.h, finding variables at given 'perf probe' point will not work, install elfutils-devel/libdw-dev >= 0.157 And return -ENOTSUPP in die_get_var_range(), failing features that need it, like the one pointed out above. This fixes the build on older systems, such as Ubuntu 12.04.5. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Vinson Lee <vlee@freedesktop.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-9l7luqkq4gfnx7vrklkq4obs@git.kernel.orgSigned-off-by:
-
Vinson Lee authored
Fix build error on Ubuntu 12.04.5 with GCC 4.6.3. CC util/config.o util/config.c: In function ‘perf_buildid_config’: util/config.c:384:15: error: declaration of ‘dirname’ shadows a global declaration [-Werror=shadow] Signed-off-by:Vinson Lee <vlee@freedesktop.org> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com> Cc: Alexei Starovoitov <ast@plumgrid.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Josh Poimboeuf <jpoimboe@redhat.com> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Taeung Song <treeze.taeung@gmail.com> Cc: Wang Nan <wangnan0@huawei.com> Fixes: 9cb5987c ("perf config: Rework buildid_dir_command_config to perf_buildid_config") Link: http://lkml.kernel.org/r/1459807659-9020-1-git-send-email-vlee@freedesktop.orgSigned-off-by:
-
Ingo Molnar authored
Merge tag 'perf-core-for-mingo-20160401' of git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux into perf/core Pull perf/core improvements and fixes from Arnaldo Carvalho de Melo: User visible changes: - Do not use events that don't have timestamps when setting 'perf trace's base timestamp, fixing up the timestamp column for syscalls (Arnaldo Carvalho de Melo) - Make the 'bpf-output' sample_type be the same as tracepoint's, fixing up 'perf trace's timestamp column for bpf events (Wang Nan) - Fix PMU term format max value calculation (Kan Liang) - Pretty print 'seccomp', 'getrandom' syscalls in 'perf trace' (Arnaldo Carvalho de Melo) Infrastructure changes: - Add support for using TSC as an ARCH timestamp when synthesizing JIT records (Adrian Hunter) Signed-off-by:
Ingo Molnar <mingo@kernel.org>
-
- 01 Apr, 2016 6 commits
-
-
Wang Nan authored
Before this patch we can see very large time in the events before the 'bpf-output' event. For example: # perf trace -vv -T --ev sched:sched_switch \ --ev bpf-output/no-inherit,name=evt/ \ --ev ./test_bpf_trace.c/map:channel.event=evt/ \ usleep 10 ... 18446744073709.551 (18446564645918.480 ms): usleep/4157 nanosleep(rqtp: 0x7ffd3f0dc4e0) ... 18446744073709.551 ( ): evt:Raise a BPF event!..) 179427791.076 ( ): perf_bpf_probe:func_begin:(ffffffff810eb9a0)) 179427791.081 ( ): sched:sched_switch:usleep:4157 [120] S ==> swapper/2:0 [120]) ... We can also see the differences between bpf-output events and breakpoint events: For bpf output event: sample_type IP|TID|RAW|IDENTIFIER For tracepoint events: sample_type IP|TID|TIME|CPU|PERIOD|RAW|IDENTIFIER This patch fix this differences by adding more sample type for bpf-output events. After this patch: # perf trace -vv -T --ev sched:sched_switch \ --ev bpf-output/no-inherit,name=evt/ \ --ev ./test_bpf_trace.c/map:channel.event=evt/ \ usleep 10 ... 179877370.878 ( 0.003 ms): usleep/5336 nanosleep(rqtp: 0x7ffff866c450) ... 179877370.878 ( ): evt:Raise a BPF event!..) 179877370.878 ( ): perf_bpf_probe:func_begin:(ffffffff810eb9a0)) 179877370.882 ( ): sched:sched_switch:usleep:5336 [120] S ==> swapper/4:0 [120]) 179877370.945 ( ): evt:Raise a BPF event!..) ... # ./perf trace -vv -T --ev sched:sched_switch \ --ev bpf-output/no-inherit,name=evt/ \ --ev ./test_bpf_trace.c/map:channel.event=evt/ \ usleep 10 2>&1 | grep sample_type sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW sample_type IP|TID|TIME|ID|CPU|PERIOD|RAW The 'IDENTIFIER' info is not required because all events have the same sample_type. Committer notes: Further testing, on top of the changes making 'perf trace' avoid samples from events without PERF_SAMPLE_TIME: Before: # trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10 <SNIP> 0.560 ( 0.001 ms): brk( ) = 0x55e5a1df8000 18446640227439.430 (18446640227438.859 ms): nanosleep(rqtp: 0x7ffc96643370) ... 18446640227439.430 ( ): evt:Raise a BPF event!..) 0.576 ( ): perf_bpf_probe:func_begin:(ffffffff81112460)) 18446640227439.430 ( ): evt:Raise a BPF event!..) 0.645 ( ): perf_bpf_probe:func_end:(ffffffff81112460 <- ffffffff81003d92)) 0.646 ( 0.076 ms): ... [continued]: nanosleep()) = 0 # After: # trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10 <SNIP> 0.292 ( 0.001 ms): brk( ) = 0x55c7cd6e1000 0.302 ( 0.004 ms): nanosleep(rqtp: 0x7ffedd8bc0f0) ... 0.302 ( ): evt:Raise a BPF event!..) 0.303 ( ): perf_bpf_probe:func_begin:(ffffffff81112460)) 0.397 ( ): evt:Raise a BPF event!..) 0.397 ( ): perf_bpf_probe:func_end:(ffffffff81112460 <- ffffffff81003d92)) 0.398 ( 0.100 ms): ... [continued]: nanosleep()) = 0 Signed-off-by:Wang Nan <wangnan0@huawei.com> Reported-and-Tested-by:
-
Arnaldo Carvalho de Melo authored
This was causing bogus values to be shown at the timestamp column: Before: # trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10 94631143.385 ( 0.001 ms): brk( ) = 0x555555757000 94631143.398 ( 0.003 ms): mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1) = 0x7ffff7ff6000 94631143.406 ( 0.004 ms): access(filename: 0xf7df9e10, mode: R ) = -1 ENOENT No such file or directory 94631143.412 ( 0.004 ms): open(filename: 0xf7df8761, flags: CLOEXEC) = 3 94631143.415 ( 0.002 ms): fstat(fd: 3, statbuf: 0x7fffffffd6b0 ) = 0 94631143.419 ( 0.003 ms): mmap(len: 106798, prot: READ, flags: PRIVATE, fd: 3) = 0x7ffff7fdb000 94631143.420 ( 0.001 ms): close(fd: 3 ) = 0 94631143.432 ( 0.004 ms): open(filename: 0xf7ff6640, flags: CLOEXEC) = 3 <SNIP> After: # trace --ev bpf-output/no-inherit,name=evt/ --ev /home/acme/bpf/test_bpf_trace.c/map:channel.event=evt/ usleep 10 0.022 ( 0.001 ms): brk( ) = 0x55d7668a6000 0.037 ( 0.003 ms): mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1) = 0x7f8fbeb97000 0.123 ( 0.083 ms): access(filename: 0xbe995e10, mode: R ) = -1 ENOENT No such file or directory 0.130 ( 0.004 ms): open(filename: 0xbe994761, flags: CLOEXEC) = 3 0.133 ( 0.002 ms): fstat(fd: 3, statbuf: 0x7fff6487a890 ) = 0 0.138 ( 0.003 ms): mmap(len: 106798, prot: READ, flags: PRIVATE, fd: 3) = 0x7f8fbeb7c000 0.140 ( 0.001 ms): close(fd: 3 ) = 0 0.151 ( 0.004 ms): open(filename: 0xbeb97640, flags: CLOEXEC) = 3 <SNIP> Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Milian Wolff <milian.wolff@kdab.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-p7m8llv81iv55ekxexdp5n57@git.kernel.orgSigned-off-by:
-
Arnaldo Carvalho de Melo authored
That is used in both live runs, i.e.: # trace ls As when processing events recorded in a perf.data file: # trace -i perf.data Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Milian Wolff <milian.wolff@kdab.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-901l6yebnzeqg7z8mbaf49xb@git.kernel.orgSigned-off-by:
-
Kan Liang authored
Currently the max value of format is calculated by the bits number. It relies on the continuity of the format. However, uncore event format is not continuous. E.g. uncore qpi event format can be 0-7,21. If bit 21 is set, there is parsing issues as below. $ perf stat -a -e uncore_qpi_0/event=0x200002,umask=0x8/ event syntax error: '..pi_0/event=0x200002,umask=0x8/' \___ value too big for format, maximum is 511 This patch return the real max value by setting all possible bits to 1. Signed-off-by:Kan Liang <kan.liang@intel.com> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com> Cc: Andi Kleen <ak@linux.intel.com> Cc: Jiri Olsa <jolsa@redhat.com> Link: http://lkml.kernel.org/r/1459365375-14285-1-git-send-email-kan.liang@intel.comSigned-off-by:
-
Adrian Hunter authored
For Intel PT / BTS, define the environment variable that selects TSC timestamps in the jitdump file. Signed-off-by:
Adrian Hunter <adrian.hunter@intel.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Stephane Eranian <eranian@google.com> Link: http://lkml.kernel.org/r/1457426333-30260-1-git-send-email-adrian.hunter@intel.comSigned-off-by:
-
Adrian Hunter authored
Intel PT uses TSC as a timestamp, so add support for using TSC instead of the monotonic clock. Use of TSC is selected by an environment variable "JITDUMP_USE_ARCH_TIMESTAMP" and flagged in the jitdump file with flag JITDUMP_FLAGS_ARCH_TIMESTAMP. Signed-off-by:
-
- 31 Mar, 2016 19 commits
-
-
Adrian Hunter authored
Intel PT uses the time members from the perf_event_mmap_page to convert between TSC and perf time. Due to a lack of foresight when Intel PT was implemented, those time members were recorded in the (implementation dependent) AUXTRACE_INFO event, the structure of which is generally inaccessible outside of the Intel PT decoder. However now the conversion between TSC and perf time is needed when processing a jitdump file when Intel PT has been used for tracing. So add a user event to record the time members. 'perf record' will synthesize the event if the information is available. And session processing will put a copy of the event on the session so that tools like 'perf inject' can easily access it. Signed-off-by:
-
Arnaldo Carvalho de Melo authored
# trace -e getrandom 35622.560 ( 0.023 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35622.585 ( 0.006 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35622.594 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35627.395 ( 0.010 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 35630.940 ( 0.013 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 35718.613 ( 0.015 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35718.629 ( 0.005 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35718.637 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 35719.355 ( 0.010 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 35721.042 ( 0.030 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 41090.830 ( 0.012 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41090.845 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41090.851 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41091.750 ( 0.010 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 41091.823 ( 0.006 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 41122.078 ( 0.053 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41122.129 ( 0.009 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41122.139 ( 0.004 ms): systemd-udevd/631 getrandom(buf: 0x55621e3c18f0, count: 16, flags: NONBLOCK) = 16 41124.492 ( 0.007 ms): libvirtd/1353 getrandom(buf: 0x7f7a1bfa35c0, count: 16, flags: NONBLOCK ) = 16 41124.470 ( 0.013 ms): fwupd/16120 getrandom(buf: 0x7f63243aa5c0, count: 16, flags: NONBLOCK ) = 16 41590.832 ( 0.014 ms): chrome/5957 getrandom(buf: 0x7fabac7b15b0, count: 16, flags: NONBLOCK ) = 16 41590.884 ( 0.004 ms): chrome/5957 getrandom(buf: 0x7fabac7b15c0, count: 16, flags: NONBLOCK ) = 16 Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Milian Wolff <milian.wolff@kdab.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-gca0n1p3aca3depey703ph2q@git.kernel.orgSigned-off-by:
-
Arnaldo Carvalho de Melo authored
E.g: # trace -e seccomp 200.061 (0.009 ms): :2441/2441 seccomp(op: FILTER, flags: TSYNC ) = -1 EFAULT Bad address 200.910 (0.121 ms): :2441/2441 seccomp(op: FILTER, flags: TSYNC, uargs: 0x7fff57479fe0) = 0 Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Milian Wolff <milian.wolff@kdab.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-t369uckshlwp4evkks4bcoo7@git.kernel.orgSigned-off-by:
-
Arnaldo Carvalho de Melo authored
We catch this record to provide a visual indication that events are getting lost, then call the default method to allow extra logging shared with the other tools to take place. This extra logging was done twice because we were continuing to the "default" clause where machine__process_event() will end up calling machine__process_lost_event() again, fix it. Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: David Ahern <dsahern@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Wang Nan <wangnan0@huawei.com> Link: http://lkml.kernel.org/n/tip-wus2zlhw3qo24ye84ewu4aqw@git.kernel.orgSigned-off-by:
-
Wang Nan authored
Convert perf_output_begin() to __perf_output_begin() and make the later function able to write records from the end of the ring-buffer. Following commits will utilize the 'backward' flag. This is the core patch to support writing to the ring-buffer backwards, which will be introduced by upcoming patches to support reading from overwritable ring-buffers. In theory, this patch should not introduce any extra performance overhead since we use always_inline, but it does not hurt to double check that assumption: When CONFIG_OPTIMIZE_INLINING is disabled, the output object is nearly identical to original one. See: http://lkml.kernel.org/g/56F52E83.70409@huawei.com When CONFIG_OPTIMIZE_INLINING is enabled, the resuling object file becomes smaller: $ size kernel/events/ring_buffer.o* text data bss dec hex filename 4641 4 8 4653 122d kernel/events/ring_buffer.o.old 4545 4 8 4557 11cd kernel/events/ring_buffer.o.new Performance testing results: Calling 3000000 times of 'close(-1)', use gettimeofday() to check duration. Use 'perf record -o /dev/null -e raw_syscalls:*' to capture system calls. In ns. Testing environment: CPU : Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz Kernel : v4.5.0 MEAN STDVAR BASE 800214.950 2853.083 PRE 2253846.700 9997.014 POST 2257495.540 8516.293 Where 'BASE' is pure performance without capturing. 'PRE' is test result of pure 'v4.5.0' kernel. 'POST' is test result after this patch. Considering the stdvar, this patch doesn't hurt performance, within noise margin. For testing details, see: http://lkml.kernel.org/g/56F89DCD.1040202@huawei.comSigned-off-by:
Peter Zijlstra (Intel) <peterz@infradead.org> Cc: <pi3orama@163.com> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com> Cc: Alexei Starovoitov <ast@kernel.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Brendan Gregg <brendan.d.gregg@gmail.com> Cc: He Kuang <hekuang@huawei.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Linus Torvalds <torvalds@linux-foundation.org> Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com> Cc: Namhyung Kim <namhyung@kernel.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Stephane Eranian <eranian@google.com> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Vince Weaver <vincent.weaver@maine.edu> Cc: Zefan Li <lizefan@huawei.com> Link: http://lkml.kernel.org/r/1459147292-239310-4-git-send-email-wangnan0@huawei.comSigned-off-by:
-
Wang Nan authored
Set a default event->overflow_handler in perf_event_alloc() so don't need to check event->overflow_handler in __perf_event_overflow(). Following commits can give a different default overflow_handler. Initial idea comes from Peter: http://lkml.kernel.org/r/20130708121557.GA17211@twins.programming.kicks-ass.net Since the default value of event->overflow_handler is not NULL, existing 'if (!overflow_handler)' checks need to be changed. is_default_overflow_handler() is introduced for this. No extra performance overhead is introduced into the hot path because in the original code we still need to read this handler from memory. A conditional branch is avoided so actually we remove some instructions. Signed-off-by:
-
Wang Nan authored
Add new ioctl() to pause/resume ring-buffer output. In some situations we want to read from the ring-buffer only when we ensure nothing can write to the ring-buffer during reading. Without this patch we have to turn off all events attached to this ring-buffer to achieve this. This patch is a prerequisite to enable overwrite support for the perf ring-buffer support. Following commits will introduce new methods support reading from overwrite ring buffer. Before reading, caller must ensure the ring buffer is frozen, or the reading is unreliable. Signed-off-by:
-
Jiri Olsa authored
Currently we check sample type for ftrace:function events even if it's not created as a sampling event. That prevents creating ftrace_function event in counting mode. Make sure we check sample types only for sampling events. Before: $ sudo perf stat -e ftrace:function ls ... Performance counter stats for 'ls': <not supported> ftrace:function 0.001983662 seconds time elapsed After: $ sudo perf stat -e ftrace:function ls ... Performance counter stats for 'ls': 44,498 ftrace:function 0.037534722 seconds time elapsed Suggested-by:Namhyung Kim <namhyung@kernel.org> Signed-off-by:
Steven Rostedt <rostedt@goodmis.org> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com> Cc: Arnaldo Carvalho de Melo <acme@kernel.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Jiri Olsa <jolsa@redhat.com> Cc: Linus Torvalds <torvalds@linux-foundation.org> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Stephane Eranian <eranian@google.com> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: Vince Weaver <vincent.weaver@maine.edu> Link: http://lkml.kernel.org/r/1458138873-1553-2-git-send-email-jolsa@kernel.orgSigned-off-by:
-
Alexander Shishkin authored
As per AUX buffer management requirement, AUX output has to happen between pmu::start and pmu::stop calls so that perf_event_stop() actually stops it and therefore perf can free the AUX data after it has called pmu::stop. This patch moves perf_aux_output_{begin,end} from bts_event_{add,del} to bts_event_{start,stop}. As a bonus, we get rid of bts_buffer_is_full(), which is already taken care of by perf_aux_output_begin() anyway. Signed-off-by:Alexander Shishkin <alexander.shishkin@linux.intel.com> Signed-off-by:
-
Alexander Shishkin authored
As per AUX buffer management requirement, AUX output has to happen between pmu::start and pmu::stop calls so that perf_event_stop() actually stops it and therefore perf can free the AUX data after it has called pmu::stop. This patch moves perf_aux_output_{begin,end} from pt_event_{add,del} to pt_event_{start,stop}. As a bonus, we get rid of pt_buffer_is_full(), which is already taken care of by perf_aux_output_begin() anyway. Signed-off-by: -
Alexander Shishkin authored
In order to ensure safe AUX buffer management, we rely on the assumption that pmu::stop() stops its ongoing AUX transaction and not just the hw. This patch documents this requirement for the perf_aux_output_{begin,end}() APIs. Signed-off-by: -
Alexander Shishkin authored
Now that we can ensure that when ring buffer's AUX area is on the way to getting unmapped new transactions won't start, we only need to stop all events that can potentially be writing aux data to our ring buffer. Having done that, we can safely free the AUX pages and corresponding PMU data, as this time it is guaranteed to be the last aux reference holder. This partially reverts: 57ffc5ca ("perf: Fix AUX buffer refcounting") ... which was made to defer deallocation that was otherwise possible from an NMI context. Now it is no longer the case; the last call to rb_free_aux() that drops the last AUX reference has to happen in perf_mmap_close() on that AUX area. Signed-off-by:
-
Alexander Shishkin authored
When ring buffer's AUX area is unmapped and rb->aux_mmap_count drops to zero, new AUX transactions into this buffer can still be started, even though the buffer in en route to deallocation. This patch adds a check to perf_aux_output_begin() for rb->aux_mmap_count being zero, in which case there is no point starting new transactions, in other words, the ring buffers that pass a certain point in perf_mmap_close will not have their events sending new data, which clears path for freeing those buffers' pages right there and then, provided that no active transactions are holding the AUX reference. Signed-off-by:
-
Peter Zijlstra authored
There should (and can) only be a single PMU for perf_hw_context events. This is because of how we schedule events: once a hardware event fails to schedule (the PMU is 'full') we stop trying to add more. The trivial 'fix' would break the Round-Robin scheduling we do. Signed-off-by:
-
Peter Zijlstra authored
Ingo says: "If we do a separate file we should have it in arch/x86/events/Kconfig (not in arch/x86/Kconfig.perf), and also move some of the other bits, such as PERF_EVENTS_AMD_POWER?" Suggested-by:
-
Huang Rui authored
AMD Zeppelin (Family 17h, Model 00h) introduces an instructions retired performance counter which is indicated by CPUID.8000_0008H:EBX[1]. A dedicated Instructions Retired MSR register (MSR 0xC000_000E9) increments once for every instruction retired. Signed-off-by:
Huang Rui <ray.huang@amd.com> Signed-off-by:
-
Huang Rui authored
AMD Carrizo (Family 15h, Model 60h) introduces a time-stamp counter which is indicated by CPUID.8000_0001H:ECX[27]. It increments at a 100 MHz rate in all P-states, and C states, S0, or S1. The frequency is about 100MHz. This counter will be used to calculate processor power and other parts. So add an interface into the MSR PMU to get the PTSC counter value. Signed-off-by:
-
Thomas Gleixner authored
Add the exit function and allow the driver to be built as a module. Signed-off-by:
Thomas Gleixner <tglx@linutronix.de> Signed-off-by:
-
Thomas Gleixner authored
There is no point in WARN_ON() inside of a well known init function. We already know the call stack and it's really not of critical importance whether the registration of a PMU fails. Aside of that for consistency reasons it's just pointless to try to register another PMU if the first register attempt failed. There is also no value in keeping one PMU if the second one can not be registered. Make it consistent so we can finaly modularize the driver. Signed-off-by:
-
