Spammy syscalls in strace dumps

An eternity ago a particular Linux kernel developer gave a series of "Why user space sucks" talks at Linux conferences. It was just going through strace logs and making fun of particularly bad examples.

Here's one instance: https://www.kernel.org/doc/ols/2006/ols2006v1-pages-441-450....

At some point I stared a lot at instruction level traces with Processor Trace or LBRs and usually I found some bad sequences in many programs, where things are implemented very inefficiently.

Related: https://flak.tedunangst.com/post/browser-ktrace-browsing

It's completely insane, what kind of nonsense some software is doing under the hood.

> If you look closely, you can see it's not quite one byte per write() but it's pretty close. Numbers go all at once for whatever reason, and those " : " strings are another curiosity.

In many languages, there's an abstraction for writing (e.g. Rust's std::io::Write). There are implementations both for raw fds (e.g. std::io::File) and wrappers for buffering (e.g. std::io::BufWriter). Someone forgot to wrap the former in the latter, so write method calls and syscalls are 1:1. It's an easy mistake to make. It's also easy to fix once you've noticed it.

I think there should be a std::io::BufWrite interface that provides the flush method but more importantly just is a marker that the supplied Write is buffered. Stuff like a JSON library should use BufWrite to prevent this mistake. Rust's read side is like this already: there's std::io::Read vs std::io::BufRead (with std::io::BufReader as the most commonly used impl of BufRead but by no means the only one.) I'm using the Rust names, but the same idea applies to other languages.

The specific behavior quoted above is probably because whatever JSON library they're using writes as follows:

* whole numbers because it uses the std library's stuff that collects the numbers in a stack-allocated buffer before passing it on to the next layer's write call

* whole separators because that's a string literal in the JSON library somewhere

* strings a byte at a time because it's looping through looking for characters it needs to escape. (It'd probably be more efficient to scan ahead until the next character that needs to be escaped and do everything until then in one write call, but when you supply a buffering Write impl as the library author probably intended, maybe not enough more efficient that they noticed and thought it was worthwhile.)

> I wonder though, do people not strace programs any more?

I'm old-school, and even I rarely use unfiltered strace anymore. Too noisy on a complex/concurrent program, and not just because of dumb stuff. I filter it down to what I'm looking for or use another tool entirely.

> If you look closely, you can see it's not quite one byte per write() but it's pretty close. Numbers go all at once for whatever reason, and those " : " strings are another curiosity.

Looks like perhaps stdio in unbuffered mode. The individual writes are characters from the format string of a printf being sent out by putc. The numbers may be digits from a conversion being sent by fwrite or puts.

Or, wait, it looks like perhaps JSON data?

  "id" : 12345, "channel" : ...

that also explains it. There is unbuffered output, and the strings are put out character-at-a-time because they are being scanned for the generation of escape codes. Syntax elements like " : " and ", " are canned literals in the JSON formatter so they go out the unbuffered stream as a unit, perhaps due to being a single fputs call. Numbers are likely formatted in a buffer and then sent out similarly.

I've always found Go programs to be more noisy straced than C or C++ ones. I wonder if it's less noisy internally at Google with their userspace threading? https://lore.kernel.org/lkml/20200722234538.166697-1-posk@po...

The syscalls section of https://wiki.freebsd.org/DTrace/One-Liners makes this super easy. I periodically "audit" our Netflix CDN stack looking for silly things and fixing them..

You have to be careful drawing conclusions about output buffering when you're using this kind of stdout redirection tool. The stdio library changes its buffering behavior depending on what stdout is connected to. For example, if stdout is a file, the stream is fully buffered, but if it's a tty, the stream is line buffered. I don't know what it does if stdout is a pipe.

The last 12 times I tried to use strace or look at a corefile, or run gdb some stupid security hardening crap prevented me from doing so. So, I gave up and just embrace the mediocrity. Why think when you can type "npm install" and hope it works the second time. (Not really.)

If you use Go you should use: https://pkg.go.dev/bufio

"Package bufio implements buffered I/O. It wraps an io.Reader or io.Writer object, creating another object (Reader or Writer) that also implements the interface but provides buffering and some help for textual I/O."

Ran into the opposite problem with Node streams, which will buffer by default, even if not doing IO on either end. That made it challenging to profile and manage throughout in a long ish pipeline, so we wound up disabling the native buffering altogether and put in a manual and explicit buffered reader and writer on either end.

Sorry, I'm tired so I'm probably just missing something. It's the binary wrapped by the author's program writing a couple of bytes at a time to stdout right? Why would TCP_NODELAY be relevant when it writes to stdout instead of a TCP socket?

sendmsg + MSG_MORE helps here.

It can't help with syscalls being so much more expensive since all the Spectre mitigations were added to the kernel.

> I wonder though, do people not strace programs any more?

No, I'm pretty sure they don't, and never really have to begin with. Any time I break out strace (or Process Monitor, mainly for Windows, although there's a pretty neat Linux version as well these days), people look at me a bit funny, and conversations starting with "so, this process that keeps crashing because it can't find a file, did you trace the OS calls to see which file that actually is?", pretty much always devolve into a crash course in using this mysterious class of tools.

It's also quite hilarious to see how subtly broken things often are at a low level, and how difficult it sometimes is to work around the resulting performance damage in your language's standard library. Insights like "hmm, maybe I should not explicitly probe for all my secret debug (file/Registry) options, but enumerate all objects in a given location and then compare them internally instead" are also quite common. Not that I mind other people making that "mistake", mind you, as it's often pretty helpful...