Re:C Runtime Overhead (2015)
by matu3ba on Monday January 03, 2022 @05:46PM
(#29788126)
strace can have a significant overhead: https://www.brendangregg.com/blog/2014-05-11/strace-wow-much...
What does the output of `perf trace` say?
[ Parent
| on HN ]
$ perf trace -S ./trivial
? ( ): trivial/84044 ... [continued]: execve()) = 0
0.038 ( 0.002 ms): trivial/84044 brk() = 0xe02000
0.048 ( 0.001 ms): trivial/84044 arch_prctl(option: 0x3001, arg2: 0x7ffe4bdf0d60) = -1 EINVAL (Invalid argument)
0.067 ( 0.007 ms): trivial/84044 access(filename: 0xee77b500, mode: R) = -1 ENOENT (No such file or directory)
0.080 ( 0.006 ms): trivial/84044 openat(dfd: CWD, filename: 0xee777ee0, flags: RDONLY|CLOEXEC) = 3
0.087 ( 0.003 ms): trivial/84044 newfstatat(dfd: 3, filename: 0xee7776f5, statbuf: 0x7ffe4bdeff90, flag: 4096) = 0
0.092 ( 0.004 ms): trivial/84044 mmap(len: 271188, prot: READ, flags: PRIVATE, fd: 3) = 0x7fc2ee70d000
0.097 ( 0.001 ms): trivial/84044 close(fd: 3) = 0
0.118 ( 0.006 ms): trivial/84044 openat(dfd: CWD, filename: 0xee783e50, flags: RDONLY|CLOEXEC) = 3
0.126 ( 0.003 ms): trivial/84044 read(fd: 3, buf: 0x7ffe4bdf00e8, count: 832) = 832
0.130 ( 0.002 ms): trivial/84044 pread64(fd: 3, buf: 0x7ffe4bdefcf0, count: 784, pos: 64) = 784
0.134 ( 0.002 ms): trivial/84044 pread64(fd: 3, buf: 0x7ffe4bdefcb0, count: 48, pos: 848) = 48
0.137 ( 0.002 ms): trivial/84044 pread64(fd: 3, buf: 0x7ffe4bdefc60, count: 68, pos: 896) = 68
0.140 ( 0.002 ms): trivial/84044 newfstatat(dfd: 3, filename: 0xee7776f5, statbuf: 0x7ffe4bdeff90, flag: 4096) = 0
0.144 ( 0.003 ms): trivial/84044 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7fc2ee70b000
0.151 ( 0.013 ms): trivial/84044 pread64(fd: 3, buf: 0x7ffe4bdefbe0, count: 784, pos: 64) = 784
0.166 ( 0.006 ms): trivial/84044 mmap(len: 1892824, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7fc2ee53c000
0.173 ( 0.010 ms): trivial/84044 mprotect(start: 0x7fc2ee562000, len: 1679360) = 0
0.185 ( 0.009 ms): trivial/84044 mmap(addr: 0x7fc2ee562000, len: 1363968, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x26000) = 0x7fc2ee562000
0.196 ( 0.005 ms): trivial/84044 mmap(addr: 0x7fc2ee6af000, len: 311296, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x173000) = 0x7fc2ee6af000
0.202 ( 0.006 ms): trivial/84044 mmap(addr: 0x7fc2ee6fc000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1bf000) = 0x7fc2ee6fc000
0.214 ( 0.004 ms): trivial/84044 mmap(addr: 0x7fc2ee702000, len: 33240, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7fc2ee702000
0.229 ( 0.001 ms): trivial/84044 close(fd: 3) = 0
0.242 ( 0.003 ms): trivial/84044 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7fc2ee53a000
0.248 ( 0.002 ms): trivial/84044 arch_prctl(option: SET_FS, arg2: 0x7fc2ee70c580) = 0
0.304 ( 0.005 ms): trivial/84044 mprotect(start: 0x7fc2ee6fc000, len: 12288, prot: READ) = 0
0.312 ( 0.004 ms): trivial/84044 mprotect(start: 0x403000, len: 4096, prot: READ) = 0
0.320 ( 0.006 ms): trivial/84044 mprotect(start: 0x7fc2ee780000, len: 8192, prot: READ) = 0
0.337 ( 0.011 ms): trivial/84044 munmap(addr: 0x7fc2ee70d000, len: 271188) = 0
0.365 ( 0.001 ms): trivial/84044 brk() = 0xe02000
0.368 ( 0.002 ms): trivial/84044 brk(brk: 0xe23000) = 0xe23000
0.377 ( 0.010 ms): trivial/84044 openat(dfd: CWD, filename: 0x402012, flags: CREAT|TRUNC|WRONLY, mode: IRUGO|IWUGO) = 3
0.398 ( 0.002 ms): trivial/84044 newfstatat(dfd: 3, filename: 0xee6c995a, statbuf: 0x7ffe4bdf0650, flag: 4096) = 0
0.401 ( 0.002 ms): trivial/84044 ioctl(fd: 3, cmd: TCGETS, arg: 0x7ffe4bdf05b0) = -1 ENOTTY (Inappropriate ioctl for device)
0.408 ( 0.002 ms): trivial/84044 write(fd: 3, buf: 0xe02480, count: 10) = 10
0.413 ( ): trivial/84044 exit_group() = ?
Summary of events:
trivial (84044), 70 events, 92.1%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
mmap 8 0 0.041 0.003 0.005 0.009 14.32%
mprotect 4 0 0.025 0.004 0.006 0.010 21.35%
openat 3 0 0.022 0.006 0.007 0.010 19.30%
pread64 4 0 0.018 0.002 0.004 0.013 62.41%
munmap 1 0 0.011 0.011 0.011 0.011 0.00%
newfstatat 3 0 0.008 0.002 0.003 0.003 17.21%
access 1 1 0.007 0.007 0.007 0.007 0.00%
brk 3 0 0.006 0.001 0.002 0.002 13.93%
arch_prctl 2 1 0.003 0.001 0.001 0.002 1.69%
close 2 0 0.003 0.001 0.001 0.001 0.00%
read 1 0 0.003 0.003 0.003 0.003 0.00%
write 1 0 0.002 0.002 0.002 0.002 0.00%
ioctl 1 1 0.002 0.002 0.002 0.002 0.00%
execve 1 0 0.000 0.000 0.000 0.000 0.00%
And great, now I know a new way to use perf! (I initially tried profiling with perf but it doesn't get enough samples to be useful!).