3 ms·

strace can have a significant overhead: https://www.brendangregg.com/blog/2014-05-11/strace-wow-much-syscall.html https://www.brendangregg.com/blog/2014-05-11/s

• cozzyd 5y ago
  $ 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% So, looks like total syscall overhead is on the order of 0.1 ms? Granted, it's a significant part of the runtime, but I think all the relocations and such are driving the libc overhead (as shown in callgrind output: https://i.imgur.com/Yligh7S.png https://i.imgur.com/Yligh7S.png ) 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!).