C Runtime Overhead (2015)

http://ryanhileman.info/posts/lib43

by Zababa • 5 years ago

218 39 5 years ago

ryanhileman.info

eatonphil• 5 years ago

Awesome post! And (2015) for the title maybe.

Zababa• 5 years ago

Thanks, added!

josefx• 5 years ago

I happened to run strace -tt against my solution (which provides microsecond-accurate timing information for syscalls)

Weirdly I always found the timing results of strace at under one millisecond generally unreliable, it just seemed to add too much overhead itself.

Also making system calls from your own code varies between prohibited and badly supported on most OSes. Some see calls that didn't pass through the system libc as a security issue and will intercept them, while Linux may just silently corrupt your process memory if you try something fancy as the Go team had to find out.

mgaunard• 5 years ago

That's the difference between precision and accuracy.

Having more precision doesn't magically make the data accurate.

commandlinefan• 5 years ago

making system calls from your own code varies between prohibited and badly supported

Which is probably at least part of the reason that libc itself ends up being slower than a specific, targeted solution.

mananaysiempre4• 5 years ago

Umm, what’s the story with Go on Linux? My understanding is that Linux explicitly supports making syscalls from your own code, it’s just that on platforms where the syscall story is a giant mess (32-bit x86) the prescription is to either use the slow historical interface (INT 80h) or to jump to the vDSO (which will do SYSENTER or SYSCALL or whatever—SYSENTER in particular has the lovely property of not saving the return address, so a common stub is pretty much architecturally required[1]).

If I’m guessing correctly about what you’re referring to, the Go people did something in between, got broken in a Linux kernel release, complained at the kernel people, the kernel got a patch to unbreak them. The story on MacOS or OpenBSD, where the kernel developers will cheerfully tell you to take a hike if you make a syscall yourself, seems much worse to me.

(And yes, I’d say there is a meaningful difference between a couple of instructions in the vDSO and Glibc’s endless wrappers.)

[1] https://lore.kernel.org/lkml/Pine.LNX.4.44.0212172225410.136...

ETA: Wait, no, I was thinking about the Android breakage[2]. What’s the Go story then?

[2] https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git/...

aw1621107• 5 years ago

This gets rather over my head, but my best guess is this bug having to do with the Go runtime underestimating how much stack space vDSO code may need (blog post at [0], fix at [1]).

[0] https://marcan.st/2017/12/debugging-an-evil-go-runtime-bug/

[1] https://github.com/golang/go/commit/a158382b1c9c0b95a7d41865...

scottlamb• 5 years ago

josefx> Also making system calls from your own code varies between prohibited and badly supported on most OSes. Some see calls that didn't pass through the system libc as a security issue and will intercept them, while Linux may just silently corrupt your process memory if you try something fancy as the Go team had to find out.

On Linux, making syscalls directly is fine. Good point about other platforms, but many people only care about Linux, for better or worse. And the author's last paragraph (quoted below) suggests using an alternate/static-linking-friendly libc, not making direct syscalls yourself. Presumably on platforms where those alternate libcs aren't available, you continue using the standard libc.

ryanhileman> If you're running into process startup time issues in a real world scenario and ever actually need to do this, it might be worth your time to profile and try one of the alternative libc implementations (like musl libc or diet libc).

IMHO, the Go vDSO problem [1] wasn't due to making direct syscalls but basically calling a userspace library without meeting its assumptions. I'd describe Linux's vDSO as a userspace library for making certain syscalls with less overhead. (If you don't care about the overhead, you can call them as you'd call any other syscall instead.) It assumed the standard ABI, in which there's a guard page as well as typically a generous amount of stack to begin with. Golang called into it from a thread that used Go's non-standard ABI with less stack space available (Go's own functions check the stack size on entry and copy the stack if necessary) and no guard page. On some Linux builds (with -fstack-check, apparently used by Gentoo Hardened ), it actually used enough stack to overflow. Without a guard page, that caused memory corruption.

[1] https://github.com/golang/go/issues/20427

badsectoracula2• 5 years ago

Also making system calls from your own code varies between prohibited and badly supported on most OSes.

This is not the case on Linux though, the official API of the kernel is its system calls, not any specific C library.

dwattttt• 5 years ago

While this is true, the go vs vDSO stack clash corruption highlights that a C ABI that doesn't specify stack usage is under defined. A platforms libc can be written such that it's aware of these limitations.

stabbles• 5 years ago

What's kinda neat about musl libc is that the interpreter/runtime linker and libc.so are the same executable, so that if you just dynamically link to libc, it does not need to open ld.so cache or locate and load libc.so.

averne_• 5 years ago

More importantly this uses the devkitPro/libnx homebrew toolchain, while the OP project uses the official SDK (the "complicated legal reasons" behind the absence of code probably being an NDA signature).

Narishma• 5 years ago

What?

2ton_jeff• 5 years ago

A couple of years ago I did a "Terminal Video Series" segment that also highlights the runtime overhead of 12 other languages, C of course actually one of the best ones: https://2ton.com.au/videos/tvs_part1/

tialaramex• 5 years ago

I was actually surprised for C how expensive that is, I'd expected maybe a dozen or so syscalls to set up the environment the provided runtime wants, but that's a lot of syscalls for not very much value. Both C++ and Rust are more expensive but they're setting up lots of stuff I might use in real programs, even if it's wasted for printing "hello" - but what on Earth can C need all those calls for when the C runtime environment is so impoverished anyway?

Go was surprising to me in the opposite direction, they're setting up a pretty nice hosted environment, and they're not using many instructions or system calls to do that compared to languages that would say they're much more focused on performance. I'd have expected to find it closer to Perl or something, and it's really much lighter.

aidenn02• 5 years ago

glibc isn't particularly optimized for startup-time. It also defaults to dynamic linkage which adds several syscalls, and even if it is statically linked, it may dynamically load NSS plugins. (musl gets around the latter by hardcoding support for NSCD, a service that can cache the NSS results).

C11 adds several things that benefit from early initialization (like everything around threads), but GCC had some level of support for most of them before that.

dang• 5 years ago

Discussed at the time:

C Runtime Overhead - https://news.ycombinator.com/item?id=8958867 - Jan 2015 (31 comments)

ginko• 5 years ago

I never quite understood why assembly wasn't part of programming language shootout competitions. C was always treated as the speed of light for computing, which didn't quite make sense to me.

pjscott3• 5 years ago

In my experience there's usually not much speed advantage to be had from assembly unless you have a specific thesis about how you're going to do better than the code that a good compiler would generate; e.g. the article author skipping C runtime setup overhead, or Mike Pall dissecting the ARM implementation of one of the bytecodes in LuaJIT (recommended!):

https://www.reddit.com/r/programming/comments/hkzg8/author_o...

Unless you can think of something you can do in assembly that a compiler just wouldn't be able to think of, their ability to generate good machine code is really quite impressive:

https://ridiculousfish.com/blog/posts/will-it-optimize.html

jart• 5 years ago

Normally it's better to focus on high-level time-complexity improving optimizations but there's still a whole lot of things where you really need assembly micro-optimizations, since they usually offer a 10x or 100x speedup. It's just that those things usually only concern core libraries. Stuff like crc32. But the rest of the time we're just writing code that glues all the assembly optimized subroutines together.

matu3ba2• 5 years ago

The link to gmane does not work, since the content is only available via NNTP: http://news.gmane.io/ Do you have any backup etc?

haberman• 5 years ago

My colleagues and I have developed a technique that addresses a lot of the issues Mike discusses in that link. In this blog article explaining the technique, I included an example that nearly matches Mike's hand-coded assembly from your link: https://blog.reverberate.org/2021/04/21/musttail-efficient-i...

In my experience, the weakest point of modern optimizing compilers is the register allocator. As Mike mentioned in his link, in functions with loops that contain complex control flow, the register allocation just falls apart. Too often you see the register allocator forcing a spill on the fast path that was caused by code in a fallback path. You can sprinkle __builtin_expect(cond, 0) on all your guards until the cows come home but the register allocator still sees a big complicated connected graph and optimizes the whole thing together.

The technique described in my link above works around this by basically forcing a specific register allocation at each "operation" boundary, putting fallback paths in separate functions entirely (as much as possible), so that they will be considered totally distinct to the optimizer. This isn't a perfect solution, but it helps a lot.

My overall view is that you can rarely beat the compiler in straight-line code. It's mainly in loops with complex control flow where the compiler's code quality suffers.

garbagecoder• 5 years ago

I would just add that on kookier platforms, sometimes there more low hanging fruit to be picked up with asm. I can still (barely) beat sha256 on the arm64 using the hardware sha calls that not everyone implements, stuff like that.

kaba0• 5 years ago

I recently came across a presentation of the contrary: https://news.ycombinator.com/item?id=9396950

Of course it falls into the category you mentioned (specific thesis), but I would be interested in some recent opinions on this post.

aidenn02• 5 years ago

Since about 1/3 of the programming language shootout competitions seem to boil down to "which language can call gmp the fastest" Assembly might not add much. TFA is for a benchmark where the input size is too small.

cozzyd4• 5 years 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• 5 years 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.

cozzyd4• 5 years 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

matu3ba2• 5 years ago

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?

cozzyd4• 5 years 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 )

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• 5 years 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-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...

cozzyd4• 5 years 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 :).

SavantIdiot• 5 years ago

Anyone have the link to the scoring architecture OP references? The provided link 404s.

C Runtime Overhead (2015)

Related Stories