Report size and speed of remote cache transfers

[kozak]

Why

Remote cache transfers were logged as a single duration, which cannot answer the question a slow restore actually raises: what were we waiting for?

What

measureTransfer sits in the conduit pipeline and records how long it was blocked waiting for upstream to hand over a chunk versus blocked waiting for downstream to accept one. Conduit runs those strictly alternately — await returns when upstream has a chunk, yield when downstream wants the next — so together they account for the pipeline's whole wall clock. Cost is two getMonotonicTime calls per chunk.

Tapping either side of zstd on the save path splits it three ways:

Packed and uploaded 286.11 MiB in 2.02s (141.66 MiB/s), compressed from 286.11 MiB - blocked on reading files 0.09s, on compression 0.18s, on upload 1.72s
Downloaded and unpacked 378.87 MiB in 2.25s (168.73 MiB/s) - blocked on download 0.24s, on decompression and unpacking 1.97s

The taps nest rather than partition — when zstd wants input it pulls through the upstream tap, so the upload tap's wait already contains the wait for tar. Compression is the difference between the two, which makes the three figures sum to the elapsed time and gives a self-check on the numbers.

Restore only gets a two-way split: there zstd runs inside tar, so decompression can't be separated from the file writes. It becomes three-way in #21, which decompresses in-process.

Reading these numbers

They are stall times, not time spent doing the work. A socket write returns once the data is copied into the kernel send buffer, and the kernel transmits it while the next chunk is compressed — so transfer overlaps the rest of the pipeline and is undercounted here; if the pipeline is CPU-bound the writes cost almost nothing. Reads are the mirror image: bytes accumulate in the receive buffer while we are busy, so an await that finds them already there is free.

So they answer "where did the pipeline stall", which is what identifies the bottleneck. They are not a breakdown of where the bytes' time went.

Verification

Three workloads over the same link, blame landing somewhere different each time and summing to the elapsed time:

workload	reading files	compression	upload	elapsed
8,000 tiny files, 7.82 MiB	0.11s	0.01s	0.00s	0.13s
one 381 MiB compressible file	0.12s	0.06s	0.00s	0.19s
one 286 MiB incompressible file	0.09s	0.18s	1.72s	2.02s

The middle row shows the undercounting directly: 381 MiB was read and compressed, but only 36 KiB reached the wire.

countBytes is gone — the new upstream tap already counts uncompressed bytes.

What it found

On CI, across seven tasks: 13.6s of stalling on download against 420.7s on unpacking. That motivated #21, and the measurements there in turn showed the win depends entirely on the archive's entry-size profile — which this logging is what made visible.

🤖 Generated with Claude Code

[kozak]

Added the diagnostic split (aea608c), so CI logs can answer which part is slow rather than just how long it took.

measureTransfer sits in the pipeline and records how long it waits for upstream to produce data versus for downstream to consume it. Conduit runs those strictly alternately — await returns when upstream has a chunk, yield returns when downstream wants the next — so it's an exact attribution of the pipeline's wall clock, not a sample. Cost is two getMonotonicTime calls per chunk.

Downloaded and unpacked 378.87 MiB in 2.25s (168.73 MiB/s) - downloading 0.24s, unpacking 1.97s
Packed and uploaded 378.87 MiB in 6.51s (58.17 MiB/s), compressed from 1.26 GiB - packing and compressing 4.22s, uploading 2.27s

Verified it discriminates rather than always blaming one side, using two workloads of comparable size over the same link:

workload	downloading	unpacking
20,160 files, 1.26 GiB (.stack-work-shaped)	0.24s	1.97s
one 190 MiB file	0.16s	0.20s

It measures waiting, and downstream applies backpressure, so a slow consumer can't inflate the producing side — time only lands there when no data was available yet. The download side also excludes connection setup, which happens earlier in AWS.send.

Context for why this matters: for a .stack-work-shaped cache, extraction is ~94% of restore time (measured separately: zstd decompress 0.40s, tar parse 0.07s, extraction ~2.0s). It's per-file syscall and filesystem cost, roughly 100 µs per file, independent of link speed. This logging is the prerequisite for deciding whether to do anything about that — parallel extraction measured 2.6× faster on 4 vCPUs and 4.4× on 8, but that's only worth building if prod caches look like the synthetic one.

[zyla]

The single duration could not answer the question it most often raises:
when restoring a cache is slow, is it the network or the unpacking?

Why not split it further? There are 3 possible things to blame:

1. File I/O
2. Compression/decompression
3. Network upload/download

If you tap the pipeline with measureTransfer before and after zstd, you can get full attribution.

(See my other comment about the interpretation of the attribution)

btw, seems like PR description is stale, doesn't talk about aea608c )

[zyla]

More idiomatic: https://hackage-content.haskell.org/package/conduit-1.3.6.1/docs/Data-Conduit-Combinators.html#v:iterM

countBytes ref = C.iterM \chunk -> modifyIORef' ref (+ BS.length chunk) 

[zyla]

This might be true for CPU work. But not for I/O! Kernel has TCP send and receive buffers internally, and data is being transferred in parallel with the zstd compression. So the actual transfer time will be undercounted. In fact, if the pipeline is CPU-bound, the write()s will take approximately zero time (just copying into a kernel buffer, which will then be sent while the next chunk is compressed).

(the above is from an upload perspective; flip for a download)

[zyla]

The paragraph below sounds like it wants to address this, but I doesn't quite explain it IMO, or even talks about a different issue.

Now, the time spent in network write() (or read() for downloads) is still useful for answering your question - "is the network the bottleneck" - I just wouldn't report it as "time spent uploading".

[kozak]

Thanks — all three were right. Fixed in 81d1b02.

Third component. Tapping either side of zstd now separates the three. One thing worth recording: the taps nest rather than partition. When zstd wants input it pulls through the upstream tap, so the time the upload tap spent waiting for zstd already contains the time spent waiting for tar. My first attempt reported both raw and produced figures summing to 0.23s against 0.13s elapsed. Compression is the difference between the two, and the three now add up to the elapsed time — which is a useful self-check on the numbers.

Interpretation. You're right, and "time spent uploading" was the wrong label. The docs now say these are stall times, that a socket write returns once the data is in the kernel send buffer and transmission overlaps compressing the next chunk (so transfer is undercounted, and is ~free when the pipeline is CPU-bound), that reads are the mirror image, and that the numbers identify the bottleneck rather than breaking down where the bytes' time went.

Note this doesn't change the conclusion the logging was built to test — for a .stack-work-shaped cache the network wasn't what we were stalling on — but that is precisely a statement about stalls, not about transfer.

countBytes. Removed rather than converted to iterM: the new upstream tap already counts the uncompressed bytes, so it was redundant. Agreed iterM would have been the right form had it stayed.

Verified against three workloads over the same link, blame landing somewhere different each time:

workload	reading files	compression	upload	elapsed
8,000 tiny files, 7.82 MiB	0.11s	0.01s	0.00s	0.13s
one 381 MiB compressible file	0.12s	0.06s	0.00s	0.19s
one 286 MiB incompressible file	0.09s	0.18s	1.72s	2.02s

The middle row is your undercounting point made concrete: 381 MiB was read and compressed, but only 36 KiB reached the wire, so "upload" is 0.00s.

One limitation. Restore only gets a two-way split, because there zstd runs inside tar (tar -x --zstd) so decompression can't be separated from the file writes. It becomes three-way in the follow-up (#21), which decompresses in-process in order to split the stream across several tar processes.

PR description updated — it predated aea608c.