Hacker News Reader

Comment by cozzyd | Hacker News Reader

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?

View on HN

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-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

Spreadsheet: https://docs.google.com/spreadsheets/d/1Is8691StsKmZsAtn4dsd...

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

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?

    $ 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 )

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

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.

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

Reply on news.ycombinator.com