03 Nov, 2020
1 commit
-
# ./perf trace -e sched:sched_switch -G test -a sleep 1
perf: Segmentation fault
Obtained 11 stack frames.
./perf(sighandler_dump_stack+0x43) [0x55cfdc636db3]
/lib/x86_64-linux-gnu/libc.so.6(+0x3efcf) [0x7fd23eecafcf]
./perf(parse_cgroups+0x36) [0x55cfdc673f36]
./perf(+0x3186ed) [0x55cfdc70d6ed]
./perf(parse_options_subcommand+0x629) [0x55cfdc70e999]
./perf(cmd_trace+0x9c2) [0x55cfdc5ad6d2]
./perf(+0x1e8ae0) [0x55cfdc5ddae0]
./perf(+0x1e8ded) [0x55cfdc5ddded]
./perf(main+0x370) [0x55cfdc556f00]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe6) [0x7fd23eeadb96]
./perf(_start+0x29) [0x55cfdc557389]
Segmentation fault
#It happens because "struct trace" in option->value is passed to the
parse_cgroups function instead of "struct evlist".Fixes: 9ea42ba4411ac ("perf trace: Support setting cgroups as targets")
Signed-off-by: Stanislav Ivanichkin
Tested-by: Arnaldo Carvalho de Melo
Acked-by: Namhyung Kim
Cc: Dmitry Monakhov
Link: http://lore.kernel.org/lkml/20201027094357.94881-1-sivanichkin@yandex-team.ru
Signed-off-by: Arnaldo Carvalho de Melo
14 Oct, 2020
1 commit
-
'perf trace ls' started crashing after commit d21cb73a9025 on
!HAVE_SYSCALL_TABLE_SUPPORT configs (armv7l here) like this:0 strlen () at ../sysdeps/arm/armv6t2/strlen.S:126
1 0xb6800780 in __vfprintf_internal (s=0xbeff9908, s@entry=0xbeff9900, format=0xa27160 "]: %s()", ap=..., mode_flags=) at vfprintf-internal.c:1688
...
5 0x0056ecdc in fprintf (__fmt=0xa27160 "]: %s()", __stream=) at /usr/include/bits/stdio2.h:100
6 trace__sys_exit (trace=trace@entry=0xbeffc710, evsel=evsel@entry=0xd968d0, event=, sample=sample@entry=0xbeffc3e8) at builtin-trace.c:2475
7 0x00566d40 in trace__handle_event (sample=0xbeffc3e8, event=, trace=0xbeffc710) at builtin-trace.c:3122
...
15 main (argc=2, argv=0xbefff6e8) at perf.c:538It is because memset in trace__read_syscall_info zeroes wrong memory:
1) when initializing for the first time, it does not reset the last id.
2) in other cases, it resets the last id of previous buffer.
ad 1) it causes the crash above as sc->name used in the fprintf above
contains garbage.ad 2) it sets nonexistent from true back to false for id 11 here. Not
sure, what the consequences are.So fix it by introducing a special case for the initial initialization
and do the right +1 in both cases.Fixes: d21cb73a9025 ("perf trace: Grow the syscall table as needed when using libaudit")
Signed-off-by: Jiri Slaby
Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Cc: Peter Zijlstra
Link: http://lore.kernel.org/lkml/20201001093419.15761-1-jslaby@suse.cz
Signed-off-by: Arnaldo Carvalho de Melo
04 Aug, 2020
1 commit
-
Extend -D,--delay option with -1 to start collection with events
disabled to be enabled later by 'enable' command provided via control
file descriptor.Signed-off-by: Alexey Budankov
Acked-by: Jiri Olsa
Acked-by: Namhyung Kim
Cc: Alexander Shishkin
Cc: Andi Kleen
Cc: Peter Zijlstra
Link: http://lore.kernel.org/lkml/3e7d362c-7973-ee5d-e81e-c60ea22432c3@linux.intel.com
Signed-off-by: Arnaldo Carvalho de Melo
23 Jun, 2020
2 commits
-
To differentiate from libperf's 'struct perf_evlist' methods.
Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo -
To differentiate from libperf's 'struct perf_evlist' methods.
Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo
30 May, 2020
1 commit
-
The audit-libs API doesn't provide a way to figure out what is the
syscall with the greatest number/id, take that into account when using
that method to go on growing the syscall table as we the syscalls go on
appearing on the radar.With this the libaudit based method is back working, i.e. when building
with:$ make NO_SYSCALL_TABLE=1 O=/tmp/build/perf -C tools/perf install-bin
Auto-detecting system features:
... libaudit: [ on ]
... libbfd: [ on ]
... libcap: [ on ]
$ ldd ~/bin/perf | grep audit
libaudit.so.1 => /lib64/libaudit.so.1 (0x00007faef22df000)
$perf trace is back working, which makes it functional in arches other
than x86_64, powerpc, arm64 and s390, that provides these generators:$ find tools/perf/arch/ -name "*syscalltbl*"
tools/perf/arch/x86/entry/syscalls/syscalltbl.sh
tools/perf/arch/arm64/entry/syscalls/mksyscalltbl
tools/perf/arch/s390/entry/syscalls/mksyscalltbl
tools/perf/arch/powerpc/entry/syscalls/mksyscalltbl
$Example output forcing the libaudit method on x86_64:
# perf trace -e file,nanosleep sleep 0.001
? ( ): sleep/859090 ... [continued]: execve()) = 0
0.045 ( 0.005 ms): sleep/859090 access(filename: 0x8733e850, mode: R) = -1 ENOENT (No such file or directory)
0.055 ( 0.005 ms): sleep/859090 openat(dfd: CWD, filename: 0x8733ba29, flags: RDONLY|CLOEXEC) = 3
0.079 ( 0.005 ms): sleep/859090 openat(dfd: CWD, filename: 0x87345d20, flags: RDONLY|CLOEXEC) = 3
0.085 ( 0.002 ms): sleep/859090 read(fd: 3, buf: 0x7ffd9d483f58, count: 832) = 832
0.090 ( 0.002 ms): sleep/859090 read(fd: 3, buf: 0x7ffd9d483b50, count: 784) = 784
0.094 ( 0.002 ms): sleep/859090 read(fd: 3, buf: 0x7ffd9d483b20, count: 32) = 32
0.098 ( 0.002 ms): sleep/859090 read(fd: 3, buf: 0x7ffd9d483ad0, count: 68) = 68
0.109 ( 0.002 ms): sleep/859090 read(fd: 3, buf: 0x7ffd9d483a50, count: 784) = 784
0.113 ( 0.002 ms): sleep/859090 read(fd: 3, buf: 0x7ffd9d483730, count: 32) = 32
0.117 ( 0.002 ms): sleep/859090 read(fd: 3, buf: 0x7ffd9d483710, count: 68) = 68
0.320 ( 0.008 ms): sleep/859090 openat(dfd: CWD, filename: 0x872c3660, flags: RDONLY|CLOEXEC) = 3
0.372 ( 1.057 ms): sleep/859090 nanosleep(rqtp: 0x7ffd9d484ac0) = 0
#There are still some limitations when using the libaudit method, that
will be fixed at some point, i.e., this works with the mksyscalltbl
method but not with libaudit's:# perf trace -e file,*sleep sleep 0.001
event syntax error: '*sleep'
\___ parser error
Run 'perf list' for a list of valid eventsUsage: perf trace [] []
or: perf trace [] -- []
or: perf trace record [] []
or: perf trace record [] -- []-e, --event event/syscall selector. use 'perf list' to list available events
#Cc: Adrian Hunter
Cc: Ingo Molnar
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo
28 May, 2020
2 commits
-
The perf compilation fails for NO_LIBBPF=1 DEBUG=1 with:
$ make NO_LIBBPF=1 DEBUG=1
BUILD: Doing 'make -j8' parallel build
CC builtin-trace.o
LD perf-in.o
LINK perf
/usr/bin/ld: perf-in.o: in function `trace__find_bpf_map_by_name':
/home/jolsa/kernel/linux-perf/tools/perf/builtin-trace.c:4608: undefined reference to `bpf_object__find_map_by_name'
collect2: error: ld returned 1 exit status
make[2]: *** [Makefile.perf:631: perf] Error 1
make[1]: *** [Makefile.perf:225: sub-make] Error 2
make: *** [Makefile:70: all] Error 2Move trace__find_bpf_map_by_name calls under HAVE_LIBBPF_SUPPORT ifdef
and add make test for this.Committer notes:
Add missing:
run += make_no_libbpf_DEBUG
Signed-off-by: Jiri Olsa
Tested-by: Arnaldo Carvalho de Melo
Cc: Alexander Shishkin
Cc: Michael Petlan
Cc: Namhyung Kim
Cc: Peter Zijlstra
Link: http://lore.kernel.org/lkml/20200518141027.3765877-1-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
As these are 'struct evsel' methods, not part of tools/lib/perf/, aka
libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo
06 May, 2020
7 commits
-
As those is a 'struct evsel' methods, not part of tools/lib/perf/, aka
libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo -
As it is a 'struct evsel' method, not part of tools/lib/perf/, aka
libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo -
As those are 'struct evsel' methods, not part of tools/lib/perf/, aka
libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo -
As those are not 'struct evsel' methods, not part of tools/lib/perf/,
aka libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo -
As those are not 'struct evsel' methods, not part of tools/lib/perf/,
aka libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo -
As they are 'struct evsel' methods or related routines, not part of
tools/lib/perf/, aka libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo -
As they are all 'struct evsel' methods, not part of tools/lib/perf/, aka
libperf, to whom the perf_ prefix belongs.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo
12 Feb, 2020
1 commit
-
# perf trace -e syscalls:sys_enter_prctl --filter="option==SET_NAME"
0.000 Socket Thread/3860 syscalls:sys_enter_prctl(option: SET_NAME, arg2: 0x7fc50b9733e8)
0.053 SSL Cert #78/3860 syscalls:sys_enter_prctl(option: SET_NAME, arg2: 0x7fc50b9733e8)
^C #If one uses '-v' with 'perf trace', we can see the filter it puts in
place:New filter for syscalls:sys_enter_prctl: (option==0xf) && (common_pid != 3859 && common_pid != 2757)
We still need to allow using plain '-e prctl' and have this turn into
creating a 'syscalls:sys_enter_prctl' event so that the filter can be
applied only to it as right now '-e prctl' ends up using the
'raw_syscalls:sys_enter/sys_exit'.The end goal is to have something like:
# perf trace -e prctl/option==SET_NAME/
And have that use tracepoint filters or eBPF ones.
Cc: Adrian Hunter
Cc: Christian Brauner
Cc: Jiri Olsa
Cc: Mike Christie
Cc: Namhyung Kim
Signed-off-by: Arnaldo Carvalho de Melo
19 Nov, 2019
1 commit
-
Record the first event parsing error and report. Implementing feedback
from Jiri Olsa:https://lkml.org/lkml/2019/10/28/680
An example error is:
$ tools/perf/perf stat -e c/c/
WARNING: multiple event parsing errors
event syntax error: 'c/c/'
\___ unknown termvalid terms: event,filter_rem,filter_opc0,edge,filter_isoc,filter_tid,filter_loc,filter_nc,inv,umask,filter_opc1,tid_en,thresh,filter_all_op,filter_not_nm,filter_state,filter_nm,config,config1,config2,name,period,percore
Initial error:
event syntax error: 'c/c/'
\___ Cannot find PMU `c'. Missing kernel support?
Run 'perf list' for a list of valid eventsUsage: perf stat [] []
-e, --event event selector. use 'perf list' to list available events
Signed-off-by: Ian Rogers
Tested-by: Arnaldo Carvalho de Melo
Cc: Adrian Hunter
Cc: Alexander Shishkin
Cc: Allison Randal
Cc: Andi Kleen
Cc: Anju T Sudhakar
Cc: Christian Borntraeger
Cc: Davidlohr Bueso
Cc: Jin Yao
Cc: Jiri Olsa
Cc: Mark Rutland
Cc: Namhyung Kim
Cc: Peter Zijlstra
Cc: Ravi Bangoria
Cc: Stephane Eranian
Cc: Thomas Gleixner
Cc: Thomas Richter
Link: http://lore.kernel.org/lkml/20191116074652.9960-1-irogers@google.com
Signed-off-by: Arnaldo Carvalho de Melo
20 Oct, 2019
6 commits
-
The 'mmap' syscall has special needs so it doesn't use
SCA_STRARRAY_FLAGS, see its implementation in
syscall_arg__scnprintf_mmap_flags(), related to special handling of
MAP_ANONYMOUS, so set ->parm to the strarray__mmap_flags and hook up
with strarray__strtoul_flags manually, now we can filter by those or-ed
string expressions:# perf trace -e syscalls:sys_enter_mmap sleep 1
0.000 syscalls:sys_enter_mmap(addr: NULL, len: 134346, prot: READ, flags: PRIVATE, fd: 3, off: 0)
0.026 syscalls:sys_enter_mmap(addr: NULL, len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS)
0.036 syscalls:sys_enter_mmap(addr: NULL, len: 1857472, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3, off: 0)
0.046 syscalls:sys_enter_mmap(addr: 0x7fae003d9000, len: 1363968, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x22000)
0.052 syscalls:sys_enter_mmap(addr: 0x7fae00526000, len: 311296, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x16f000)
0.055 syscalls:sys_enter_mmap(addr: 0x7fae00573000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1bb000)
0.062 syscalls:sys_enter_mmap(addr: 0x7fae00579000, len: 14272, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS)
0.253 syscalls:sys_enter_mmap(addr: NULL, len: 217750512, prot: READ, flags: PRIVATE, fd: 3, off: 0)
## perf trace -e syscalls:sys_enter_mmap --filter="flags==PRIVATE|FIXED|DENYWRITE" sleep 1
0.000 syscalls:sys_enter_mmap(addr: 0x7f6ab3dcb000, len: 1363968, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x22000)
0.010 syscalls:sys_enter_mmap(addr: 0x7f6ab3f18000, len: 311296, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x16f000)
0.014 syscalls:sys_enter_mmap(addr: 0x7f6ab3f65000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1bb000)
# perf trace -e syscalls:sys_enter_mmap --filter="flags==PRIVATE|ANONYMOUS" sleep 1
0.000 syscalls:sys_enter_mmap(addr: NULL, len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS)
## perf trace -v -e syscalls:sys_enter_mmap --filter="flags==PRIVATE|ANONYMOUS" sleep 1 |& grep "New filter"
New filter for syscalls:sys_enter_mmap: flags==0x22
#Cc: Adrian Hunter
Cc: Andi Kleen
Cc: Brendan Gregg
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-czw754b7m9rp9ibq2f6be2o1@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Now anything that uses STRARRAY_FLAGS, like the 'fsmount' syscall will
support mapping or-ed strings back to a value that can be used in a
filter.In some cases, where STRARRAY_FLAGS isn't used but instead the scnprintf
is a special one because of specific needs, like for mmap, then one has
to set the ->pars to the strarray. See the next cset.Cc: Adrian Hunter
Cc: Andi Kleen
Cc: Brendan Gregg
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-r2lpqo7dfsrhi4ll0npsb3u7@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Counterpart of strarray__scnprintf_flags(), i.e. from a expression like:
# perf trace -e syscalls:sys_enter_mmap --filter="flags==PRIVATE|FIXED|DENYWRITE"
I.e. that "flags==PRIVATE|FIXED|DENYWRITE", turn that into
# perf trace -e syscalls:sys_enter_mmap --filter=0x812
Cc: Adrian Hunter
Cc: Andi Kleen
Cc: Brendan Gregg
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-8xst3zrqqogax7fmfzwymvbl@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Since its values are in two ranges of values we ended up codifying it
using a 'struct strarrays', so now hook it up with STUL_STRARRAYS so
that we can do:# perf trace -e syscalls:*enter_fcntl --filter=cmd==SETLK||cmd==SETLKW
0.000 sssd_kcm/19021 syscalls:sys_enter_fcntl(fd: 13, cmd: SETLK, arg: 0x7ffcf0a4dee0)
1.523 sssd_kcm/19021 syscalls:sys_enter_fcntl(fd: 13, cmd: SETLK, arg: 0x7ffcf0a4de90)
1.629 sssd_kcm/19021 syscalls:sys_enter_fcntl(fd: 13, cmd: SETLK, arg: 0x7ffcf0a4de90)
2.711 sssd_kcm/19021 syscalls:sys_enter_fcntl(fd: 13, cmd: SETLK, arg: 0x7ffcf0a4de70)
^C#Cc: Adrian Hunter
Cc: Andi Kleen
Cc: Brendan Gregg
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-mob96wyzri4r3rvyigqfjv0a@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
To allow going from string to integer for 'struct strarrays'.
Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-b1ia3xzcy72hv0u4m168fcd0@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
With just what we need for the STUL_STRARRAY, i.e. the 'struct strarray'
pointer to be used, just like with syscall_arg_fmt->scnprintf() for the
other direction (number -> string).With this all the strarrays that are associated with syscalls can be
used with '-e syscalls:sys_enter_SYSCALLNAME --filter', and soon will be
possible as well to use with the strace-like shorter form, with just the
syscall names, i.e. something like:-e lseek/whence==END/
For now we have to use the longer form:
# perf trace -e syscalls:sys_enter_lseek
0.000 pool/2242 syscalls:sys_enter_lseek(fd: 14, offset: 0, whence: CUR)
0.031 pool/2242 syscalls:sys_enter_lseek(fd: 15, offset: 0, whence: CUR)
0.046 pool/2242 syscalls:sys_enter_lseek(fd: 16, offset: 0, whence: CUR)
5003.528 pool/2242 syscalls:sys_enter_lseek(fd: 14, offset: 0, whence: CUR)
5003.575 pool/2242 syscalls:sys_enter_lseek(fd: 15, offset: 0, whence: CUR)
5003.593 pool/2242 syscalls:sys_enter_lseek(fd: 16, offset: 0, whence: CUR)
10002.017 pool/2242 syscalls:sys_enter_lseek(fd: 14, offset: 0, whence: CUR)
10002.051 pool/2242 syscalls:sys_enter_lseek(fd: 15, offset: 0, whence: CUR)
10002.068 pool/2242 syscalls:sys_enter_lseek(fd: 16, offset: 0, whence: CUR)
^C# perf trace -e syscalls:sys_enter_lseek --filter="whence!=CUR"
0.000 sshd/24476 syscalls:sys_enter_lseek(fd: 3, offset: 9032, whence: SET)
0.060 sshd/24476 syscalls:sys_enter_lseek(fd: 3, offset: 9032, whence: SET)
0.187 sshd/24476 syscalls:sys_enter_lseek(fd: 3, offset: 118632, whence: SET)
0.203 sshd/24476 syscalls:sys_enter_lseek(fd: 3, offset: 118632, whence: SET)
0.349 sshd/24476 syscalls:sys_enter_lseek(fd: 3, offset: 61936, whence: SET)
^C#And for those curious about what are those lseek(DSO, offset, SET), well, its the loader:
# perf trace -e syscalls:sys_enter_lseek/max-stack=16/ --filter="whence!=CUR"
0.000 sshd/24495 syscalls:sys_enter_lseek(fd: 3, offset: 9032, whence: SET)
__libc_lseek64 (/usr/lib64/ld-2.29.so)
_dl_map_object (/usr/lib64/ld-2.29.so)
0.067 sshd/24495 syscalls:sys_enter_lseek(fd: 3, offset: 9032, whence: SET)
__libc_lseek64 (/usr/lib64/ld-2.29.so)
_dl_map_object_from_fd (/usr/lib64/ld-2.29.so)
_dl_map_object (/usr/lib64/ld-2.29.so)
0.198 sshd/24495 syscalls:sys_enter_lseek(fd: 3, offset: 118632, whence: SET)
__libc_lseek64 (/usr/lib64/ld-2.29.so)
_dl_map_object (/usr/lib64/ld-2.29.so)
0.219 sshd/24495 syscalls:sys_enter_lseek(fd: 3, offset: 118632, whence: SET)
__libc_lseek64 (/usr/lib64/ld-2.29.so)
_dl_map_object_from_fd (/usr/lib64/ld-2.29.so)
_dl_map_object (/usr/lib64/ld-2.29.so)
^C#:-)
With this we can use strings in strarrays in filters, which allows us to
reuse all these that are in place for syscalls:$ find tools/perf/trace/beauty/ -name "*.c" | xargs grep -w DEFINE_STRARRAY
tools/perf/trace/beauty/fcntl.c: static DEFINE_STRARRAY(fcntl_setlease, "F_");
tools/perf/trace/beauty/mmap.c: static DEFINE_STRARRAY(mmap_flags, "MAP_");
tools/perf/trace/beauty/mmap.c: static DEFINE_STRARRAY(madvise_advices, "MADV_");
tools/perf/trace/beauty/sync_file_range.c: static DEFINE_STRARRAY(sync_file_range_flags, "SYNC_FILE_RANGE_");
tools/perf/trace/beauty/socket.c: static DEFINE_STRARRAY(socket_ipproto, "IPPROTO_");
tools/perf/trace/beauty/mount_flags.c: static DEFINE_STRARRAY(mount_flags, "MS_");
tools/perf/trace/beauty/pkey_alloc.c: static DEFINE_STRARRAY(pkey_alloc_access_rights, "PKEY_");
tools/perf/trace/beauty/sockaddr.c:DEFINE_STRARRAY(socket_families, "PF_");
tools/perf/trace/beauty/tracepoints/x86_irq_vectors.c:static DEFINE_STRARRAY(x86_irq_vectors, "_VECTOR");
tools/perf/trace/beauty/tracepoints/x86_msr.c:static DEFINE_STRARRAY(x86_MSRs, "MSR_");
tools/perf/trace/beauty/prctl.c: static DEFINE_STRARRAY(prctl_options, "PR_");
tools/perf/trace/beauty/prctl.c: static DEFINE_STRARRAY(prctl_set_mm_options, "PR_SET_MM_");
tools/perf/trace/beauty/fspick.c: static DEFINE_STRARRAY(fspick_flags, "FSPICK_");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(ioctl_tty_cmd, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(drm_ioctl_cmds, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(sndrv_pcm_ioctl_cmds, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(sndrv_ctl_ioctl_cmds, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(kvm_ioctl_cmds, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(vhost_virtio_ioctl_cmds, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(vhost_virtio_ioctl_read_cmds, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(perf_ioctl_cmds, "");
tools/perf/trace/beauty/ioctl.c: static DEFINE_STRARRAY(usbdevfs_ioctl_cmds, "");
tools/perf/trace/beauty/fsmount.c: static DEFINE_STRARRAY(fsmount_attr_flags, "MOUNT_ATTR_");
tools/perf/trace/beauty/renameat.c: static DEFINE_STRARRAY(rename_flags, "RENAME_");
tools/perf/trace/beauty/kcmp.c: static DEFINE_STRARRAY(kcmp_types, "KCMP_");
tools/perf/trace/beauty/move_mount.c: static DEFINE_STRARRAY(move_mount_flags, "MOVE_MOUNT_");
$Well, some, as the mmap flags are like:
$ tools/perf/trace/beauty/mmap_flags.sh
static const char *mmap_flags[] = {
[ilog2(0x40) + 1] = "32BIT",
[ilog2(0x01) + 1] = "SHARED",
[ilog2(0x02) + 1] = "PRIVATE",
[ilog2(0x10) + 1] = "FIXED",
[ilog2(0x20) + 1] = "ANONYMOUS",
[ilog2(0x008000) + 1] = "POPULATE",
[ilog2(0x010000) + 1] = "NONBLOCK",
[ilog2(0x020000) + 1] = "STACK",
[ilog2(0x040000) + 1] = "HUGETLB",
[ilog2(0x080000) + 1] = "SYNC",
[ilog2(0x100000) + 1] = "FIXED_NOREPLACE",
[ilog2(0x0100) + 1] = "GROWSDOWN",
[ilog2(0x0800) + 1] = "DENYWRITE",
[ilog2(0x1000) + 1] = "EXECUTABLE",
[ilog2(0x2000) + 1] = "LOCKED",
[ilog2(0x4000) + 1] = "NORESERVE",
};
$So we'll need a strarray__strtoul_flags() that will break donw the flags
into tokens separated by '|' before doing the lookup and then go on
reconstructing the value from, say:# perf trace -e syscalls:sys_enter_mmap --filter="flags==PRIVATE|FIXED|DENYWRITE"
into:
# perf trace -e syscalls:sys_enter_mmap --filter="flags==0x2|0x10|0x0800"
and finally into:
# perf trace -e syscalls:sys_enter_mmap --filter="flags==0x812"
That is what we see if we don't use the augmented view obtained from:
# perf trace -e mmap
211792.885 procmail/15393 mmap(addr: 0x7fcd11645000, len: 8192, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 8, off: 0xa000) = 0x7fcd11645000
But plain use tracefs:
procmail-15559 [000] .... 54557.178262: sys_mmap(addr: 7f5c9bf7a000, len: 9b000, prot: 1, flags: 812, fd: 3, off: a9000)
Cc: Adrian Hunter
Cc: Andi Kleen
Cc: Brendan Gregg
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-c6mgkjt8ujnc263eld5tb7q3@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo
18 Oct, 2019
7 commits
-
We were doing this only at the sys_exit syscall tracepoint, as for
strace-like we count the pair of sys_enter and sys_exit as one event,
but when asking specifically for a the syscalls:sys_enter_NAME
tracepoint we need to count each of those as an event.I.e. things like:
# perf trace --max-events=4 -e syscalls:sys_enter_lseek
0.000 pool/2242 syscalls:sys_enter_lseek(fd: 14, offset: 0, whence: CUR)
0.034 pool/2242 syscalls:sys_enter_lseek(fd: 15, offset: 0, whence: CUR)
0.051 pool/2242 syscalls:sys_enter_lseek(fd: 16, offset: 0, whence: CUR)
2307.900 sshd/30800 syscalls:sys_enter_lseek(fd: 3, offset: 9032, whence: SET)
#Were going on forever, since we only had sys_enter events.
Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-0ob1dky1a9ijlfrfhxyl40wr@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
To go from strarrays strings to its indexes.
Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-wta0qvo207z27huib2c4ijxq@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
From the syscall_fmts->arg entries for formatting strace-like syscalls.
This is when resolving the string "whence" on a filter expression for
the syscalls:sys_enter_lseek:Breakpoint 3, perf_evsel__syscall_arg_fmt (evsel=0xc91ed0, arg=0x7fffffff7cd0 "whence") at builtin-trace.c:3626
3626 {
(gdb) n
3628 struct syscall_arg_fmt *fmt = __evsel__syscall_arg_fmt(evsel);
(gdb) n
3630 if (evsel->tp_format == NULL || fmt == NULL)
(gdb) n
3633 for (field = evsel->tp_format->format.fields; field; field = field->next, ++fmt)
(gdb) n
3634 if (strcmp(field->name, arg) == 0)
(gdb) p field->name
$3 = 0xc945e0 "__syscall_nr"
(gdb) n
3633 for (field = evsel->tp_format->format.fields; field; field = field->next, ++fmt)
(gdb) p *fmt
$4 = {scnprintf = 0x0, strtoul = 0x0, mask_val = 0x0, parm = 0x0, name = 0x0, nr_entries = 0, show_zero = false}
(gdb) n
3634 if (strcmp(field->name, arg) == 0)
(gdb) p field->name
$5 = 0xc94690 "fd"
(gdb) n
3633 for (field = evsel->tp_format->format.fields; field; field = field->next, ++fmt)
(gdb) n
3634 if (strcmp(field->name, arg) == 0)
(gdb) n
3633 for (field = evsel->tp_format->format.fields; field; field = field->next, ++fmt)
(gdb) n
3634 if (strcmp(field->name, arg) == 0)
(gdb) p *fmt
$9 = {scnprintf = 0x489be2 , strtoul = 0x0, mask_val = 0x0, parm = 0xa2da80 , name = 0x0,
nr_entries = 0, show_zero = false}
(gdb) p field->name
$10 = 0xc947b0 "whence"
(gdb) p fmt->parm
$11 = (void *) 0xa2da80
(gdb) p *(struct strarray *)fmt->parm
$12 = {offset = 0, nr_entries = 5, prefix = 0x724d37 "SEEK_", entries = 0xa2da40 }
(gdb) p (struct strarray *)fmt->parm)->entries
Junk after end of expression.
(gdb) p ((struct strarray *)fmt->parm)->entries
$13 = (const char **) 0xa2da40
(gdb) p ((struct strarray *)fmt->parm)->entries[0]
$14 = 0x724d21 "SET"
(gdb) p ((struct strarray *)fmt->parm)->entries[1]
$15 = 0x724d25 "CUR"
(gdb) p ((struct strarray *)fmt->parm)->entries[2]
$16 = 0x724d29 "END"
(gdb) p ((struct strarray *)fmt->parm)->entries[2]
$17 = 0x724d29 "END"
(gdb) p ((struct strarray *)fmt->parm)->entries[3]
$18 = 0x724d2d "DATA"
(gdb) p ((struct strarray *)fmt->parm)->entries[4]
$19 = 0x724d32 "HOLE"
(gdb)Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-lc8h9jgvbnboe0g7ic8tra1y@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
For syscalls we need to cache the 'syscall_id' and 'ret' field offsets
but as well have a pointer to the syscall_fmt_arg array for the fields,
so that we can expand strings in filter expressions, so introduce
a 'struct evsel_trace' to have in evsel->priv that allows for that.Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-hx8ukasuws5sz6rsar73cocv@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Next step will be to have a 'struct evsel_trace' to allow for handling
the syscalls tracepoints via the strace-like code while reusing parts of
that code with the other tracepoints, where we don't have things like
the 'syscall_nr' or 'ret' ((raw_)?syscalls:sys_{enter,exit}(_SYSCALL)?)
args that we want to cache offsets and have been using evsel->priv for
that, while for the other tracepoints we'll have just an array of
'struct syscall_arg_fmt' (i.e. ->scnprint() for number->string and
->strtoul() string->number conversions and other state those functions
need).Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-fre21jbyoqxmmquxcho7oa0x@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
We're using evsel->priv in syscalls:sys_{enter,exit}_SYSCALL and in
raw_syscalls:sys_{enter,exit} to cache the offset of the common fields,
the multiplexor id/syscall_id in the sys_enter case and syscall_id + ret
for sys_exit.And for the rest of the tracepoints we use it to have a syscall_arg_fmt
array to have scnprintf/strtoul for tracepoint args.So we better clearly mark them with accessors so that we can move to
having a 'struct evsel_trace' struct for all 'perf trace' specific
evsel->priv usage.Cc: Adrian Hunter
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-dcoyxfslg7atz821tz9aupjh@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
It was there, but as pr_debug(), make it pr_err() so that we can see it
without -v:# trace -e syscalls:*lseek --filter="whenc==SET" sleep 1
"whenc" not found in "syscalls:sys_enter_lseek", can't set filter "whenc==SET"
#Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-ly4rgm1bto8uwc2itpaixjob@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo
16 Oct, 2019
5 commits
-
Ended up only being useful when filtering multiple irq_vectors
tracepoints, as we end up having a tracepoint for each of the entries,
i.e.:This will always come with the "RESCHEDULE_VECTOR" in the 'vector' arg:
# perf trace --max-events 8 -e irq_vectors:reschedule*
0.000 cc1/29067 irq_vectors:reschedule_entry(vector: RESCHEDULE)
0.004 cc1/29067 irq_vectors:reschedule_exit(vector: RESCHEDULE)
0.553 cc1/29067 irq_vectors:reschedule_entry(vector: RESCHEDULE)
0.556 cc1/29067 irq_vectors:reschedule_exit(vector: RESCHEDULE)
1.182 cc1/29067 irq_vectors:reschedule_entry(vector: RESCHEDULE)
1.185 cc1/29067 irq_vectors:reschedule_exit(vector: RESCHEDULE)
1.203 :29052/29052 irq_vectors:reschedule_entry(vector: RESCHEDULE)
1.206 :29052/29052 irq_vectors:reschedule_exit(vector: RESCHEDULE)
#While filtering that value will produce nothing:
# perf trace --max-events 8 -e irq_vectors:reschedule* --filter="vector != RESCHEDULE"
^C#Maybe it'll be useful for those other tracepoints:
# perf list irq_vectors:vector_*
List of pre-defined events (to be used in -e):
irq_vectors:vector_activate [Tracepoint event]
irq_vectors:vector_alloc [Tracepoint event]
irq_vectors:vector_alloc_managed [Tracepoint event]
irq_vectors:vector_clear [Tracepoint event]
irq_vectors:vector_config [Tracepoint event]
irq_vectors:vector_deactivate [Tracepoint event]
irq_vectors:vector_free_moved [Tracepoint event]
irq_vectors:vector_reserve [Tracepoint event]
irq_vectors:vector_reserve_managed [Tracepoint event]
irq_vectors:vector_setup [Tracepoint event]
irq_vectors:vector_teardown [Tracepoint event]
irq_vectors:vector_update [Tracepoint event]
#But since we have it done, keep it.
This at least served to teach me that all those irq vectors have a entry
and an exit tracepoint that I can then use just like with
raw_syscalls:sys_{enter,exit}, i.e. pair them, use just a
trace__irq_vectors_entry() + trace__irq_vectors_exit() and use the
'vector' arg as I use the 'syscall id' one for syscalls.Then the default for 'perf trace' will include irq_vectors in addition
to syscalls.Cc: Adrian Hunter
Cc: Andi Kleen
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-wer4cwbbqub3o7sa8h1j3uzb@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
In some cases, like with x86 IRQ vectors, the common part in names is at
the end, so a suffix, add a scnprintf function for that.Cc: Adrian Hunter
Cc: Andi Kleen
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-agxbj6es2ke3rehwt4gkdw23@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Things like:
# grep __data_loc /sys/kernel/debug/tracing/events/sched/sched_process_exec/format
field:__data_loc char[] filename; offset:8; size:4; signed:1;
#That, at that offset (8) and with that size(8) have an integer that
contains the real length and offset for the contents of that array.Now this works:
# perf trace --max-events 1 -e sched:*exec -a
0.000 sed/19441 sched:sched_process_exec(filename: "/usr/bin/sync", pid: 19441 (sync), old_pid: 19441 (sync))
#As when using the libtraceevent based beautifier:
# perf trace --libtraceevent --max-events 1 -e sched:*exec -a
0.000 sync/19463 sched:sched_process_exec(filename=/usr/bin/sync pid=19463 old_pid=19463)
#I.e. that 'filename' is implemented as a dynamic char array.
Cc: Adrian Hunter
Cc: Andi Kleen
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-950p0m842fe6n7sxsdwqj5i2@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
When doing a system wide 'perf trace record' we need, just like in 'perf
trace' live mode, to filter out perf trace's own pid, so set up a
tracepoint filter for the raw_syscalls tracepoints right after adding
them to the argv array that is set up to then call cmd_record().Reported-by: Andi Kleen
Cc: Adrian Hunter
Cc: David Ahern
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-uysx5w8f2y5ndoln5cq370tv@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
To be used with -S or -s, using just this new option implies -s,
examples:# perf trace --errno-summary sleep 1
Summary of events:
sleep (10793), 80 events, 93.0%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
nanosleep 1 0 1000.427 1000.427 1000.427 1000.427 0.00%
mmap 8 0 0.026 0.002 0.003 0.005 9.18%
close 5 0 0.018 0.001 0.004 0.009 48.97%
mprotect 4 0 0.017 0.003 0.004 0.006 16.49%
openat 3 0 0.012 0.003 0.004 0.005 9.41%
munmap 1 0 0.010 0.010 0.010 0.010 0.00%
brk 4 0 0.005 0.001 0.001 0.002 22.77%
read 4 0 0.005 0.001 0.001 0.002 22.33%
access 1 1 0.004 0.004 0.004 0.004 0.00%
ENOENT: 1
fstat 3 0 0.004 0.001 0.001 0.002 17.18%
lseek 3 0 0.003 0.001 0.001 0.001 11.62%
arch_prctl 2 1 0.002 0.001 0.001 0.001 3.32%
EINVAL: 1
execve 1 0 0.000 0.000 0.000 0.000 0.00%#
Works as well together with --failure and -S, i.e. collect the stats and
show just the syscalls that failed:# perf trace --failure -S --errno-summary sleep 1
0.032 arch_prctl(option: 0x3001, arg2: 0x7fffdb11b580) = -1 EINVAL (Invalid argument)
0.045 access(filename: "/etc/ld.so.preload", mode: R) = -1 ENOENT (No such file or directory)Summary of events:
sleep (10806), 80 events, 93.0%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
nanosleep 1 0 1000.094 1000.094 1000.094 1000.094 0.00%
mmap 8 0 0.026 0.002 0.003 0.005 9.06%
close 5 0 0.018 0.001 0.004 0.010 49.58%
mprotect 4 0 0.017 0.003 0.004 0.006 17.56%
openat 3 0 0.014 0.004 0.005 0.006 12.29%
munmap 1 0 0.010 0.010 0.010 0.010 0.00%
brk 4 0 0.005 0.001 0.001 0.002 22.75%
read 4 0 0.005 0.001 0.001 0.002 17.19%
access 1 1 0.005 0.005 0.005 0.005 0.00%
ENOENT: 1
fstat 3 0 0.004 0.001 0.001 0.002 21.66%
lseek 3 0 0.003 0.001 0.001 0.001 11.71%
arch_prctl 2 1 0.002 0.001 0.001 0.001 2.66%
EINVAL: 1
execve 1 0 0.000 0.000 0.000 0.000 0.00%#
Suggested-by: Andi Kleen
Cc: Adrian Hunter
Cc: Brendan Gregg
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-l0mjwczkpouov7lss5zn8d9h@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo
15 Oct, 2019
1 commit
-
Just like strace has:
# trace -s sleep 1
Summary of events:
sleep (32370), 80 events, 93.0%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
nanosleep 1 0 1000.402 1000.402 1000.402 1000.402 0.00%
mmap 8 0 0.023 0.002 0.003 0.004 8.49%
close 5 0 0.015 0.001 0.003 0.009 51.39%
mprotect 4 0 0.014 0.002 0.003 0.005 16.95%
openat 3 0 0.013 0.003 0.004 0.005 14.29%
munmap 1 0 0.010 0.010 0.010 0.010 0.00%
read 4 0 0.005 0.001 0.001 0.002 16.83%
brk 4 0 0.004 0.001 0.001 0.002 20.82%
access 1 1 0.004 0.004 0.004 0.004 0.00%
fstat 3 0 0.003 0.001 0.001 0.001 12.17%
lseek 3 0 0.003 0.001 0.001 0.001 11.45%
arch_prctl 2 1 0.002 0.001 0.001 0.001 2.30%
execve 1 0 0.000 0.000 0.000 0.000 0.00%#
# perf trace -S sleep 1
? ... [continued]: execve()) = 0
0.028 brk(brk: NULL) = 0x559f5bd96000
0.033 arch_prctl(option: 0x3001, arg2: 0x7ffda8b715a0) = -1 EINVAL (Invalid argument)
0.046 access(filename: "/etc/ld.so.preload", mode: R) = -1 ENOENT (No such file or directory)
0.055 openat(dfd: CWD, filename: "/etc/ld.so.cache", flags: RDONLY|CLOEXEC) = 3
0.060 fstat(fd: 3, statbuf: 0x7ffda8b707a0) = 0
0.062 mmap(addr: NULL, len: 134346, prot: READ, flags: PRIVATE, fd: 3, off: 0) = 0x7f3aedfc4000
0.066 close(fd: 3) = 0
0.079 openat(dfd: CWD, filename: "/lib64/libc.so.6", flags: RDONLY|CLOEXEC) = 3
0.085 read(fd: 3, buf: 0x7ffda8b70948, count: 832) = 832
0.088 lseek(fd: 3, offset: 792, whence: SET) = 792
0.090 read(fd: 3, buf: 0x7ffda8b70810, count: 68) = 68
0.093 fstat(fd: 3, statbuf: 0x7ffda8b707f0) = 0
0.095 mmap(addr: NULL, len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7f3aedfc2000
0.101 lseek(fd: 3, offset: 792, whence: SET) = 792
0.103 read(fd: 3, buf: 0x7ffda8b70450, count: 68) = 68
0.105 lseek(fd: 3, offset: 864, whence: SET) = 864
0.107 read(fd: 3, buf: 0x7ffda8b70470, count: 32) = 32
0.110 mmap(addr: NULL, len: 1857472, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3, off: 0) = 0x7f3aeddfc000
0.114 mprotect(start: 0x7f3aede1e000, len: 1679360, prot: NONE) = 0
0.121 mmap(addr: 0x7f3aede1e000, len: 1363968, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x22000) = 0x7f3aede1e000
0.127 mmap(addr: 0x7f3aedf6b000, len: 311296, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x16f000) = 0x7f3aedf6b000
0.131 mmap(addr: 0x7f3aedfb8000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1bb000) = 0x7f3aedfb8000
0.138 mmap(addr: 0x7f3aedfbe000, len: 14272, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7f3aedfbe000
0.147 close(fd: 3) = 0
0.158 arch_prctl(option: SET_FS, arg2: 0x7f3aedfc3580) = 0
0.210 mprotect(start: 0x7f3aedfb8000, len: 16384, prot: READ) = 0
0.230 mprotect(start: 0x559f5b27d000, len: 4096, prot: READ) = 0
0.236 mprotect(start: 0x7f3aee00f000, len: 4096, prot: READ) = 0
0.240 munmap(addr: 0x7f3aedfc4000, len: 134346) = 0
0.300 brk(brk: NULL) = 0x559f5bd96000
0.302 brk(brk: 0x559f5bdb7000) = 0x559f5bdb7000
0.305 brk(brk: NULL) = 0x559f5bdb7000
0.310 openat(dfd: CWD, filename: "/usr/lib/locale/locale-archive", flags: RDONLY|CLOEXEC) = 3
0.315 fstat(fd: 3, statbuf: 0x7f3aedfbdac0) = 0
0.318 mmap(addr: NULL, len: 217750512, prot: READ, flags: PRIVATE, fd: 3, off: 0) = 0x7f3ae0e52000
0.325 close(fd: 3) = 0
0.358 nanosleep(rqtp: 0x7ffda8b714b0, rmtp: NULL) = 0
1000.622 close(fd: 1) = 0
1000.641 close(fd: 2) = 0
1000.664 exit_group(error_code: 0) = ?Summary of events:
sleep (722), 80 events, 93.0%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
nanosleep 1 0 1000.194 1000.194 1000.194 1000.194 0.00%
mmap 8 0 0.025 0.002 0.003 0.005 10.17%
close 5 0 0.018 0.001 0.004 0.010 50.18%
mprotect 4 0 0.016 0.003 0.004 0.006 16.81%
openat 3 0 0.011 0.003 0.004 0.004 6.57%
munmap 1 0 0.010 0.010 0.010 0.010 0.00%
brk 4 0 0.005 0.001 0.001 0.002 20.72%
read 4 0 0.005 0.001 0.001 0.002 16.71%
access 1 1 0.005 0.005 0.005 0.005 0.00%
fstat 3 0 0.004 0.001 0.001 0.002 14.82%
lseek 3 0 0.003 0.001 0.001 0.001 11.66%
arch_prctl 2 1 0.002 0.001 0.001 0.001 3.59%
execve 1 0 0.000 0.000 0.000 0.000 0.00%#
Works for system wide, e.g. for 1ms:
# perf trace -s -a sleep 0.001
Summary of events:
sleep (768), 94 events, 37.9%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
nanosleep 1 0 1.133 1.133 1.133 1.133 0.00%
execve 7 6 0.351 0.003 0.050 0.316 88.53%
mmap 8 0 0.024 0.002 0.003 0.004 8.86%
mprotect 4 0 0.017 0.003 0.004 0.006 16.02%
openat 3 0 0.013 0.004 0.004 0.005 8.34%
munmap 1 0 0.010 0.010 0.010 0.010 0.00%
brk 4 0 0.007 0.001 0.002 0.002 10.99%
close 5 0 0.005 0.001 0.001 0.002 11.69%
read 5 0 0.005 0.000 0.001 0.002 30.53%
access 1 1 0.004 0.004 0.004 0.004 0.00%
fstat 3 0 0.004 0.001 0.001 0.002 10.74%
lseek 3 0 0.003 0.001 0.001 0.001 10.20%
arch_prctl 2 1 0.002 0.001 0.001 0.001 3.34%Web Content (21258), 46 events, 18.5%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
recvmsg 12 12 0.015 0.001 0.001 0.002 8.50%
futex 2 0 0.008 0.003 0.004 0.005 27.08%
poll 6 0 0.006 0.000 0.001 0.002 22.14%
read 2 0 0.006 0.002 0.003 0.003 26.08%
write 1 0 0.002 0.002 0.002 0.002 0.00%Web Content (4365), 36 events, 14.5%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
recvmsg 10 10 0.015 0.001 0.002 0.003 11.83%
poll 5 0 0.006 0.000 0.001 0.002 28.44%
futex 2 0 0.005 0.001 0.003 0.004 48.29%
read 1 0 0.003 0.003 0.003 0.003 0.00%Timer (21275), 14 events, 5.6%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
futex 6 1 0.240 0.000 0.040 0.149 64.58%
write 1 0 0.008 0.008 0.008 0.008 0.00%Timer (4383), 14 events, 5.6%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
futex 6 2 0.186 0.000 0.031 0.181 96.45%
write 1 0 0.010 0.010 0.010 0.010 0.00%Web Content (20354), 28 events, 11.3%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
recvmsg 8 8 0.010 0.001 0.001 0.002 15.24%
poll 4 0 0.004 0.000 0.001 0.002 35.68%
futex 1 0 0.003 0.003 0.003 0.003 0.00%
read 1 0 0.003 0.003 0.003 0.003 0.00%Timer (20371), 10 events, 4.0%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
futex 4 1 0.077 0.000 0.019 0.075 95.46%
write 1 0 0.005 0.005 0.005 0.005 0.00%[root@quaco ~]#
Cc: Adrian Hunter
Cc: Andi Kleen
Cc: Brendan Gregg
Cc: Jiri Olsa
Cc: Luis Cláudio Gonçalves
Cc: Namhyung Kim
Link: https://lkml.kernel.org/n/tip-k7kh2muo5oeg56yx446hnw9v@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo
10 Oct, 2019
4 commits
-
Move perf_mmap__read_event() from tools/perf to libperf and export it in
the perf/mmap.h header.Signed-off-by: Jiri Olsa
Cc: Alexander Shishkin
Cc: Michael Petlan
Cc: Namhyung Kim
Cc: Peter Zijlstra
Link: http://lore.kernel.org/lkml/20191007125344.14268-13-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Move perf_mmap__read_init() from tools/perf to libperf and export it in
the perf/mmap.h header.Signed-off-by: Jiri Olsa
Cc: Alexander Shishkin
Cc: Michael Petlan
Cc: Namhyung Kim
Cc: Peter Zijlstra
Link: http://lore.kernel.org/lkml/20191007125344.14268-12-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Move perf_mmap__read_init() from tools/perf to libperf and export it in
perf/mmap.h header.And add pr_debug2()/pr_debug3() macros support, because the code is
using them.Signed-off-by: Jiri Olsa
Cc: Alexander Shishkin
Cc: Michael Petlan
Cc: Namhyung Kim
Cc: Peter Zijlstra
Link: http://lore.kernel.org/lkml/20191007125344.14268-11-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo -
Move perf_mmap__consume() vrom tools/perf to libperf and export it in
the perf/mmap.h header.Move also the needed helpers perf_mmap__write_tail(),
perf_mmap__read_head() and perf_mmap__empty().Signed-off-by: Jiri Olsa
Cc: Alexander Shishkin
Cc: Michael Petlan
Cc: Namhyung Kim
Cc: Peter Zijlstra
Link: http://lore.kernel.org/lkml/20191007125344.14268-10-jolsa@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo