3 ms·

So, on my system (Fedora 34, glibc 2.33, gcc11, Ryzen 5 3600) a trivial program takes only about 1 ms according to time: $ cat trivial.c #include <st

by cozzyd 5y ago

So, on my system (Fedora 34, glibc 2.33, gcc11, Ryzen 5 3600) a trivial program takes only about 1 ms according to time: $ cat trivial.c #include <stdio.h> int main(int nargs, char ** args) { FILE * f = fopen("/dev/null","w"); for (int i = 0; i < nargs; i++) { fprintf(f,"%s\n",args[i]); } return 0; } $ make trivial # just default CFLAGS $ time ./trivial real 0m0.001s user 0m0.000s sys 0m0.001s But if I add strace -tt, it does indeed take 9 ms, even if I redirect strace output $ time strace -tt ./trivial 2> /dev/null real 0m0.009s user 0m0.005s sys 0m0.004s So, is author just measuring strace overhead?

justicezyx 5y ago
But the 1ms number is also measured with strace. Plus, the article is in 2015, and the author did not mention the CPU and other configuration. So that also make things muddy.
- cozzyd 5y ago
  Yes, but if there are almost no syscalls, then strace is doing a lot less. Profiling my trivial program with callgrind shows (unsurprisingly) that the majority of the time is in dynamic library relocation and whatever __GI__tunables_init does: https://i.imgur.com/Yligh7S.png https://i.imgur.com/Yligh7S.png
matu3ba 5y ago
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/strace-wow-much... What does the output of `perf trace` say?
- 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!).
lunixbochs 5y ago
Author here. Strace seems to add more overhead than I realized at the time, but not quite as much overhead as you suggest. For instance, you're measuring the time it takes to run strace itself, while my blog post uses the times from strace's output (i.e. excluding strace's own startup/shutdown costs). The overhead of `strace -tt` output seems much lower than `time strace -tt` on my testbed, but it's still not as good as `perf trace`. (Also note that this was written in 2015. These days spectre/meltdown CPU mitigations make the kernel <-> userspace switch more expensive, which likely has an even bigger effect on strace. PTRACE_SYSCALL requires a thread-blocking context switch chain like (proc -> kern -> strace -> kern -> proc) for every syscall.) I've reproduced my test conditions with `perf trace` below. My relative improvements seem to hold, and I stand by my suggestion that a no-libc solution would easily top the leaderboard. My level0-glibc solution placed #6 (3729/4048 = 92% of the #1 score): https://web.archive.org/web/20140210000314/https://stripe-ctf.com/leaderboard/0 https://web.archive.org/web/20140210000314/https://stripe-ct... It's been enough years and I don't have the original test machine. I cobbled together a similar testbed using a faster machine from that era and the same OS base (Ubuntu 14.04 LTS). Here are a handful of `perf trace` runs comparing: glibc dynamic/static empty binaries, my actual level0 solution as both glibc dynamic/static, and my level0 solution under lib43. I also show timings when using /dev/null as a no-op input for each level0 implementation. Timing logs: https://bochs.info/p/nvq38m https://bochs.info/p/nvq38m Spreadsheet: https://docs.google.com/spreadsheets/d/1Is8691StsKmZsAtn4dsdAGszBZ87C-mY1XNhLDHQnAI/ https://docs.google.com/spreadsheets/d/1Is8691StsKmZsAtn4dsd...
- cozzyd 5y ago
  Yes, good point, I neglected strace startup overhead, though it still seems to slow down the program by a factor of 5 compared to perf trace (2 ms vs. 0.4 ms on my machine). Indeed mitigations probably hurt here. Also fun, try time strace strace -tt ./prog to watch the walltime explode. I guess glibc's inability to be truly static must make the biggest difference. Compiling my program with -static, I get a 2-3x speedup, but even still, callgrind suggests half of the time is spent in _dl_relocate_object, since I guess even staticly-linked glibc needs to dlopen some things, which probably your minimal libc doesn't require at all :).

by cozzyd 5y ago

justicezyx 5y ago

But the 1ms number is also measured with strace. Plus, the article is in 2015, and the author did not mention the CPU and other configuration. So that also make things muddy.

cozzyd 5y ago
Yes, but if there are almost no syscalls, then strace is doing a lot less. Profiling my trivial program with callgrind shows (unsurprisingly) that the majority of the time is in dynamic library relocation and whatever __GI__tunables_init does: https://i.imgur.com/Yligh7S.png https://i.imgur.com/Yligh7S.png

matu3ba 5y ago

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/strace-wow-much... What does the output of `perf trace` say?

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!).

lunixbochs 5y ago

Author here. Strace seems to add more overhead than I realized at the time, but not quite as much overhead as you suggest. For instance, you're measuring the time it takes to run strace itself, while my blog post uses the times from strace's output (i.e. excluding strace's own startup/shutdown costs). The overhead of `strace -tt` output seems much lower than `time strace -tt` on my testbed, but it's still not as good as `perf trace`. (Also note that this was written in 2015. These days spectre/meltdown CPU mitigations make the kernel <-> userspace switch more expensive, which likely has an even bigger effect on strace. PTRACE_SYSCALL requires a thread-blocking context switch chain like (proc -> kern -> strace -> kern -> proc) for every syscall.) I've reproduced my test conditions with `perf trace` below. My relative improvements seem to hold, and I stand by my suggestion that a no-libc solution would easily top the leaderboard. My level0-glibc solution placed #6 (3729/4048 = 92% of the #1 score): https://web.archive.org/web/20140210000314/https://stripe-ctf.com/leaderboard/0 https://web.archive.org/web/20140210000314/https://stripe-ct... It's been enough years and I don't have the original test machine. I cobbled together a similar testbed using a faster machine from that era and the same OS base (Ubuntu 14.04 LTS). Here are a handful of `perf trace` runs comparing: glibc dynamic/static empty binaries, my actual level0 solution as both glibc dynamic/static, and my level0 solution under lib43. I also show timings when using /dev/null as a no-op input for each level0 implementation. Timing logs: https://bochs.info/p/nvq38m https://bochs.info/p/nvq38m Spreadsheet: https://docs.google.com/spreadsheets/d/1Is8691StsKmZsAtn4dsdAGszBZ87C-mY1XNhLDHQnAI/ https://docs.google.com/spreadsheets/d/1Is8691StsKmZsAtn4dsd...

cozzyd 5y ago
Yes, good point, I neglected strace startup overhead, though it still seems to slow down the program by a factor of 5 compared to perf trace (2 ms vs. 0.4 ms on my machine). Indeed mitigations probably hurt here. Also fun, try time strace strace -tt ./prog to watch the walltime explode. I guess glibc's inability to be truly static must make the biggest difference. Compiling my program with -static, I get a 2-3x speedup, but even still, callgrind suggests half of the time is spent in _dl_relocate_object, since I guess even staticly-linked glibc needs to dlopen some things, which probably your minimal libc doesn't require at all :).