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 > "${INFILE}" | zig build run -Doptimize=ReleaseFast < "${INFILE}"EVM gas used: 18 > 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.
> 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.
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.
So is the runtime.
>"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.