sccache isn't compatible with Cargo pipelining on cache miss

[weihanglo]

What happens

Cargo can start a dependent crate when rustc notify that its dependency .rmeta is ready. This is the pipelining compilation feature added like several years ago to cargo. You can see the overlap between units in cargo timing HTML: https://doc.rust-lang.org/nightly/cargo/reference/timings.html. That is the pipelining and could cut off non-neglectable build time if codegen time is long.

However, on a cache miss, sccache seems to buffer that rustc notification until rustc exits. That basically kills the pipelining compilation because Cargo won't receive earler rmeta finish notification until the codegen phase is done.

This mainly hurts cold builds and incremental builds with large cache misses. A mostly warm build is totally fine just FYI.

Reproduction

Here is also an LLM generated repro script. It requires -Zbuild-analysis nightly Cargo feature and jq.

bash repro/cargo-pipelining.sh /path/to/sccache

Expand to see the script

#!/usr/bin/env bash
set -euo pipefail

# This 
# 1. creates a two-crate workspace
# 2. builds it directly and through a cold sccache miss.
# 3. Cargo's `-Zbuild-analysis` log records when Cargo receives the dependency's `.rmeta` notification, starts the consumer, and considers the dependency wrapper finished.

if [[ $# -ne 1 ]]; then
	echo "usage: $0 /path/to/sccache" >&2
	exit 2
fi
command -v jq >/dev/null

sccache=$(cd -- "$(dirname -- "$1")" && pwd -P)/$(basename -- "$1")
root=$(mktemp -d "${TMPDIR:-/tmp}/sccache-pipelining.XXXXXX")
port=$((42000 + $$ % 10000))
unset RUSTC_WRAPPER RUSTC_WORKSPACE_WRAPPER
export SCCACHE_DIR="$root/cache" SCCACHE_SERVER_PORT="$port" SCCACHE_IDLE_TIMEOUT=0

stop_server() {
	"$sccache" --stop-server >/dev/null 2>&1 || true
}
trap stop_server EXIT

cargo new --lib --edition 2024 "$root/dep" --quiet
cargo new --lib --edition 2024 "$root/consumer" --quiet
cat >"$root/Cargo.toml" <<'EOF'
[workspace]
members = ["dep", "consumer"]
resolver = "3"
EOF
echo 'dep = { path = "../dep" }' >>"$root/consumer/Cargo.toml"

# Leave enough code generation after metadata emission to make the overlap visible.
for i in {0..999}; do
	printf '#[inline(never)] pub fn f%s(x: u64) -> u64 { x + %s }\n' "$i" "$i"
done >"$root/dep/src/lib.rs"
echo 'pub fn answer() -> u64 { dep::f0(42) }' >"$root/consumer/src/lib.rs"

build() {
	local name=$1
	local home="$root/home-$name"
	local target="$root/target-$name"
	mkdir -p "$home"

	if [[ $name == sccache ]]; then
		export RUSTC_WRAPPER="$sccache"
	else
		unset RUSTC_WRAPPER
	fi

	CARGO_HOME="$home" CARGO_BUILD_ANALYSIS_ENABLED=true \
		CARGO_TARGET_DIR="$target" CARGO_INCREMENTAL=0 \
		cargo +nightly build -Zbuild-analysis -p consumer --quiet \
		--manifest-path "$root/Cargo.toml"

	printf '%s\n' "$home"/log/*.jsonl
}

measure() {
	jq -rs '
        (map(select(.reason == "unit-registered" and ((.package_id // "") | contains("/dep#"))))[0].index) as $dep |
        (map(select(.reason == "unit-registered" and ((.package_id // "") | contains("/consumer#"))))[0].index) as $consumer |
        (map(select(.reason == "unit-rmeta-finished" and .index == $dep))[0].elapsed) as $rmeta |
        (map(select(.reason == "unit-finished" and .index == $dep))[0].elapsed) as $finish |
        (map(select(.reason == "unit-started" and .index == $consumer))[0].elapsed) as $consumer_start |
        [1000 * ($finish - $rmeta), 1000 * ($finish - $consumer_start)] | @tsv
    ' "$1"
}

direct_log=$(build direct)
sccache_log=$(build sccache)
direct_values=$(measure "$direct_log")
sccache_values=$(measure "$sccache_log")
read -r direct_rmeta direct_consumer <<<"$direct_values"
read -r sccache_rmeta sccache_consumer <<<"$sccache_values"

printf '%-10s %12s %18s\n' mode rmeta-before-end consumer-before-end
printf '%-10s %9.1f ms %15.1f ms\n' direct "$direct_rmeta" "$direct_consumer"
printf '%-10s %9.1f ms %15.1f ms\n' sccache "$sccache_rmeta" "$sccache_consumer"

Output with current main at 8396f020 on my machine:

mode       rmeta-before-end consumer-before-end
direct          67.9 ms            67.5 ms
sccache          1.6 ms             1.2 ms

Direct rustc shows the remaining code generation time (67ms) for Cargo to overlap the dependent rustc rmeta emission.
However, with sccache, the 1–2 ms gap is probably sccache bookkeeping after rustc has exited. There is no real gap for pipeline compilation 😞.

You can also use cargo report timing to look at the timing HTML from -Zbuild-analysis log.

Code analysis

Some LLM code analysis (I haven't verified myself but will soon):

• Current main still waits for CompileFinished before returning output.
• The compiler path collects the complete process output, and the protocol has no str eaming-output response.

I would probably come up with a fix with LLM assist (if that is acceptable).

[weihanglo]

A proposed solution in #2875. I am not entirely satisfied with it but it works anyway.