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?
I guess this is due to shoddy code looping through a buffer and calling write() for each byte. So I don't think strace would be revealing anything because it's doing what the author of the black box binary intended. They might not know the performance penalty or might not care.
The problem is worse than that. The particular case on the blog may be shoddy code. But it is easy to encounter cases where the bit of the code that is emitting is most naturally written as making a ton of little write calls.
Here's an example. I have some code that streams a very large JSON array out from a DB query. It loops through the results of the DB query and constructs that individual value to send out, then goes to the next one. The resulting write calls are basically '.Write({the JSON object})', and '.Write(",\n ")'. But the JSON objects are individually small. I don't quite end up with literally one write call per character, but you can imagine it's not that hard to end up with several million '.Write("[1,2,3]"', '.Write(",\n ")', which translated to packets is still a problem.
Since I'm aware of this problem, I know to put a coalescing buffer between my writer and my network. Any serious language will have one somewhere. The challenge isn't finding it or using it, the challenge is knowing you need to.
But you shouldn't really think of the code writing that JSON object out as "shoddy code". It would be an inappropriate separation of concerns for that code to also be inlining its own coalescing buffer implementation into itself. That code should be making a ton of little .Write calls, to keep it simple and focused on its one task. It only becomes "shoddy code" if it is run in a context where the code calling it fails to provide it a coalescing buffer of some sort, be it a language feature, a socket without TCP_NODELAY, etc.
Shoddy is as shoddy does. If your language doesn't provide a convenient way to pass in a coalescing absorber of bytes, that doesn't incur a whole function call (never mind system call) per byte, for the JSONy thing to use, maybe a better language is in order.
TCP_NODELAY is not directly involved in the author's binary. But sending a ton of network packets that only have a few bytes each is pretty much the same problem as making a ton of write() calls with a few bytes each.
> 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...
Interesting, when I have a program crash or fail on me and their logs or other mechanisms are not immediately useful I tend to strace the situation. Understanding what kind of thing it failed during is usually quite simple to understand unless it's a super concurrent system. But even then you can often figure out what triggered the condition.
My two favorite uses is finding which files a program opens,and looking for pathological uses of write/read. The former to debug failures, the latter has helped speed up so much IO heavy code where people clearly failed to realise the cost of not doing userspace buffering.
A "fave" of mine is that library loading on both Windows and Linux won't tell you if a dependency of a library is missing, which dependency it is. So you load libfoo and get a "file not found" error - but for which file?
I kinda «never» use strace, even after learning about it «annoyingly late». I find myself often in a container which has zero tools / no access to run strace/perf/… or on a win10/mac laptop with no strace. Would be great if someone made a general solution to this «too locked down container» problem.
strace is useless for containers, you cant attach across container boundaries, and usually you can't install it into the container, either. Which is really sad because its such an useful tool.
Not really, you can start it from the host and trace any container process you like. On Linux the processes are in one large tree and the host has IDs for all container processes. Inside the container you may have different IDs if a pid namespace is used but from the outside these processes are in the host's process tree and have regular IDs.
You don't need to be in the container and trace from there, you can run strace outside of the container (you just have to make sure that the process ID you use is the one as seen from the host).
> No, I'm pretty sure they don't, and never really have to begin with
I use strace relatively frequently for troubleshooting. It become harder nowadays because modern software tends to do much more syscalls but with filtering it still helpful (many of syscalls I see are not necessary or overused, like calling gettimeofday in a tight loop; developers further and further away from OS and many don't even know what syscall is). Having said that I know developers who tried to minimize number of syscalls they software does (to improve performance) and used tracing as a way to ensure that the software does only what it needs to do.
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.
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.
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.)
Yeah, it's banned out of the box on OSX and I've never bothered to work out how many hoops you need to jump through to make it work. Windows has similar capabilities through ETW but usually accessed in a completely different way ( https://learn.microsoft.com/en-us/sysinternals/downloads/pro... ).
> 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.
>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.
This!
Learning all of the strace flags is a very useful endeavor. Filtering is a must to see exactly the calls that I'm looking for.
I don't think most developers appreciate how often syscalls happen. Without filtering, you're getting all:
Yeah, excellent description of why the number of syscalls is so high, and when you're tracing a multithreaded program there's the additional noise from the way it reports concurrent syscalls from the various threads.
Besides filtering, I forgot to mention that I like seeing some kind of aggregation/summary. strace flags are useful; even better to write a little program with eBPF (on Linux) or DTrace (on macOS/BSD/Solaris). I like being able to do stuff like this: https://github.com/scottlamb/retina/issues/5#issue-933945792
It's no wonder really. It's asynchronous IO + thread pool serving currently available to run goroutine, it will run few threads even if code is just a single function calling other functions.
> I wonder if it's less noisy internally at Google with their userspace threading?
No, the Go runtime's the same outside and inside Google. The experience of writing concurrent code is pretty good, the performance is pretty good, and optimizing strace output would be nice but I think isn't at the top of the design priorities. There are also other nice tools for debugging Go, e.g. the built-in CPU, memory, and (iirc) lock contention profiling that are well-integrated with the runtime.
Google's fibers library is C++-only, last I checked. It does help vs other userspace threading libraries in that the same kernel pid is used for the same task, but it's really similar to just threaded C++ otherwise. And typically programs using it still have event-driven threads, as well as fibers dedicated to particular requests, and the two styles do a lot of handoffs.
metadat asked:
> Has any further progress been made in open sourcing this work?
> We are in the process of finalizing UMCG internally, and I plan to post the patches here once all reviews/testing and some preliminary rollouts are done.
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.
"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."
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.
If it’s a pipe, then it’s the same as for a regular file. POSIX says[1] “the standard input and standard output streams are fully buffered if and only if the stream can be determined not to refer to an interactive device”; the Glibc implementation[2] looks at isatty().
> 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.
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..
48 comments
[ 4.5 ms ] story [ 118 ms ] thread> I pretty much forgot about this until the TCP_NODELAY post crossed my path, and then was reminded of this. Clearly, short writes are pretty common.
I guess this is due to shoddy code looping through a buffer and calling write() for each byte. So I don't think strace would be revealing anything because it's doing what the author of the black box binary intended. They might not know the performance penalty or might not care.
That's what it's revealing - the actions of the black box binary.
Here's an example. I have some code that streams a very large JSON array out from a DB query. It loops through the results of the DB query and constructs that individual value to send out, then goes to the next one. The resulting write calls are basically '.Write({the JSON object})', and '.Write(",\n ")'. But the JSON objects are individually small. I don't quite end up with literally one write call per character, but you can imagine it's not that hard to end up with several million '.Write("[1,2,3]"', '.Write(",\n ")', which translated to packets is still a problem.
Since I'm aware of this problem, I know to put a coalescing buffer between my writer and my network. Any serious language will have one somewhere. The challenge isn't finding it or using it, the challenge is knowing you need to.
But you shouldn't really think of the code writing that JSON object out as "shoddy code". It would be an inappropriate separation of concerns for that code to also be inlining its own coalescing buffer implementation into itself. That code should be making a ton of little .Write calls, to keep it simple and focused on its one task. It only becomes "shoddy code" if it is run in a context where the code calling it fails to provide it a coalescing buffer of some sort, be it a language feature, a socket without TCP_NODELAY, etc.
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...
That is assuming it's reproducible.
This is 87.53% of all my uses of strace!
And on docker desktop on mac/win it’s at least some hassle to get into that hidden VM (but let me know if I’m wrong)
On linux-no-vm-bs it’s fine, sure!
I use strace relatively frequently for troubleshooting. It become harder nowadays because modern software tends to do much more syscalls but with filtering it still helpful (many of syscalls I see are not necessary or overused, like calling gettimeofday in a tight loop; developers further and further away from OS and many don't even know what syscall is). Having said that I know developers who tried to minimize number of syscalls they software does (to improve performance) and used tracing as a way to ensure that the software does only what it needs to do.
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.
http://web.archive.org/web/20070223102951/http://www.linuxsy...
https://lwn.net/Articles/192214/
https://www.linux.com/news/day-two-ols-why-userspace-sucks-a...
It's completely insane, what kind of nonsense some software is doing under the hood.
It can't help with syscalls being so much more expensive since all the Spectre mitigations were added to the kernel.
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.
This!
Learning all of the strace flags is a very useful endeavor. Filtering is a must to see exactly the calls that I'm looking for.
I don't think most developers appreciate how often syscalls happen. Without filtering, you're getting all:
- file i/o (read, write, readv, writev, pread, pwrite, ...)
- network i/o (select, poll, accept, epoll, ...)
- memory allocations (mmap,munmap, sbrk, ...)
- process querying (getenv/setenv, getpid, gettid,...)
- time (gettimeofday, sleep, ...)
- synchronization (futex, ...)
I'm sure there's a bunch more that I'm neglecting. It produces quite a bit of noise!
Besides filtering, I forgot to mention that I like seeing some kind of aggregation/summary. strace flags are useful; even better to write a little program with eBPF (on Linux) or DTrace (on macOS/BSD/Solaris). I like being able to do stuff like this: https://github.com/scottlamb/retina/issues/5#issue-933945792
No, the Go runtime's the same outside and inside Google. The experience of writing concurrent code is pretty good, the performance is pretty good, and optimizing strace output would be nice but I think isn't at the top of the design priorities. There are also other nice tools for debugging Go, e.g. the built-in CPU, memory, and (iirc) lock contention profiling that are well-integrated with the runtime.
Google's fibers library is C++-only, last I checked. It does help vs other userspace threading libraries in that the same kernel pid is used for the same task, but it's really similar to just threaded C++ otherwise. And typically programs using it still have event-driven threads, as well as fibers dedicated to particular requests, and the two styles do a lot of handoffs.
metadat asked:
> Has any further progress been made in open sourcing this work?
Last I saw was https://lwn.net/Articles/879398/ and https://lore.kernel.org/linux-mm/E63F4045-E624-47FE-A417-5D2... .
https://lore.kernel.org/all/20221212210547.1105894-1-posk@go...
> We are in the process of finalizing UMCG internally, and I plan to post the patches here once all reviews/testing and some preliminary rollouts are done.
"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."
[1] https://man7.org/linux/man-pages/man3/stdin.3p.html
[2] https://sourceware.org/git/?p=glibc.git;a=blob;f=libio/filed...
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?
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.