Why does an extraneous build step make my Zig app 10x faster?
mtlynch.io
mtlynch.io
* This is not about a build step that makes the app perform better
* The app isn't 10x faster (or faster at all; it's the same binary)
* The author ran a benchmark two ways, one of which inadvertently included the time taken to generate sample input data, because it was coming from a pipe
* Generating the data before starting the program under test fixes the measurement
>"echo '60016000526001601ff3' | xxd -r -p | zig build run -Doptimize=ReleaseFast" is much faster than "echo '60016000526001601ff3' | xxd -r -p | ./zig-out/bin/count-bytes" (compiling + running the program is faster than just running an already-compiled program)
>When you execute the program directly, xxd and count-bytes start at the same time, so the pipe buffer is empty when count-bytes first tries to read from stdin, requiring it to wait until xxd fills it. But when you use zig build run, xxd gets a head start while the program is compiling, so by the time count-bytes reads from stdin, the pipe buffer has been filled.
>Imagine a simple bash pipeline like the following: "./jobA | ./jobB". My mental model was that jobA would start and run to completion and then jobB would start with jobA’s output as its input. It turns out that all commands in a bash pipeline start at the same time.
Because the compilation time overlaps with the pipes filling up, blocking on the pipe is mostly excluded from the measurement in the former case (by the time the program starts there’s enough data in the pipe that the program can slurp a bunch of it, especially reading it byte by byte), but included in the latter.
The amount of input data is just laughably small here to result in a huge timing discrepancy.
I wonder if there’s an added element where the constant syscalls are reading on a contended mutex and that contention disappears if you delay the start of the program.
> INFILE="$(mktemp)" && echo $INFILE && \ echo '60016000526001601ff3' | xxd -r -p > "${INFILE}" && \ zig build run -Doptimize=ReleaseFast < "${INFILE}" > execution time: 27.742µs
vs
> echo '60016000526001601ff3' | xxd -r -p | zig build run -Doptimize=ReleaseFast > execution time: 27.999µs
The idea that the overlap of execution here by itself plays a role is nonsensical. The overlap of execution + reading a byte at a time causing kernel mutex contention seems like a more plausible explanation although I would expect someone better knowledgeable (& more motivated) about capturing kernel perf measurements to confirm. If this is the explanation, I'm kind of surprised that there isn't a lock-free path for pipes in the kernel.
Here are the benchmarks before and after fixing the benchmarking code:
Before: https://output.circle-artifacts.com/output/job/2f6666c1-1165...
After: https://output.circle-artifacts.com/output/job/457cd247-dd7c...
What would explain the drastic performance increase if the pipelining behavior is irrelevant?
Using both invocation variants, I ran:
8a5ecac63e44999e14cdf16d5ed689d5770c101f (before buffered changes)
78188ecbc66af6e5889d14067d4a824081b4f0ad (after buffered changes)
On my machine, they're all equally fast at ~28 us. Clearly the changes only had an impact on machines with a different configuration (kernel version or kernel config or xxd version or hw).
One hypothesis outlined above is that the when you pipeline all 3 applications, the single byte reader version is doing back-to-back syscalls and that's causing contention between your code and xxd on a kernel mutex leading to things going to sleep extra long.
It's not a strong hypothesis though just because of how little data there is and the fact that it doesn't repro on my machine. To get a real explanation, I think you have to actually do some profile measurements on a machine that can repro and dig in to obtain a satisfiable explanation of what exactly is causing the problem.
> echo '60016000526001601ff3' | xxd -r -p > | zig build run -Doptimize=ReleaseFast
> execution time: 28.889µs
So I think my machine config for whatever reason isn't representative of whatever OP is using.
Linux-ck 6.8 CONFIG_NO_HZ=y CONFIG_HZ_1000=y
Intel 13900k
zig 0.11
bash 5.2.26
xxd 2024-02-10
Would be good if someone that can repro it compares the two invocation variants with buffered reader implemented & lists their config.
So is the runtime.
He then wrote a program that generated some large amount of data and wrote it to a file. Being much smarter than I am, his first program worked the first time.
But it ran terribly slow. Baffled, he showed it to his friend, who exclaimed why are you, in a loop, opening the file, appending one character, and closing the file? That's going to run incredibly slowly. Instead, open the file, write all the data, then close it!
The reply was "the manual didn't say anything about that or how to do I/O efficiently."
I think that's the right choice, by the way. Baby developers don't need to learn efficient I/O, they need to learn how you make the pile of sand do smart things.
And if you've spent weeks doing I/O one syscall per character, getting to the point you write hundreds of lines that way, the moment some classmate shows you that you can 100x your program's performance by batching I/O gets burned in your memory forever, in a way "I'm doing it because the manual said so" doesn't.
I do t think rhe sort of low level bit banging you propose is a worthwhile use of a students time, given the vast amount they have to learn that won’t be immediately obsolete.
More programming tasks than you might imagine are low-level bit banging, and C remains the language of choice for doing them. It might be Zig one day, and if so, the same sort of deep-end dive into low-level detail will remain a good way to approach such a language.
Far from becoming "rapidly obsolete", learning in this style will prevent this sort of mistake for years into the future: https://news.ycombinator.com/item?id=39766130
Everybody should, at some early point, interact with basic file descriptors and see how they map to syscalls. Preferably including building their own character and line oriented abstractions on top of that, so they can see how they work.
I'm convinced that IO is in the same category as parallelism; most devs understand it poorly at best, and the ones who do understand it are worth their weight in gold.
I do think they should all teach IO, though. If I could only pick 1 part of a language to understand really, really well it would be IO.
The vast majority of apps spend the vast majority of their productive time on IO. Your average CRUD app is almost entirely IO. The user sends IO to the app, the app send IO to the database, the database does IO to get the results and then the IO propagates back up. The only part that isn't basically pure IO is transforming and marshalling the DB records into API responses.
If you you add parallelism, that's like 98% of what most apps do. Parallel IO dominates most apps.
Thanks for reading!
>I am surprised, that people using a low-level language on Linux wouldn't know ... that reading one byte per syscall is quite inefficient.
In my defense, it wasn't that I didn't realize one byte per syscall was inefficient; it was that I didn't realize that I was doing one syscall per byte read.
I'm coming back to low-level programming after 8ish years of Go/Python/JS, so I wasn't really registering that I'd forgotten to layer in a buffered reader on top of stdin's reader.
Alex Kladov (matklad) made an interesting point on the Ziggit thread[0] that the Zig standard library could adjust the API to make this kind of mistake less likely:
>I’d say readByte is a flawed API to have on a Reader. While you technically can read a byte-at-time from something like TCP socket, it just doesn’t make sense. The reader should only allow reading into a slice.
>Byte-oriented API belongs to a buffered reader.
[0] https://ziggit.dev/t/zig-build-run-is-10x-faster-than-compil...
> execution time: 438.059µs
That’s a rather short time. (It’s a lot of cycles, but there are plenty of things one might do on a computer that take time comparable to this, especially anything involving IO. It’s only a small fraction of a disk head seek if you’re using spinning disks, and it’s only a handful of non-overlapping random accesses even on NVMe.)
So, when you benchmark anything and get a time this short, you should make sure you’re benchmarking the right thing. Watch out for fixed costs or correct for them. Run in a loop and see how time varies with iteration count. Consider using a framework that can handle this type of benchmarking.
A result like “this program took half a millisecond to run” doesn’t really tell you much about how long any part of it took.
In any case I would recommend anyone investigating things like that to run things through strace. It is often my first step in trying to understand what happens with anything - like a cryptic error "No such file or directory" without telling me what a thing tried to access. You would run:
$ strace -f sh -c 'your | pipeline | here' -o strace.log
You could then track things easily and see what is really happening.
Cheers!
I tried running your suggested command, and I got 2,800 lines of output like this:
execve("/nix/store/vqvj60h076bhqj6977caz0pfxs6543nb-bash-5.2-p15/bin/sh", ["sh", "-c", "echo \"60016000526001601ff3\" | xx"...], 0x7fffffffcf38 /* 106 vars */) = 0
brk(NULL) = 0x4ea000
arch_prctl(0x3001 /* ARCH_??? */, 0x7fffffffcdd0) = -1 EINVAL (Invalid argument)
access("/etc/ld-nix.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/aw2fw9ag10wr9pf0qk4nk5sxi0q0bn56-glibc-2.37-8/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 832) = 832
newfstatat(3, "", {st_mode=S_IFREG|0555, st_size=15688, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ffff7fc2000
mmap(NULL, 16400, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ffff7fbd000
mmap(0x7ffff7fbe000, 4096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x7ffff7fbe000
Am I doing it wrong? Or is there more training involved before one could usefully integrate this into debugging? Because to me, the output is pretty inscrutable.I think something like this could work:
strace -f -e execve,clone,write,read -o strace.log sh -c '...'
Clone is fork, so a creation of a new process, before eventual execve (with echo there will probably be just clone).As for how to filter this I'll leave that to the other comments, but I personally would look at the man page or Google around for tips
Here's a possibly more detailed reason as to why https://news.ycombinator.com/item?id=39764287#39768022.
Articles like this are how one learns the nuances of such things, and it's good for people to keep putting them out there.
Not too long ago I hit this same realization with pipes because my "grep ... file | sed > file" (or something of that nature) was racey.
I took the time to think about it and realized "oh I guess that's how pipes would _have_ to be implemented".
Exploratory programming and being curious about strange effects is a great way to learn the fundamentals. I already knew how pipes and processes work, but I don't know the Ethereum VM. The author now knows both.
Its not uncommon. As a professional developer I have observed this obfuscation of prior technology countless times, especially with junior devs.
There is a lot to learn. Always. It doesn't ever stop.
[1] https://exploringjs.com/nodejs-shell-scripting/ch_web-stream...
stage1.exe /in:input.dat /out:stage1.dat
stage2.exe /in:stage1.dat /out:stage2.dat
del stage1.dat
stage3.exe /in:stage2.dat /out:result.dat
del stage2.datGuys just write small programs and chain them. The wisdom of the ancients is continuously lost.
I commonly write little python scripts to filter logs, which I have read from stdin. That means I can filter a log to stdout:
cat logfile.log | python parse_logs.py
Or filter them as they're generated: tail -f logfile.log | python parse_logs.py
Or write the filtered output to a file: cat logfile.log | python parse_logs.py > filtered.log
Or both: tail -f logfile.log | python parse_logs.py | tee filtered.log
It would be possible, I suppose, to configure a single python script to do all those things, with flags or whatever.But who on Earth has the time for that?
This is one of the reasons why, for all its faults, shell just isn't going anywhere any time soon.
You can also (assuming your language supports it), execute gzip, and assuming your language gives you some writable-handle to the pipe, then write data into it. So, you get the concurrency "for free", but you don't have to go all the way to "do all of it in process".
I've also done the "trick" of executing [bash, -c, <stuff>] in a higher language, too. I'd personally rather see the work better suited for the high language done in the higher language, but if shell is easier, then as such it is.
It's sort of like unsafe blocks: minimize the shell to a reasonable portion, clearly define the inputs/outputs, and make sure you're not vulnerable to shell-isms, as best as you can, at the boundary.
But I still think I see the reverse far more often. Like, `steam` is … all the time, apparently … exec'ing a shell to then exec … xdg-user-dir? (And the error seems to indicate that that's it…) Which seems more like the sort of "you could just exec this yourself?". (But Steam is also mostly a web-app of sorts, so, for all I know there's JS under there, and I think node is one of those "makes exec(2) hard/impossible" langs.)
Did I do that right?
or was it
`tar cvzf t.tar.gz *`
import subprocess
subprocess.run(['tar', 'cvzf', 't.tar.gz', *list_of_files])
or indeed import os, subprocess
subprocess.run(['tar', 'cvzf', 't.tar.gz', *(f.path for f in os.scandir('.'))])
if you need files from the current directoryTee can be useful for that. Maybe pv (pipe viewer) too. I have not tried it yet.
SPONGE(1) moreutils SPONGE(1)
NAME
sponge - soak up standard input and write to a file
SYNOPSIS
sed '...' file | grep '...' | sponge [-a] file
DESCRIPTION
sponge reads standard input and writes it out to the specified file.
Unlike a shell redirect, sponge soaks up all its input before writing
the output file. This allows constructing pipelines that read from and
write to the same file.Of course, there many reasons you wouldn’t want this—processes can take time to start up, for example—but it’s not an unreasonable mental model.
(Since, as GP said, not an infinite buffer.)
Though now I will break your mind as my mind was broken not a long time ago. Powershell, which is often said to be a better shell, works like that. It doesn't run things in parallel. I think the same is to be said about Windows cmd/batch, but don't cite me on that. That one thing makes Powershell insufficient to ever be a full replacement of a proper shell.
cmd.exe uses standard OS pipes and behaves the same as UNIX shells, same as Powershell invoking native binaries.
A Pipeline is PowerShell is definitely streaming unless you accidentally forces the output into a list/array at some point, e.g. try this for yourself (somewhere you can interrupt the script obviously as it's going to run forever)
class InfiniteEnumerator : System.Collections.IEnumerator
{
hidden [ulong]$countMod2e64 = 0
[object] get_Current()
{
return $this.countMod2e64
}
[bool] MoveNext() {
$this.countMod2e64 += 1
return $true
}
Reset() {
$this.countMod2e64 = 0
}
}
class InfiniteEnumerable : System.Collections.IEnumerable {
InfiniteEnumerable() {}
[System.Collections.IEnumerator] GetEnumerator() {
return [InfiniteEnumerator]::new()
}
}
[InfiniteEnumerable]::new() | ForEach-Object { Write-Host "Element number mod 2^64: $_" }
Whether it runs in parallel depends on the implementation of each side. Interpreted powershell code does not run in parallel unless you run it a job, use ForEach-Object -Parallel, or explicitly put it on another thread. But the data is not collected together before being sent from one step from the next. 0..1000000 | where {$_ % 10 -eq 0} | foreach {"Got Value: $_"} > 0..1000000000 | % { $_ }
# Starts printing out numbers immediately
> 0..1000000000
# Hangs longer than I had patience to wait for
> $x=0..100
> $x.GetType()
# IsPublic IsSerial Name BaseType
# -------- -------- ---- --------
# True True Object[] System.Array
It's an array when I save it in a variable, but it's obviously not an array on the LHS of a pipe.The next year the experimental NPL (New Programming Language) has been rebranded as PL/I and it has become a commercial product of IBM.
Following PL/I, other programming languages have begun to use "&" and "|" for AND and OR, including the B language, the predecessor of C.
The pipe and its notation have been introduced in the Third Edition of UNIX (based on a proposal made by M. D. McIlroy), in 1972, so after the language B had been used for a few years and before the development of C. The oldest documentation about pipes that I have seen is in "UNIX Programmer's Manual Third Edition" from February 1973.
Before NPL, the vertical bar had already been used in the Backus-Naur notation introduced in the report about ALGOL 60 as a separator between alternatives in the description of the grammar of the language, so with a meaning somewhat similar to OR.
Untrue: ".OR." in FORTRAN meant ordinary OR, not bitwise OR. I don't remember ever seeing bitwise OR or AND or XOR in FORTRAN IV.
FORTRAN IV did not have bit strings, it had only Boolean values ("LOGICAL").
Therefore all the logical operators could be applied only to Boolean operands, giving a Boolean result.
The same was true for all earlier high-level programming languages.
The language NPL, renamed PL/I in 1965, has been the first high-level programming language that has introduced bit string values, so the AND, OR and NOT operators could operate on bit strings, not only on single Boolean values.
If PL/I would have remained restricted to the smaller character set accepted by FORTRAN IV in source texts, they would have retained the FORTRAN IV operators ".NOT.", ".AND.", ".OR.", extending their meaning as bit string operators.
However IBM has decided to extend the character set, which has allowed the use of dedicated symbols for the logical operators and also for other operators that previously had to use keywords, like the relational operators, and also for new operators introduced by PL/I, like the concatenation operator.
Although 0x7D is overly specific, since if a sibling comment is correct (I have no reason to think otherwise), | for bitwise OR originates in PL/1, where it would have been encoded in EBCDIC, which codes it as 0x4F.
I'm not really disagreeing with you, the |abs| notation is quite a bit older than computers, just musing on what should count as the first use of "|". I'm inclined to say that it should go to the first use of an encoding of "|", not to the similarly-appearing pen and paper notation, and definitely not the first use of ASCII "|" aka 0x7D in a programming language. But I don't think there's a right answer here, it's a matter of taste.
Because one could argue back to the Roman numeral I, if one were determined to do so: when written sans serif, it's just a vertical line, after all. Somehow, abs notation and "first use of an encoded vertical bar" both seem reasonable, while the Roman numeral and specifically-ASCII don't, but I doubt I can unpack that intuition in any detail.
If you don't do that, if you use the `time` CLI for example, this wouldn't have been a problem in the first place. Though sure you couldn't have compared to compiling fresh & running anyway, and at least on small inputs would've wanted to do the input prep first anyway.
But I think if you put the benchmark code inside the DUT you're setting yourself up for all kinds of gotchas like this.
The author's example code, "jobA starts, sleeps for three seconds, prints to stdout, sleeps for two more seconds, then exits" and "jobB starts, waits for input on stdin, then prints everything it can read from stdin until stdin closes" is measuring 5 seconds not because the input to jobB is not ready until jobA terminates but because jobB is waiting for the pipe to close which doesn't happen until jobA ends. That explains the timing of the output:
$ ./jobA | ./jobB
09:11:53.326 jobA is starting
09:11:53.326 jobB is starting
09:11:53.328 jobB is waiting on input
09:11:56.330 jobB read 'result of jobA is...' from input
09:11:58.331 jobA is terminating
09:11:58.331 jobB read '42' from input
09:11:58.333 jobB is done reading input
09:11:58.335 jobB is terminating
The bottom line is that it's important to actually measure what you want to measure.Thanks for reading!
>All the commands in a bash pipeline do start at the same time, but output goes into the pipeline buffer whenever the writing process writes it. There is no specific point where the "output from jobA is ready".
Right, I didn't mean to give the impression that there's a time at which all input from jobA is ready at once. But there is a time when jobB can start reading stdin, and there's a time when jobA closes the handle to its stdout.
The reason I split jobA's output into two commands is to show that jobB starts reading 3 seconds after the command begins, and jobB finishes reading 2 seconds after reading the first output from jobA.
Then I would try to benchmark what happens if it all fits in L1 cache, L2, L3, and main memory.
Of course, if the common use case is reading from a file, network, or pipe, maybe you can optimize that, but I would take it step by step.
This assumes CI runs on the same machine with same hardware every time, but most CI doesn’t do that.
And it seemed correlated to time of day. So pretty sure they had some contention there.
Edit: and that was with all the same cpu’s reported to the os atleast
Nothing to do with Zig. Just a nice debugging story.