Bug 207301
| Summary: | Missing application stacktrace when profiling sleeping times | ||
|---|---|---|---|
| Product: | Tracing/Profiling | Reporter: | Konstantin Kharlamov (hi-angel) |
| Component: | Perf tool | Assignee: | Arnaldo Carvalho de Melo (acme) |
| Status: | RESOLVED INVALID | ||
| Severity: | normal | CC: | jolsa |
| Priority: | P1 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| See Also: | https://bugzilla.kernel.org/show_bug.cgi?id=207777 | ||
| Kernel Version: | 5.6.2 | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
|
Description
Konstantin Kharlamov
2020-04-16 10:33:37 UTC
s/5.2 kernel/5.6.2 kernel So, I did a bit of research, and it seems the problem is that neither `sched:sched_stat_sleep` nor `sched:sched_switch` event give a stack in context of the profilee. And I just realized: the example trace in the tutorial on kernel Wiki has the same problem, no useful stack. It seems that the problem here is misinformation on the Wiki article, nothing to do with perf. Still, that begs again the question: how does one profile latency/sleep with perf? I think it would be correct to close this report as INVALID, and reopen an RFE for perf to allow profiling latency. Closing. The feature request is filled over at https://bugzilla.kernel.org/show_bug.cgi?id=207323 So, can you try using 'perf trace', syscalls strace-like + the tracepoints you want to see?
I.e. try:
[root@five ~]# perf trace -e sched:* --syscalls sleep 1
0.000 ( ): :35241/35241 sched:sched_waking(comm: "perf", pid: 35242 (perf), prio: 120, success: 1, target_cpu: 2)
0.005 ( ): :35241/35241 sched:sched_wakeup(comm: "perf", pid: 35242 (perf), prio: 120, success: 1, target_cpu: 2)
0.372 ( ): sleep/35242 sched:sched_process_exec(filename: "/usr/bin/sleep", pid: 35242 (sleep), old_pid: 35242 (sleep))
? ( ): sleep/35242 ... [continued]: execve()) = 0
0.394 ( 0.002 ms): sleep/35242 brk() = 0x55c5a396e000
0.400 ( 0.002 ms): sleep/35242 arch_prctl(option: 0x3001, arg2: 0x7ffe65f58da0) = -1 EINVAL (Invalid argument)
0.413 ( 0.005 ms): sleep/35242 access(filename: 0xfd877850, mode: R) = -1 ENOENT (No such file or directory)
0.421 ( 0.003 ms): sleep/35242 openat(dfd: CWD, filename: 0xfd874a29, flags: RDONLY|CLOEXEC) = 3
0.425 ( 0.001 ms): sleep/35242 fstat(fd: 3, statbuf: 0x7ffe65f57fa0) = 0
0.428 ( 0.006 ms): sleep/35242 mmap(len: 119797, prot: READ, flags: PRIVATE, fd: 3) = 0x7fdcfd833000
0.435 ( 0.001 ms): sleep/35242 close(fd: 3) = 0
0.442 ( 0.003 ms): sleep/35242 openat(dfd: CWD, filename: 0xfd87ed20, flags: RDONLY|CLOEXEC) = 3
0.446 ( 0.002 ms): sleep/35242 read(fd: 3, buf: 0x7ffe65f58148, count: 832) = 832
0.449 ( 0.001 ms): sleep/35242 lseek(fd: 3, offset: 64, whence: SET) = 64
0.451 ( 0.001 ms): sleep/35242 read(fd: 3, buf: 0x7ffe65f57d40, count: 784) = 784
0.453 ( 0.001 ms): sleep/35242 lseek(fd: 3, offset: 848, whence: SET) = 848
0.455 ( 0.001 ms): sleep/35242 read(fd: 3, buf: 0x7ffe65f57d10, count: 32) = 32
0.458 ( 0.001 ms): sleep/35242 lseek(fd: 3, offset: 880, whence: SET) = 880
0.460 ( 0.001 ms): sleep/35242 read(fd: 3, buf: 0x7ffe65f57cc0, count: 68) = 68
0.462 ( 0.001 ms): sleep/35242 fstat(fd: 3, statbuf: 0x7ffe65f57ff0) = 0
0.465 ( 0.005 ms): sleep/35242 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7fdcfd831000
0.472 ( 0.001 ms): sleep/35242 lseek(fd: 3, offset: 64, whence: SET) = 64
0.474 ( 0.001 ms): sleep/35242 read(fd: 3, buf: 0x7ffe65f57c40, count: 784) = 784
0.477 ( 0.001 ms): sleep/35242 lseek(fd: 3, offset: 848, whence: SET) = 848
0.479 ( 0.001 ms): sleep/35242 read(fd: 3, buf: 0x7ffe65f57920, count: 32) = 32
0.481 ( 0.001 ms): sleep/35242 lseek(fd: 3, offset: 880, whence: SET) = 880
0.483 ( 0.001 ms): sleep/35242 read(fd: 3, buf: 0x7ffe65f57900, count: 68) = 68
0.486 ( 0.006 ms): sleep/35242 mmap(len: 1868728, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7fdcfd668000
0.493 ( 0.008 ms): sleep/35242 mprotect(start: 0x7fdcfd68d000, len: 1679360) = 0
0.502 ( 0.011 ms): sleep/35242 mmap(addr: 0x7fdcfd68d000, len: 1372160, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x25000) = 0x7fdcfd68d000
0.514 ( 0.006 ms): sleep/35242 mmap(addr: 0x7fdcfd7dc000, len: 303104, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x174000) = 0x7fdcfd7dc000
0.521 ( 0.006 ms): sleep/35242 mmap(addr: 0x7fdcfd827000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1be000) = 0x7fdcfd827000
0.530 ( 0.006 ms): sleep/35242 mmap(addr: 0x7fdcfd82d000, len: 13240, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7fdcfd82d000
0.539 ( 0.001 ms): sleep/35242 close(fd: 3) = 0
0.548 ( 0.001 ms): sleep/35242 arch_prctl(option: SET_FS, arg2: 0x7fdcfd832580) = 0
0.581 ( 0.006 ms): sleep/35242 mprotect(start: 0x7fdcfd827000, len: 12288, prot: READ) = 0
0.595 ( 0.006 ms): sleep/35242 mprotect(start: 0x55c5a3207000, len: 4096, prot: READ) = 0
0.603 ( 0.006 ms): sleep/35242 mprotect(start: 0x7fdcfd87c000, len: 4096, prot: READ) = 0
0.611 ( 0.005 ms): sleep/35242 munmap(addr: 0x7fdcfd833000, len: 119797) = 0
0.648 ( 0.001 ms): sleep/35242 brk() = 0x55c5a396e000
0.651 ( 0.005 ms): sleep/35242 brk(brk: 0x55c5a398f000) = 0x55c5a398f000
0.657 ( 0.001 ms): sleep/35242 brk() = 0x55c5a398f000
0.661 ( 0.003 ms): sleep/35242 openat(dfd: CWD, filename: 0xfd7fc660, flags: RDONLY|CLOEXEC) = 3
0.666 ( 0.001 ms): sleep/35242 fstat(fd: 3, statbuf: 0x7fdcfd82c520) = 0
0.668 ( 0.006 ms): sleep/35242 mmap(len: 217990208, prot: READ, flags: PRIVATE, fd: 3) = 0x7fdcf0683000
0.678 ( 0.001 ms): sleep/35242 close(fd: 3) = 0
0.702 ( ): sleep/35242 nanosleep(rqtp: 0x7ffe65f58cb0) ...
0.705 ( ): sleep/35242 sched:sched_stat_runtime(comm: "sleep", pid: 35242 (sleep), runtime: 598301, vruntime: 1815260801)
0.706 ( ): sleep/35242 sched:sched_switch(prev_comm: "sleep", prev_pid: 35242 (sleep), prev_prio: 120, prev_state: 1, next_comm: "swapper/11", next_prio: 120)
1000.767 ( ): :0/0 sched:sched_waking(comm: "sleep", pid: 35242 (sleep), prio: 120, success: 1, target_cpu: 11)
1000.777 ( ): :0/0 sched:sched_wakeup(comm: "sleep", pid: 35242 (sleep), prio: 120, success: 1, target_cpu: 11)
0.702 (1000.095 ms): sleep/35242 ... [continued]: nanosleep()) = 0
1000.808 ( 0.005 ms): sleep/35242 close(fd: 1) = 0
1000.817 ( 0.004 ms): sleep/35242 close(fd: 2) = 0
1000.827 ( ): sleep/35242 exit_group() = ?
1000.883 ( ): sleep/35242 sched:sched_process_exit(comm: "sleep", pid: 35242 (sleep), prio: 120)
[root@five ~]#
you can ask for tracepoints for specific tracepoints, like:
perf trace -e sched:*/max-stack=16/ --syscalls sleep 1
And only those tracepoints will have backtraces, etc.
The time the syscalls take and what happens in the tracepoints in the kernel may help you understand where is it that it is waiting for something else and what was it in the kernel that made it go wait, etc.
for instance:
[root@five ~]# perf trace -e *sleep,sched:*wak*,sched:*switch/max-stack=10/ sleep 1
0.000 ( ): :35647/35647 sched:sched_waking(comm: "perf", pid: 35648 (perf), prio: 120, success: 1, target_cpu: 2)
0.005 ( ): :35647/35647 sched:sched_wakeup(comm: "perf", pid: 35648 (perf), prio: 120, success: 1, target_cpu: 2)
0.734 ( ): sleep/35648 nanosleep(rqtp: 0x7ffe4c5fca50) ...
0.744 ( ): sleep/35648 sched:sched_switch(prev_comm: "sleep", prev_pid: 35648 (sleep), prev_prio: 120, prev_state: 1, next_comm: "swapper/10", next_prio: 120)
__schedule ([kernel.kallsyms])
__schedule ([kernel.kallsyms])
schedule ([kernel.kallsyms])
do_nanosleep ([kernel.kallsyms])
hrtimer_nanosleep ([kernel.kallsyms])
__x64_sys_nanosleep ([kernel.kallsyms])
do_syscall_64 ([kernel.kallsyms])
entry_SYSCALL_64 ([kernel.kallsyms])
__nanosleep (/usr/lib64/libc-2.30.so)
1000.798 ( ): :0/0 sched:sched_waking(comm: "sleep", pid: 35648 (sleep), prio: 120, success: 1, target_cpu: 10)
1000.802 ( ): :0/0 sched:sched_wakeup(comm: "sleep", pid: 35648 (sleep), prio: 120, success: 1, target_cpu: 10)
0.734 (1000.080 ms): sleep/35648 ... [continued]: nanosleep()) = 0
[root@five ~]#
Another suggestion, look for syscalls taking more than some threshold (in milliseconds) and exclude some of the select, poll, futex, i.e. operations with timeouts:
[root@five ~]# perf trace --duration=0.5 -e \!*poll*,futex,*select*,*sleep
2527.492 ( 1.795 ms): pool/2368 read(fd: 7<socket:[365237]>, buf: 0x7f8c02a56a20, count: 4) = 4
2529.302 ( 1.821 ms): pool/2368 read(fd: 7<socket:[365237]>, buf: 0x7f8c02a56a20, count: 4) = 4
2531.141 ( 1.658 ms): pool/2368 read(fd: 7<socket:[365237]>, buf: 0x7f8c02a569d0, count: 4) = 4
5101.466 ( 8.105 ms): ThreadPoolFore/28180 fdatasync(fd: 403</home/acme/.config/chromium/Default/Cookies-journal>) = 0
5109.584 ( 2.339 ms): ThreadPoolFore/28180 fdatasync(fd: 434</home/acme/.config/chromium/Default>) = 0
5111.953 ( 0.660 ms): ThreadPoolFore/28180 fdatasync(fd: 403</home/acme/.config/chromium/Default/Cookies-journal>) = 0
5112.706 ( 1.189 ms): ThreadPoolFore/28180 fdatasync(fd: 402</home/acme/.config/chromium/Default/Cookies>) = 0
5113.938 ( 2.313 ms): ThreadPoolFore/28180 fdatasync(fd: 403</home/acme/.config/chromium/Default/Cookies-journal>) = 0
5278.970 ( 4.045 ms): ThreadPoolFore/28180 fdatasync(fd: 414) = 0
7527.541 ( 1.698 ms): pool/2368 read(fd: 7<socket:[365299]>, buf: 0x7f8c02a56a20, count: 4) = 4
7529.269 ( 1.729 ms): pool/2368 read(fd: 7<socket:[365299]>, buf: 0x7f8c02a56a20, count: 4) = 4
7531.027 ( 1.589 ms): pool/2368 read(fd: 7<socket:[365299]>, buf: 0x7f8c02a569d0, count: 4) = 4
^C[root@five ~]#
Thank you! Unfortunately I didn't manage to explore `perf trace` utility too much because it mostly crashes on me, in particular when running e.g. `ping localhost` in place of `sleep 1`. But from what I can see it is just a trace for system calls on locks/sleeps/etc enriched with time spent sleeping. I.e. it is not a tree of stacktraces with *accumulated* time spent sleeping, like the one `perf report` would give, and nothing to create a Flamegraph from. While this may help with some trivial apps, but for any complex ones with lots of threads, locks between them, IO-activity, etc, this approach would get you overwhelmed with the amount of output from various places. To make it even more complicated, at work I'm debugging a workload where a kernel module spawns a bunch of threads, and I have no idea exactly which one has the problem, so I had to do a system-wide 30 seconds record hoping to see an offender among those threads :) [root@seventh ~]# uname -a
Linux seventh 5.6.0-00026-ga241c89060e9 #1 SMP Mon Apr 6 12:21:10 -03 2020 x86_64 x86_64 x86_64 GNU/Linux
[root@seventh ~]# perf -vv
perf version 5.7.rc1.g06b233aa2eb5
dwarf: [ on ] # HAVE_DWARF_SUPPORT
dwarf_getlocations: [ on ] # HAVE_DWARF_GETLOCATIONS_SUPPORT
glibc: [ on ] # HAVE_GLIBC_SUPPORT
gtk2: [ on ] # HAVE_GTK2_SUPPORT
syscall_table: [ on ] # HAVE_SYSCALL_TABLE_SUPPORT
libbfd: [ on ] # HAVE_LIBBFD_SUPPORT
libelf: [ on ] # HAVE_LIBELF_SUPPORT
libnuma: [ on ] # HAVE_LIBNUMA_SUPPORT
numa_num_possible_cpus: [ on ] # HAVE_LIBNUMA_SUPPORT
libperl: [ on ] # HAVE_LIBPERL_SUPPORT
libpython: [ on ] # HAVE_LIBPYTHON_SUPPORT
libslang: [ on ] # HAVE_SLANG_SUPPORT
libcrypto: [ on ] # HAVE_LIBCRYPTO_SUPPORT
libunwind: [ on ] # HAVE_LIBUNWIND_SUPPORT
libdw-dwarf-unwind: [ on ] # HAVE_DWARF_SUPPORT
zlib: [ on ] # HAVE_ZLIB_SUPPORT
lzma: [ on ] # HAVE_LZMA_SUPPORT
get_cpuid: [ on ] # HAVE_AUXTRACE_SUPPORT
bpf: [ on ] # HAVE_LIBBPF_SUPPORT
aio: [ on ] # HAVE_AIO_SUPPORT
zstd: [ on ] # HAVE_ZSTD_SUPPORT
[root@seventh ~]# perf trace ping localhost
? ( ): ping/19709 ... [continued]: execve()) = 0
0.024 ( 0.001 ms): ping/19709 brk() = 0x56341a4c2000
0.029 ( 0.001 ms): ping/19709 arch_prctl(option: 0x3001, arg2: 0x7ffffa374db0) = -1 EINVAL (Invalid argument)
0.041 ( 0.004 ms): ping/19709 access(filename: 0x28fe55a0, mode: R) = -1 ENOENT (No such file or directory)
0.048 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fe29ef, flags: RDONLY|CLOEXEC) = 3
0.052 ( 0.001 ms): ping/19709 fstat(fd: 3, statbuf: 0x7ffffa373fb0) = 0
0.054 ( 0.002 ms): ping/19709 mmap(len: 117946, prot: READ, flags: PRIVATE, fd: 3) = 0x7faa28fa3000
0.057 ( 0.001 ms): ping/19709 close(fd: 3) = 0
0.065 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fecd00, flags: RDONLY|CLOEXEC) = 3
0.070 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa374158, count: 832) = 832
0.073 ( 0.001 ms): ping/19709 lseek(fd: 3, offset: 18984, whence: SET) = 18984
0.074 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa374040, count: 32) = 32
0.077 ( 0.001 ms): ping/19709 fstat(fd: 3, statbuf: 0x7ffffa374000) = 0
0.079 ( 0.002 ms): ping/19709 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7faa28fa1000
0.083 ( 0.001 ms): ping/19709 lseek(fd: 3, offset: 18984, whence: SET) = 18984
0.085 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa373d10, count: 32) = 32
0.087 ( 0.003 ms): ping/19709 mmap(len: 24896, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa28f9a000
0.091 ( 0.005 ms): ping/19709 mmap(addr: 0x7faa28f9c000, len: 8192, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x2000) = 0x7faa28f9c000
0.097 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28f9e000, len: 4096, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x4000) = 0x7faa28f9e000
0.101 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28f9f000, len: 8192, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x4000) = 0x7faa28f9f000
0.109 ( 0.001 ms): ping/19709 close(fd: 3</usr/lib/locale/locale-archive>) = 0
0.113 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fa14d0, flags: RDONLY|CLOEXEC) = 3
0.117 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa374138, count: 832) = 832
0.119 ( 0.001 ms): ping/19709 lseek(fd: 3, offset: 129752, whence: SET) = 129752
0.121 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa374020, count: 32) = 32
0.123 ( 0.001 ms): ping/19709 fstat(fd: 3, statbuf: 0x7ffffa373fe0) = 0
0.125 ( 0.001 ms): ping/19709 lseek(fd: 3, offset: 129752, whence: SET) = 129752
0.127 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa373cf0, count: 32) = 32
0.129 ( 0.002 ms): ping/19709 mmap(len: 135184, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa28f78000
0.132 ( 0.004 ms): ping/19709 mmap(addr: 0x7faa28f7a000, len: 20480, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x2000) = 0x7faa28f7a000
0.137 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28f7f000, len: 102400, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x7000) = 0x7faa28f7f000
0.141 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28f98000, len: 4096, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1f000) = 0x7faa28f98000
0.144 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28f99000, len: 16, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7faa28f99000
0.150 ( 0.001 ms): ping/19709 close(fd: 3) = 0
0.154 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fa19c0, flags: RDONLY|CLOEXEC) = 3
0.157 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa374118, count: 832) = 832
0.160 ( 0.001 ms): ping/19709 fstat(fd: 3, statbuf: 0x7ffffa373fc0) = 0
0.162 ( 0.003 ms): ping/19709 mmap(len: 3014528, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa28c98000
0.165 ( 0.005 ms): ping/19709 mprotect(start: 0x7faa28d11000, len: 2310144) = 0
0.171 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28d11000, len: 1712128, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x79000) = 0x7faa28d11000
0.175 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28eb3000, len: 593920, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x21b000) = 0x7faa28eb3000
0.179 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28f45000, len: 192512, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x2ac000) = 0x7faa28f45000
0.185 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28f74000, len: 16256, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7faa28f74000
0.191 ( 0.001 ms): ping/19709 close(fd: 3) = 0
0.199 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fa1eb0, flags: RDONLY|CLOEXEC) = 3
0.203 ( 0.001 ms): ping/19709 read(fd: 3, buf: 0x7ffffa3740f8, count: 832) = 832
0.205 ( 0.001 ms): ping/19709 fstat(fd: 3, statbuf: 0x7ffffa373fa0) = 0
0.208 ( 0.003 ms): ping/19709 mmap(len: 105088, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa28c7e000
0.212 ( 0.004 ms): ping/19709 mprotect(start: 0x7faa28c82000, len: 73728) = 0
0.217 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28c82000, len: 53248, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x4000) = 0x7faa28c82000
0.221 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28c8f000, len: 16384, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x11000) = 0x7faa28c8f000
0.224 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28c94000, len: 8192, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x15000) = 0x7faa28c94000
0.229 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28c96000, len: 6784, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7faa28c96000
0.235 ( 0.001 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
0.239 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fa23a0, flags: RDONLY|CLOEXEC) = 3
0.243 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa3740d8, count: 832) = 832
0.245 ( 0.001 ms): ping/19709 fstat(fd: 3<socket:[419069]>, statbuf: 0x7ffffa373f80) = 0
0.247 ( 0.003 ms): ping/19709 mmap(len: 1331456, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa28b38000
0.251 ( 0.004 ms): ping/19709 mmap(addr: 0x7faa28b45000, len: 638976, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0xd000) = 0x7faa28b45000
0.256 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28be1000, len: 634880, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0xa9000) = 0x7faa28be1000
0.260 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28c7c000, len: 8192, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x143000) = 0x7faa28c7c000
0.269 ( 0.008 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
0.281 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fa2890, flags: RDONLY|CLOEXEC) = 3
0.285 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa3740b8, count: 832) = 832
0.287 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 792, whence: SET) = 792
0.289 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373f80, count: 68) = 68
0.291 ( 0.001 ms): ping/19709 fstat(fd: 3<socket:[419069]>, statbuf: 0x7ffffa373f60) = 0
0.293 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 792, whence: SET) = 792
0.295 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373bc0, count: 68) = 68
0.296 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 864, whence: SET) = 864
0.298 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373be0, count: 32) = 32
0.300 ( 0.003 ms): ping/19709 mmap(len: 1857280, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa28972000
0.304 ( 0.004 ms): ping/19709 mprotect(start: 0x7faa28994000, len: 1679360) = 0
0.309 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28994000, len: 1363968, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x22000) = 0x7faa28994000
0.313 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28ae1000, len: 311296, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x16f000) = 0x7faa28ae1000
0.317 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28b2e000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1bb000) = 0x7faa28b2e000
0.323 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28b34000, len: 14080, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7faa28b34000
0.329 ( 0.001 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
0.337 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28fa2db0, flags: RDONLY|CLOEXEC) = 3
0.341 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa374098, count: 832) = 832
0.343 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 1566912, whence: SET) = 1566912
0.345 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373f80, count: 32) = 32
0.347 ( 0.001 ms): ping/19709 fstat(fd: 3<socket:[419069]>, statbuf: 0x7ffffa373f40) = 0
0.349 ( 0.002 ms): ping/19709 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7faa28970000
0.353 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 1566912, whence: SET) = 1566912
0.355 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373c50, count: 32) = 32
0.357 ( 0.002 ms): ping/19709 mmap(len: 1587432, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa287ec000
0.360 ( 0.005 ms): ping/19709 mmap(addr: 0x7faa287fd000, len: 225280, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x11000) = 0x7faa287fd000
0.366 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28834000, len: 1273856, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x48000) = 0x7faa28834000
0.370 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa2896b000, len: 20480, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x17e000) = 0x7faa2896b000
0.378 ( 0.001 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
0.383 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28970510, flags: RDONLY|CLOEXEC) = 3
0.387 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa374078, count: 832) = 832
0.389 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 94320, whence: SET) = 94320
0.391 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373f60, count: 32) = 32
0.393 ( 0.001 ms): ping/19709 fstat(fd: 3<socket:[419069]>, statbuf: 0x7ffffa373f20) = 0
0.395 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 94320, whence: SET) = 94320
0.397 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373c30, count: 32) = 32
0.398 ( 0.002 ms): ping/19709 mmap(len: 102408, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa287d2000
0.402 ( 0.004 ms): ping/19709 mmap(addr: 0x7faa287d5000, len: 57344, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x3000) = 0x7faa287d5000
0.407 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa287e3000, len: 28672, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x11000) = 0x7faa287e3000
0.410 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa287ea000, len: 4096, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x17000) = 0x7faa287ea000
0.415 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa287eb000, len: 8, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7faa287eb000
0.418 ( 0.001 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
0.422 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28970a00, flags: RDONLY|CLOEXEC) = 3
0.426 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa374058, count: 832) = 832
0.428 ( 0.001 ms): ping/19709 fstat(fd: 3<socket:[419069]>, statbuf: 0x7ffffa373f00) = 0
0.430 ( 0.002 ms): ping/19709 mmap(len: 20784, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa287cc000
0.433 ( 0.004 ms): ping/19709 mmap(addr: 0x7faa287cd000, len: 8192, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1000) = 0x7faa287cd000
0.439 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa287cf000, len: 4096, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x3000) = 0x7faa287cf000
0.442 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa287d0000, len: 8192, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x3000) = 0x7faa287d0000
0.450 ( 0.001 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
PING localhost(localhost (::1)) 56 data bytes
0.454 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28970ef0, flags: RDONLY|CLOEXEC) = 3
0.458 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa374038, count: 832) = 832
0.460 ( 0.001 ms): ping/19709 fstat(fd: 3<socket:[419069]>, statbuf: 0x7ffffa373ee0) = 0
0.464 ( 0.001 ms): ping/19709 lseek(fd: 3<socket:[419069]>, offset: 808, whence: SET) = 808
0.465 ( 0.001 ms): ping/19709 read(fd: 3<socket:[419069]>, buf: 0x7ffffa373b90, count: 32) = 32
0.467 ( 0.002 ms): ping/19709 mmap(len: 132288, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7faa287ab000
0.471 ( 0.005 ms): ping/19709 mmap(addr: 0x7faa287b1000, len: 61440, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x6000) = 0x7faa287b1000
0.476 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa287c0000, len: 24576, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x15000) = 0x7faa287c0000
0.480 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa287c6000, len: 8192, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1a000) = 0x7faa287c6000
0.486 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa287c8000, len: 13504, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7faa287c8000
0.492 ( 0.001 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
0.506 ( 0.002 ms): ping/19709 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7faa287a9000
0.515 ( 0.001 ms): ping/19709 arch_prctl(option: SET_FS, arg2: 0x7faa287aa4c0) = 0
0.563 ( 0.004 ms64 bytes from localhost (::1): icmp_seq=1 ttl=64 time=0.033 ms
): ping/19709 mprotect(start: 0x7faa28b2e000, len: 16384, prot: READ) = 0
0.589 ( 0.003 ms): ping/19709 mprotect(start: 0x7faa287c6000, len: 4096, prot: READ) = 0
0.599 ( 0.002 ms): ping/19709 mprotect(start: 0x7faa287d0000, len: 4096, prot: READ) = 0
0.613 ( 0.001 ms): ping/19709 mprotect(start: 0x7faa287ea000, len: 4096, prot: READ) = 0
0.698 ( 0.004 ms): ping/19709 mprotect(start: 0x7faa2896b000, len: 16384, prot: READ) = 0
0.716 ( 0.003 ms): ping/19709 mprotect(start: 0x7faa28c7c000, len: 4096, prot: READ) = 0
0.731 ( 0.003 ms): ping/19709 mprotect(start: 0x7faa28c94000, len: 4096, prot: READ) = 0
0.868 ( 0.004 ms): ping/19709 mprotect(start: 0x7faa28f45000, len: 176128, prot: READ) = 0
0.883 ( 0.002 ms): ping/19709 mprotect(start: 0x7faa28f98000, len: 4096, prot: READ) = 0
0.891 ( 0.003 ms): ping/19709 mprotect(start: 0x7faa28f9f000, len: 4096, prot: READ) = 0
0.910 ( 0.002 ms): ping/19709 mprotect(start: 0x56341a391000, len: 4096, prot: READ) = 0
0.916 ( 0.004 ms): ping/19709 mprotect(start: 0x7faa28fea000, len: 4096, prot: READ) = 0
0.921 ( 0.011 ms): ping/19709 munmap(addr: 0x7faa28fa3000, len: 117946) = 0
0.936 ( 0.001 ms): ping/19709 set_tid_address(tidptr: 0x7faa287aa790) = 19709 (ping)
0.938 ( 0.001 ms): ping/19709 set_robust_list(head: 0x7faa287aa7a0, len: 24) = 0
0.942 ( 0.001 ms): ping/19709 rt_sigaction(sig: 0x20, act: 0x7ffffa374bd0, sigsetsize: 8) = 0
0.944 ( 0.001 ms): ping/19709 rt_sigaction(sig: 0x21, act: 0x7ffffa374bd0, sigsetsize: 8) = 0
0.945 ( 0.001 ms): ping/19709 rt_sigprocmask(how: UNBLOCK, nset: 0x7ffffa374d48, sigsetsize: 8) = 0
0.949 ( 0.001 ms): ping/19709 prlimit64(resource: STACK, old_rlim: 0x7ffffa374d30) = 0
0.987 ( 0.004 ms): ping/19709 access(filename: 0x28edbb45) = -1 ENOENT (No such file or directory)
1.019 ( 0.001 ms): ping/19709 brk() = 0x56341a4c2000
1.020 ( 0.002 ms): ping/19709 brk(brk: 0x56341a4e3000) = 0x56341a4e3000
1.023 ( 0.001 ms): ping/19709 brk() = 0x56341a4e3000
1.029 ( 0.001 ms): ping/19709 capget(header: 94781779485348) = 0
1.031 ( 0.001 ms): ping/19709 capget(header: 94781779485348, dataptr: 94781779485356) = 0
1.033 ( 0.001 ms): ping/19709 capget(header: 94781779485396) = 0
1.035 ( 0.001 ms): ping/19709 capset(header: 94781779485396, data: 94781779485404) = 0
1.038 ( 0.001 ms): ping/19709 prctl(option: SET_KEEPCAPS, arg2: 1, arg3: 12288, arg4: 140368803195403, arg5: 1) = 0
1.038 ( 0.005 ms): ping/19709 ... [continued]: getuid()) = 0
1.044 ( 0.001 ms): ping/19709 setuid() = 0
1.046 ( 0.001 ms): ping/19709 prctl(option: SET_KEEPCAPS, arg3: 140368808625661, arg5: 1) = 0
1.048 ( 0.001 ms): ping/19709 getuid(arg0: 94781779485344, arg1: 2, arg2: 94781779485392, arg3: 0, arg4: 94781779484690, arg5: 1) = 0
1.048 ( 0.004 ms): ping/19709 ... [continued]: geteuid()) = 0
1.059 ( 0.005 ms): ping/19709 openat(dfd: CWD, filename: 0x28b00240, flags: RDONLY|CLOEXEC) = 3
1.065 ( 0.001 ms): ping/19709 fstat(fd: 3<socket:[419069]>, statbuf: 0x7faa28b33a00) = 0
1.066 ( 0.003 ms): ping/19709 mmap(len: 217750512, prot: READ, flags: PRIVATE, fd: 3) = 0x7faa1b7ff000
1.073 ( 0.001 ms): ping/19709 close(fd: 3<socket:[419069]>) = 0
1.097 ( 0.001 ms): ping/19709 capget(header: 94781779489876) = 0
1.099 ( 0.001 ms): ping/19709 capget(header: 94781779489876, dataptr: 94781779489884) = 0
1.101 ( 0.001 ms): ping/19709 capset(header: 94781779489876, data: 94781779489884) = 0
1.104 ( 0.028 ms): ping/19709 socket(family: INET, type: DGRAM, protocol: ICMP) = -1 EACCES (Permission denied)
1.133 ( 0.300 ms): ping/19709 socket(family: INET, type: RAW, protocol: ICMP) = 3
1.434 ( 0.018 ms): ping/19709 socket(family: INET6, type: DGRAM, protocol: 58) = -1 EACCES (Permission denied)
1.454 ( 0.031 ms): ping/19709 socket(family: INET6, type: RAW, protocol: 58) = 4
1.487 ( 0.001 ms): ping/19709 capget(header: 94781779489924) = 0
1.489 ( 0.001 ms): ping/19709 capget(header: 94781779489924, dataptr: 94781779489932) = 0
1.491 ( 0.001 ms): ping/19709 capset(header: 94781779489924, data: 94781779489932) = 0
1.498 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28afc578) = 5
1.503 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa374170) = 0
1.505 ( 0.003 ms): ping/19709 mmap(len: 26398, prot: READ, flags: SHARED, fd: 5) = 0x7faa28fb9000
1.509 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.512 ( 0.001 ms): ping/19709 futex(uaddr: 0x7faa28b33974, op: WAKE|PRIVATE_FLAG, val: 2147483647) = 0
1.518 ( 0.032 ms): ping/19709 socket(family: LOCAL, type: STREAM|CLOEXEC|NONBLOCK) = 5
1.552 ( 0.102 ms): ping/19709 connect(fd: 5, uservaddr: 0x7ffffa374200, addrlen: 110) = -1 ENOENT (No such file or directory)
1.655 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.658 ( 0.030 ms): ping/19709 socket(family: LOCAL, type: STREAM|CLOEXEC|NONBLOCK) = 5
1.689 ( 0.003 ms): ping/19709 connect(fd: 5, uservaddr: 0x7ffffa3743c0, addrlen: 110) = -1 ENOENT (No such file or directory)
1.693 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.702 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x28afbef5, flags: RDONLY|CLOEXEC) = 5
1.708 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa374340) = 0
1.712 ( 0.002 ms): ping/19709 read(fd: 5, buf: 0x56341a4c3950, count: 4096) = 1763
1.721 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c3950, count: 4096) = 0
1.724 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.727 ( 0.002 ms): ping/19709 stat(filename: 0x28afbd40, statbuf: 0x7ffffa374430) = 0
1.731 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28afbd8f, flags: RDONLY|CLOEXEC) = 5
1.734 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa373e30) = 0
1.737 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c5220, count: 4096) = 9
1.740 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c5220, count: 4096) = 0
1.742 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.744 ( 0.001 ms): ping/19709 futex(uaddr: 0x7faa28b36804, op: WAKE|PRIVATE_FLAG, val: 2147483647) = 0
1.746 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28afbd40, flags: RDONLY|CLOEXEC) = 5
1.749 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa374040) = 0
1.751 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c5220, count: 4096) = 54
1.754 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c5220, count: 4096) = 0
1.756 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.758 ( 0.001 ms): ping/19709 uname(name: 0x7ffffa373ff0) = 0
1.764 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28fe29ef, flags: RDONLY|CLOEXEC) = 5
1.767 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa373b00) = 0
1.769 ( 0.003 ms): ping/19709 mmap(len: 117946, prot: READ, flags: PRIVATE, fd: 5) = 0x7faa1b7e2000
1.773 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.780 ( 0.003 ms): ping/19709 openat(dfd: CWD, filename: 0x1a4c3ae0, flags: RDONLY|CLOEXEC) = 5
1.784 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x7ffffa373ca8, count: 832) = 832
1.787 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa373b50) = 0
1.789 ( 0.003 ms): ping/19709 mmap(len: 83800, prot: READ, flags: PRIVATE|DENYWRITE, fd: 5) = 0x7faa28fa4000
1.793 ( 0.004 ms): ping/19709 mprotect(start: 0x7faa28fa7000, len: 40960) = 0
1.799 ( 0.006 ms): ping/19709 mmap(addr: 0x7faa28fa7000, len: 28672, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 5, off: 0x3000) = 0x7faa28fa7000
1.806 ( 0.003 ms): ping/19709 mmap(addr: 0x7faa28fae000, len: 8192, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 5, off: 0xa000) = 0x7faa28fae000
1.810 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28fb1000, len: 8192, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 5, off: 0xc000) = 0x7faa28fb1000
1.816 ( 0.002 ms): ping/19709 mmap(addr: 0x7faa28fb3000, len: 22360, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7faa28fb3000
1.822 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.842 ( 0.003 ms): ping/19709 mprotect(start: 0x7faa28fb1000, len: 4096, prot: READ) = 0
1.849 ( 0.009 ms): ping/19709 munmap(addr: 0x7faa1b7e2000, len: 117946) = 0
1.863 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28fae024, flags: RDONLY|CLOEXEC) = 5
1.868 ( 0.001 ms): ping/19709 lseek(fd: 5, whence: CUR) = 0
1.870 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa374280) = 0
1.872 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c5220, count: 4096) = 488
1.879 ( 0.001 ms): ping/19709 lseek(fd: 5, whence: CUR) = 488
1.881 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c5220, count: 4096) = 0
1.883 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.892 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x1a4c3950, flags: RDONLY|NOFOLLOW) = -1 ENOENT (No such file or directory)
1.903 ( 0.001 ms): ping/19709 openat(dfd: CWD, filename: 0x28afa4a0, flags: RDONLY|CLOEXEC) = -1 ENOENT (No such file or directory)
1.906 ( 0.001 ms): ping/19709 futex(uaddr: 0x7faa28b355c4, op: WAKE|PRIVATE_FLAG, val: 2147483647) = 0
1.908 ( 0.033 ms): ping/19709 socket(family: NETLINK, type: RAW|CLOEXEC) = 5
1.942 ( 0.002 ms): ping/19709 bind(fd: 5, umyaddr: 0x7ffffa374678, addrlen: 12) = 0
1.945 ( 0.001 ms): ping/19709 getsockname(fd: 5, usockaddr: 0x7ffffa374678, usockaddr_len: 0x7ffffa374674) = 0
1.951 ( 0.008 ms): ping/19709 sendto(fd: 5, buff: 0x7ffffa3746e0, len: 20, addr: 0x7ffffa374684, addr_len: 0xc) = 20
1.961 ( 0.007 ms): ping/19709 recvmsg(fd: 5, msg: 0x7ffffa3746a0) = 260
1.969 ( 0.002 ms): ping/19709 recvmsg(fd: 5, msg: 0x7ffffa3746a0) = 216
1.972 ( 0.001 ms): ping/19709 recvmsg(fd: 5, msg: 0x7ffffa3746a0) = 20
1.974 ( 0.001 ms): ping/19709 close(fd: 5) = 0
1.978 ( 0.032 ms): ping/19709 socket(family: INET, type: DGRAM|CLOEXEC) = 5
2.011 ( 0.006 ms): ping/19709 connect(fd: 5, uservaddr: 0x56341a4c4250, addrlen: 16) = 0
2.018 ( 0.001 ms): ping/19709 getsockname(fd: 5, usockaddr: 0x7ffffa374748, usockaddr_len: 0x7ffffa374870) = 0
2.021 ( 0.001 ms): ping/19709 close(fd: 5) = 0
2.024 ( 0.030 ms): ping/19709 socket(family: INET6, type: DGRAM|CLOEXEC) = 5
2.054 ( 0.006 ms): ping/19709 connect(fd: 5, uservaddr: 0x56341a4c42a0, addrlen: 28) = 0
2.061 ( 0.001 ms): ping/19709 getsockname(fd: 5, usockaddr: 0x7ffffa374778, usockaddr_len: 0x7ffffa374870) = 0
2.063 ( 0.001 ms): ping/19709 close(fd: 5) = 0
2.070 ( 0.029 ms): ping/19709 socket(family: INET6, type: DGRAM) = 5
2.101 ( 0.002 ms): ping/19709 connect(fd: 5, uservaddr: 0x56341a394620, addrlen: 28) = 0
2.104 ( 0.001 ms): ping/19709 getsockname(fd: 5, usockaddr: 0x56341a392150, usockaddr_len: 0x7ffffa374c8c) = 0
2.106 ( 0.001 ms): ping/19709 close(fd: 5) = 0
2.110 ( 0.002 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 1, optname: 7, optval: 0x56341a3b5c18, optlen: 4) = 0
2.112 ( 0.001 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 1, optname: 8, optval: 0x7ffffa374c30, optlen: 4) = 0
2.114 ( 0.001 ms): ping/19709 getsockopt(fd: 4<socket:[419071]>, level: 1, optname: 8, optval: 0x7ffffa374c30, optlen: 0x7ffffa374c34) = 0
2.116 ( 0.001 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 255, optname: 7, optval: 0x7ffffa374c98, optlen: 4) = 0
2.118 ( 0.001 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 58, optname: 1, optval: 0x7ffffa374ca0, optlen: 32) = 0
2.120 ( 0.001 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 41, optname: 51, optval: 0x7ffffa374c98, optlen: 4) = 0
2.128 ( 0.002 ms): ping/19709 stat(filename: 0x28afbd40, statbuf: 0x7ffffa373c00) = 0
2.133 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28fae024, flags: RDONLY|CLOEXEC) = 5
2.136 ( 0.001 ms): ping/19709 lseek(fd: 5, whence: CUR) = 0
2.138 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa373a70) = 0
2.142 ( 0.002 ms): ping/19709 read(fd: 5, buf: 0x56341a4c62a0, count: 4096) = 488
2.146 ( 0.001 ms): ping/19709 close(fd: 5) = 0
2.150 ( 0.001 ms): ping/19709 fstat(fd: 1</dev/pts/1>, statbuf: 0x7ffffa3744d0) = 0
2.154 ( 0.003 ms): ping/19709 write(fd: 1</dev/pts/1>, buf: 0x56341a4c62a0, count: 46) = 46
2.157 ( 0.003 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 1, optname: 29, optval: 0x7ffffa374b70, optlen: 4) = 0
2.225 ( 0.001 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 1, optname: 21, optval: 0x7ffffa374b60, optlen: 16) = 0
2.227 ( 0.001 ms): ping/19709 setsockopt(fd: 4<socket:[419071]>, level: 1, optname: 20, optval: 0x7ffffa374b60, optlen: 16) = 0
2.227 ( 0.005 ms): ping/19709 ... [continued]: getpid()) = 19709
2.233 ( 0.001 ms): ping/19709 rt_sigaction(sig: INT, act: 0x7ffffa374a00, sigsetsize: 8) = 0
2.235 ( 0.001 ms): ping/19709 rt_sigaction(sig: ALRM, act: 0x7ffffa374a00, sigsetsize: 8) = 0
2.237 ( 0.001 ms): ping/19709 rt_sigaction(sig: QUIT, act: 0x7ffffa374a00, sigsetsize: 8) = 0
2.239 ( 0.001 ms): ping/19709 rt_sigprocmask(how: SETMASK, nset: 0x7ffffa374b90, sigsetsize: 8) = 0
2.241 ( 0.002 ms): ping/19709 ioctl(fd: 1</dev/pts/1>, cmd: TCGETS, arg: 0x7ffffa374ab0) = 0
2.244 ( 0.001 ms): ping/19709 ioctl(fd: 1</dev/pts/1>, cmd: TIOCGWINSZ, arg: 0x7ffffa374b70) = 0
2.246 ( 0.001 ms): ping/19709 capget(header: 94781779495220) = 0
2.248 ( 0.002 ms): ping/19709 capset(header: 94781779495220, data: 94781779495228) = 0
2.251 ( 0.036 ms): ping/19709 sendto(fd: 4<socket:[419071]>, buff: 0x56341a396700, len: 64, addr: 0x56341a394640, addr_len: 0x1c) = 64
2.289 ( 0.003 ms): ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = 64
2.296 ( 0.002 ms): ping/19709 stat(filename: 0x28afbd40, statbuf: 0x7ffffa3729e0) = 0
2.299 ( 0.002 ms): ping/19709 openat(dfd: CWD, filename: 0x28fae024, flags: RDONLY|CLOEXEC) = 5
2.303 ( 0.001 ms): ping/19709 lseek(fd: 5, whence: CUR) = 0
2.305 ( 0.001 ms): ping/19709 fstat(fd: 5, statbuf: 0x7ffffa372850) = 0
2.307 ( 0.001 ms): ping/19709 read(fd: 5, buf: 0x56341a4c66b0, count: 4096) = 488
2.310 ( 0.001 ms): ping/19709 close(fd: 5) = 0
2.317 ( 1.037 ms): ping/19709 write(fd: 1</dev/pts/1>, buf: 0x56341a4c62a0, count: 63) = 63
3.360 (999.937 ms): 64 bytes from localhost (::1): icmp_seq=2 ttl=64 time=0.034 ms
ping/19709 poll(ufds: 0x7ffffa373b40, nfds: 1, timeout_msecs: 999) = 0 (Timeout)
1003.305 ( 0.038 ms): ping/19709 sendto(fd: 4<socket:[419071]>, buff: 0x56341a396700, len: 64, flags: CONFIRM, addr: 0x56341a394640, addr_len: 0x1c) = 64
1003.345 ( 0.004 ms): ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = 64
1003.356 ( 0.003 ms): ping/19709 write(fd: 1</dev/pts/1>, buf: 0x56341a4c62a0, count: 63) = 63
1003.360 (1034.015 ms): 64 bytes from localhost (::1): icmp_seq=3 ttl=64 time=0.080 ms
ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = -1 EAGAIN (Resource temporarily unavailable)
2037.397 ( 0.092 ms): ping/19709 sendto(fd: 4<socket:[419071]>, buff: 0x56341a396700, len: 64, flags: CONFIRM, addr: 0x56341a394640, addr_len: 0x1c) = 64
2037.497 ( 0.012 ms): ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = 64
2037.528 ( 0.014 ms): ping/19709 write(fd: 1</dev/pts/1>, buf: 0x56341a4c62a0, count: 63) = 63
64 bytes from localhost (::1): icmp_seq=4 ttl=64 time=0.033 ms
2037.549 (1023.788 ms): ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = -1 EAGAIN (Resource temporarily unavailable)
3061.345 ( 0.037 ms): ping/19709 sendto(fd: 4<socket:[419071]>, buff: 0x56341a396700, len: 64, flags: CONFIRM, addr: 0x56341a394640, addr_len: 0x1c) = 64
3061.384 ( 0.004 ms): ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = 64
3061.393 ( 0.007 ms): ping/19709 write(fd: 1</dev/pts/1>, buf: 0x56341a4c62a0, count: 63) = 63
64 bytes from localhost (::1): icmp_seq=5 ttl=64 time=0.035 ms
3061.402 (1023.949 ms): ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = -1 EAGAIN (Resource temporarily unavailable)
4085.361 ( 0.039 ms): ping/19709 sendto(fd: 4<socket:[419071]>, buff: 0x56341a396700, len: 64, flags: CONFIRM, addr: 0x56341a394640, addr_len: 0x1c) = 64
4085.402 ( 0.004 ms): ping/19709 recvmsg(fd: 4<socket:[419071]>, msg: 0x7ffffa373b50) = 64
4085.412 ( 0.009 ms): ping/19709 write(fd: 1</dev/pts/1>, buf: 0x56341a4c62a0, count: 63) = 63
^C
--- localhost ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 87ms
rtt min/avg/max/mdev = 0.033/0.043/0.080/0.018 ms
[root@seventh ~]#
So you want to profile/trace some workload that stars a lot of threads and want to know which one is spending more time sleeping and perhaps what they are waiting for while sleeping? There are ways to go on narrowing down in a trace with lots of events, such as adding to the recording some events, be it tracepoints or 'perf probe' kprobes/uprobes you put in suspicious places, and then use:
[root@five ~]# perf report -h switch-on
Usage: perf report [<options>]
--show-on-off-events
Show the on/off switch events, used with --switch-on and --switch-off
--switch-on <event>
Consider events after the ocurrence of this event
[root@five ~]# perf report -h switch-off
Usage: perf report [<options>]
--show-on-off-events
Show the on/off switch events, used with --switch-on and --switch-off
--switch-off <event>
Stop considering events after the ocurrence of this event
[root@five ~]#
LEmme find the commit log messages detailing examples:
git.kernel.org/acme/c/ef4b1a539f4b8776701752c5a09ee741a4232ae6
hope this may be of help.
> [root@seventh ~]# perf -vv > perf version 5.7.rc1.g06b233aa2eb5 > […] > [root@seventh ~]# perf trace ping localhost > […] Oh, okay, so it works on latest devel version, I see. Maybe I should try bisecting which commit fixes that. I wonder if #207299 works too on latest devel. (In reply to Arnaldo Carvalho de Melo from comment #7) > So you want to profile/trace some workload that starts a lot of threads and > want to know which one is spending more time sleeping and perhaps what they > are waiting for while sleeping? Yep. (In reply to Arnaldo Carvalho de Melo from comment #8) > There are ways to go on narrowing down in a trace with lots of events, such > as adding to the recording some events, be it tracepoints or 'perf probe' > kprobes/uprobes you put in suspicious places, and then use: > > [root@five ~]# perf report -h switch-on > > Usage: perf report [<options>] > > --show-on-off-events > Show the on/off switch events, used with > --switch-on and --switch-off > --switch-on <event> > Consider events after the ocurrence of this event > > [root@five ~]# perf report -h switch-off > > Usage: perf report [<options>] > > --show-on-off-events > Show the on/off switch events, used with > --switch-on and --switch-off > --switch-off <event> > Stop considering events after the ocurrence of > this event > > [root@five ~]# > > LEmme find the commit log messages detailing examples: > > git.kernel.org/acme/c/ef4b1a539f4b8776701752c5a09ee741a4232ae6 > > hope this may be of help. Hmm… Thank you. Although I'm a bit in doubts it may help, but perhaps it's better than nothing. The reason I'm in doubts is because your suggested way seems to imply I at least have a guess what events to look for. Unfortunately I don't. I don't know the code, nor I have any guesses. All I have is a large codebase and a workload being slow to crawl for no visible reason, with CPUs being idle. I also was wrong when I said "threads", sorry about that, these are actually processes, with different names like `[z_wr_int_0]`, `[z_wr_int_1]`, etc. P.S.: sorry I'll be slow to answer, trying to get sound working on my gf's laptop > P.S.: sorry I'll be slow to answer, trying to get sound working on my gf's
> laptop
I mean, it will take long: there's some hw problem appeared and I'm trying to figure out if there's a workaround
(In reply to Konstantin Kharlamov from comment #9) > > [root@seventh ~]# perf -vv > > perf version 5.7.rc1.g06b233aa2eb5 > > […] > > [root@seventh ~]# perf trace ping localhost > > […] > > Oh, okay, so it works on latest devel version, I see. Maybe I should try > bisecting which commit fixes that. I wonder if #207299 works too on latest > devel. Okay, so, I'm not sure if this crash is on-topic on this report, but since it's being discussed, to give some update: yesterday I tried perf from latest git, and it crashes on me too. I tried debugging it, but didn't get too far because for some reason gdb complains everything is "optimized out" even though I built with `-O0` CFLAGS. I tried to use `rr record` on this, but that didn't work too¹. By then I was out of time I had, so I decided to make another stab at it some time later. 1: https://github.com/mozilla/rr/issues/2518 |