[anonymous-panda]

That doesn’t make sense unless you have only 1 or 2 physical CPUs with contention. In a modern CPU the latter should be faster and I’m left unsatisfied by the correctness of the explanation. Am I just being thick or is there a more plausible explanation?

[masklinn]

The latter is faster in actual CPU time, however note that TFA the measurement only starts with the program, it does not start with the start of the pipeline.

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.

[anonymous-panda]

My hunch is that if you added the buffered reader and kept the original xxd in the pipe you’d see similar timings.

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.

[vlovich123]

Good hunch. On my machine (13900k) & zig 0.11, the latest version of the code:

> 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.

[mtlynch]

Based on what you've shared, the second version can start reading instantly because "INFILE" was populated in the previous test. Did you clear it between tests?

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?

[vlovich123]

That was just a typo in the comment. The command run locally was just a strait pipe.

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.

[rofrol]

This @mtlynch

[vlovich123]

To sanity check myself, I reran this without the buffered reader and still don't see the slow execution time:

> 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.

[DougBTX]

It depends on where the timing code is. If the timer starts after all the data has already been loaded, the time recorded will be lower (even if the total time for the whole process is higher).

[anonymous-panda]

I’m not following how that would result in a 10x discrepancy. The amount of data we’re talking about here is laughably small (it’s like 32 bytes or something)

[DougBTX]

I’ll admit to not having looked at the details at all, but a possible explanation is that almost all the time is spent on inter process communication overhead, so if that also happens before the timer starts (eg, the data has been transferred, just waiting to be read from a local buffer) then the measured time will be significantly lower.

[masklinn]

> The amount of data we’re talking about here is laughably small

So is the runtime.