Docker Builds: I Shipped an Optimization and Nothing Happened

I merged the two-phase uv sync optimization on Monday. Built a dedicated A/B test workflow that showed 86% faster rebuilds. Wrote a blog post about the design. Felt great. PR #21006, merged to main, deployed to production.

Then I opened the Datadog CI dashboard and saw… nothing. Same build durations. No drop. No inflection point. The line was flat.

The instinct that fires in that moment is a very specific flavor of dread: I shipped a no-op.

The dashboard doesn’t lie (but it doesn’t tell the whole truth either)

Before panicking, I forced myself to do the thing that distinguishes engineering from anxiety: write down hypotheses, rank them, eliminate them.

I came up with eight. Here are the three that mattered.

Hypothesis 1: Too early

The PR merged today. How many builds have run since then?

I checked. A handful — all on commits that didn’t touch uv.lock.

Remember the three scenarios:

Scenario A: Nothing changed. Both lockfiles cached. Optimization: irrelevant.
Scenario B: Minor dep bump. uv.lock changed, uv-stable.lock didn’t. Optimization: this is where it helps.
Scenario C: Major overhaul. Both lockfiles changed. Optimization: slightly worse.

Every post-merge build was Scenario A. No dependency changes happened since the merge. The optimization hadn’t been exercised. It’s like installing a fire sprinkler system and then checking whether it works by… not having a fire.

No Scenario B events = no speedup = correct behavior.

Hypothesis 2: Wrong metric granularity

Even if a Scenario B build had run, would the dashboard show it?

Datadog was tracking job-level duration. But the optimization lives inside one step of one job: the docker buildx bake command. A single CI job includes:

Runner provisioning and checkout
Tailscale VPN setup
ACR login and cache restore
docker buildx bake ← optimization lives here
Multi-registry push
Cache export
Cleanup

And the overall workflow includes multiple jobs — rocket builds (not optimized), enroot conversion, multiarch manifest merge. The uv sync speedup is buried three levels deep in a Russian nesting doll of CI steps.

Staring at job-level duration to find a step-level optimization is like checking your electricity bill to see if you replaced a lightbulb.

Hypothesis 3: Registry cache overhead

This one was more interesting. I found one post-merge build where uv.lock actually changed — commit 59c54cf (“Add gateway process & runtime metrics”). A real Scenario B event in the wild. Downloaded the raw BuildKit logs from GitHub Actions. Parsed them. And found something I didn’t expect.

The optimization was working perfectly. Phase 2 uv sync completed in 0.3 seconds. The stable lockfile stayed cached, the delta was installed in under a second. Exactly as designed.

But total wall time was higher post-merge than pre-merge. 13 minutes vs 10 minutes.

What? How?

Registry cache import overhead. BuildKit pulls compressed layers from ACR to verify they’re cached — even on cache hits. With a 66GB image, that’s significant I/O. The optimization saved time on the uv sync step but couldn’t offset the cost of Docker checking “do I already have this enormous layer?”

The optimization works. It’s just one variable in a system with many variables. And right now, the other variables are louder.

Reading BuildKit logs like tea leaves

GitHub Actions logs for docker buildx bake are a wall of interleaved text from BuildKit’s parallel execution engine. Multiple build targets running simultaneously, each with their own step numbering, all dumped into one stream. It looks like this:

#19 [pretraining internal] load build context
#19 transferring context: 19.33MB 0.2s done
#20 [pretraining stage-0 5/14] COPY pyproject-stable.toml ...
#20 CACHED
#21 [pretraining stage-0 6/14] COPY uv-stable.lock ...
#21 CACHED
#22 [pretraining stage-0 7/14] RUN --mount=type=cache ...
#22 CACHED
#23 [pretraining stage-0 8/14] COPY pyproject.toml ...
#23 CACHED* 9m 16.4s
#24 [pretraining stage-0 9/14] COPY uv.lock ...
#24 DONE 3.4s
#25 [pretraining stage-0 10/14] RUN --mount=type=cache ...
#25 DONE 0.3s

I stared at this format long enough that I started seeing patterns. Then I built a tool to see them for me.

The tool: parse-buildx-log.py

A single-file Python script that turns BuildKit log noise into a readable table. Stdlib only — no dependencies, because a diagnostic tool that requires pip install has already failed.

Single-file mode parses a downloaded log file:

Step   Target        Phase  Status    Duration  Role
5/14   pretraining   P1     CACHED    -         COPY pyproject-stable.toml
6/14   pretraining   P1     CACHED    -         ★ COPY uv-stable.lock
7/14   pretraining   P1     CACHED    -         ★ uv sync (Phase 1)
8/14   pretraining   P2     CACHED*   9m 16s    COPY pyproject.toml
9/14   pretraining   P2     BUILT     3.4s      ★ COPY uv.lock
10/14  pretraining   P2     BUILT     0.3s      ★ uv sync (Phase 2)
11/14  pretraining   post   BUILT     2m 38s    ★ CUDA compile

Compare mode shows three builds side-by-side — pre-merge baseline, Scenario B, Scenario A — with status and duration diffs.

Fetch mode pulls logs directly from the GitHub Actions API: python3 parse-buildx-log.py --fetch JOB_ID. Because the hardest part of build investigation is always getting the logs in the first place.

Some design decisions worth noting:

Phase detection: The script identifies Phase 1 vs Phase 2 by finding the uv-stable.lock COPY step. Everything before it is Phase 1; the uv.lock COPY and subsequent uv sync is Phase 2.
CACHED* notation: BuildKit logs sometimes show CACHED with a duration. That means “cached this time, but here’s how long it took when it last ran.” The script renders this as CACHED* to distinguish “cached with known historical cost” from plain “cached, no cost info.” This is useful for understanding the counterfactual — what would have happened on a cache miss.
Command truncation: RUN commands in Dockerfiles can be 200 characters of --mount flags and paths. The script truncates to the identifying prefix while preserving enough to know which step you’re looking at.

The actual evidence

Three builds, parsed and compared. Here are the actual runs — you can click through and check the logs yourself:

Build 1 — Pre-merge baseline (1-phase, 04:36 UTC):

uv sync: CACHED at 6m 34s historical duration
CUDA compile: 2m 43s
Total: 10m 34s

Build 2 — Post-merge, Scenario B (2-phase, 08:15 UTC, includes 59c54cf which changed uv.lock):

Phase 1 uv sync: CACHED ✅ (stable lock unchanged)
Phase 2 uv sync: BUILT 0.3 seconds ✅
CUDA compile: 2m 38s
Total: 13m 18s

Build 3 — Post-merge, Scenario A (2-phase, 12:15 UTC, nothing changed):

Everything cached
Total: 13m 12s

The 0.3-second Phase 2 is the proof. When uv.lock changes post-optimization, instead of a 6+ minute full reinstall, it installs only the delta in under a second. The mechanism works exactly as designed.

The total wall time being higher is a separate problem — registry cache I/O overhead on a 66GB image — and has nothing to do with the optimization’s effectiveness.

Three interpretations of “nothing happened”

This experience crystallized something I want to write on a sticky note and put on my monitor:

“No visible change” has at least three interpretations:

It’s broken. The feared one. The code doesn’t work.
It works but hasn’t been exercised. The code works perfectly — it just hasn’t encountered the conditions where it matters. This was our case.
You’re measuring the wrong thing. The code works AND has been exercised, but your metrics are at the wrong granularity to see it. Also partially our case — job-level duration vs step-level duration.

The instinct is to jump to interpretation #1. It’s the one that triggers the most adrenaline. But it’s not the most likely. Especially when you have A/B test data showing 86% improvement. At some point you have to trust your controlled experiment over your dashboard squinting.

What I told the team

I drafted a Slack message to the DevEx squad explaining:

“No improvement on dashboard” is expected — no Scenario B events yet
One real data point exists (commit 59c54cf) showing 0.3s Phase 2
Which Datadog jobs to filter by (Build Yolo Base Image and the Falcon ACR variants)
Updated Datadog filter URL with the right job names

The key framing: “the optimization is deployed but not yet activated.” It’s waiting for its first real-world dependency bump to show value at scale. The A/B test data is solid. The one organic Scenario B confirms the mechanism. We just need more data points — and they’ll come naturally, because someone bumps something in a monorepo almost every day.

What I still don’t know

Why is total wall time higher post-merge even on Scenario A? Registry cache import overhead is my best guess, but I need more data points to separate signal from noise.
Will the weekly cron job work correctly? The update-uv-stable-lock.yml workflow is scheduled for Monday midnight UTC. It hasn’t fired yet. There’s a difference between “the YAML looks right” and “the automation works.”
At what point does stable lock drift matter? Currently, uv-stable.lock and uv.lock differ by 134 lines. At what delta does Phase 2 start taking real time instead of sub-second? That determines how aggressively we need to refresh.
Rocket is still 1-phase. A follow-up PR is needed, but the data shows only ~7% improvement due to bind mount architecture. Low priority.

The meta-lesson

The two-phase optimization took a day to write and a week to prove. Now I’ve spent another day proving that the absence of proof on a dashboard isn’t evidence of absence.

Building the diagnostic tooling — parse-buildx-log.py — before panicking turned a “did it work?” question into a “here’s exactly what happened at each layer” answer. The log parser is now a reusable tool for any future build investigation. Next time someone asks “why was this build slow?”, the answer is a command, not an archaeology expedition.

If I’ve learned anything from this Docker optimization saga, it’s this: ship the fix, ship the proof, and ship the tool that lets you re-prove it six months from now. The fix is six lines of Dockerfile. The proof is a test workflow. The tool is a log parser. Together, they form a complete argument — not just “it works” but “here’s how to check.”

The dashboard will catch up. Dep bumps happen every day in a monorepo. The first weekly uv-stable.lock refresh hasn’t even fired yet. By next week, there’ll be enough Scenario B events to draw a trendline.

And if the trendline is flat, I’ll have the tools to figure out why.