5 ms·
Spammy syscalls in strace dumps
- c7DJTLrn 4y agoSorry, 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?
- zokier 4y agoIt's just part of narrative, the commonality is programs making excessive short writes > 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.
- c7DJTLrn 4y agoI see, thanks. 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.
- pjc50 4y ago> I don't think strace would be revealing anything because it's doing what the author of the black box binary intended That's what it's revealing - the actions of the black box binary.
- jerf 4y agoThe 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.
- moloch-hai 4y agoShoddy 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.
- csande17 4y agoTCP_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.
- pifm_guy 4y agoThe problems are identical when you pipe stdout through SSH...
- PreInternet01 4y ago> 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...
- guywhocodes 4y agoInteresting, 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. That is assuming it's reproducible.
- vidarh 4y agoMy 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.
- deleted 4y ago[deleted]
- gpderetta 4y ago> "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?" This is 87.53% of all my uses of strace!
- andikleen3 4y agoAn 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.pdf 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.
- drewg123 4y agoThat talk is brilliant, and matches my experience unfortunately..
- bear24rw 4y agoDo you know if there are videos of those talks posted anywhere?
- thewisenerd 4y agowhile I wait for a video from 2006 to miraculously survive, some googling gave me these, though: http://web.archive.org/web/20070223102951/http://www.linuxsymposium.org/2006/view_abstract.php?content_key=193 http://web.archive.org/web/20070223102951/http://www.linuxsy... https://lwn.net/Articles/192214/ https://lwn.net/Articles/192214/ https://www.linux.com/news/day-two-ols-why-userspace-sucks-and-more/ https://www.linux.com/news/day-two-ols-why-userspace-sucks-a...
- rollcat 4y agoRelated: https://flak.tedunangst.com/post/browser-ktrace-browsing https://flak.tedunangst.com/post/browser-ktrace-browsing It's completely insane, what kind of nonsense some software is doing under the hood.
- bloak 4y agoYes. Try running Kubernetes under strace. Or grep the source for arbitrary times, which mostly correspond to daft polling loops.
- jeffrallen 4y agoThe 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.)
- pjc50 4y agoYeah, 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/procmon https://learn.microsoft.com/en-us/sysinternals/downloads/pro... ).
- spullara 4y agoOn Mac you can use ktrace or dtrace.
- rwmj 4y agosendmsg + 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.
- scottlamb 4y ago> 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.
- chrsig 4y ago>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!
- mkj 4y agoI'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@posk.io/ https://lore.kernel.org/lkml/20200722234538.166697-1-posk@po...
- metadat 4y agoHas any further progress been made in open sourcing this work?
- ilyt 4y agoIt'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.
- scottlamb 4y ago> 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? Last I saw was https://lwn.net/Articles/879398/ https://lwn.net/Articles/879398/ and https://lore.kernel.org/linux-mm/E63F4045-E624-47FE-A417-5D2FF7923179@gmail.com/T/ https://lore.kernel.org/linux-mm/E63F4045-E624-47FE-A417-5D2... .
- scottlamb 4y agoOh, this looks promising: https://lore.kernel.org/all/20221212210547.1105894-1-posk@google.com/ 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.
- fovc 4y agoRan 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.
- Thaxll 4y agoIf you use Go you should use: https://pkg.go.dev/bufio 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."
- dn3500 4y agoYou 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.
- mananaysiempre 4y agoIf 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(). [1] https://man7.org/linux/man-pages/man3/stdin.3p.html https://man7.org/linux/man-pages/man3/stdin.3p.html [2] https://sourceware.org/git/?p=glibc.git;a=blob;f=libio/filedoalloc.c;hb=HEAD https://sourceware.org/git/?p=glibc.git;a=blob;f=libio/filed...
- kazinator 4y ago> 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.
- drewg123 4y agoThe syscalls section of https://wiki.freebsd.org/DTrace/One-Liners 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..