Track root cause isolation and fix plan for the 500-image build regression after #456

[simonrosenberg]

Summary

Issue #502 established that full 500-image builds regressed badly after 2bfcc6c / PR #456. That change bundled two things:

• a useful benchmarks refactor for auto-detecting local Docker images
• an SDK submodule bump from b498a699 to bde715c1

The observed regression is severe:

• historical fast run: 20806796288 built 500 images in about 52 minutes and ended around 55 GiB BuildKit usage
• historical slow run: 22694639473 reached about 599 GiB BuildKit usage by batch 19 and ran for ~5h49m before cancellation
• PR fix: Reuse pre-built SDK sdist to speed up image builds #499 (22929182421) reused a prebuilt sdist but was still slow and still grew past 550 GiB, so per-image sdist creation is real but not the dominant issue

Current working hypothesis:

1. The primary regression is in the SDK build path introduced by the submodule bump, not in the benchmarks helper refactor itself.
2. The slowdown is amplified by BuildKit prune/rebuild cycles once cold-cache runs blow past the runner disk budget.
3. The Rich/fork logger issue is a real correctness bug, but it does not match the observed symptom of continuous, very slow progress.

This issue is to track a clean isolation plan and the fix strategy.

Related:

• Revert commit 2bfcc6c to speed up image builds #502
• Revert "feat: auto-detect pre-built Docker images across all benchmarks (#456)" #503

Why the previous fixes were only partial

• #486 addressed fork/spawn behavior, but not the cache-footprint regression.
• #487 addressed SDK logger initialization behavior, but not the cache-footprint regression.
• #499 addressed repeated uv build --sdist, but evidence suggests that only removes a secondary cost.
• #503 is the correct short-term operational rollback, but it does not isolate the root cause.

Plan

Phase 0: unblock builds

1. Merge #503 to restore known-good behavior while the regression is investigated.

Phase 1: add lightweight instrumentation

Add temporary env-gated timing and disk-usage logging around the hot path so we stop inferring from noisy historical runs alone:

• SDK _make_build_context() duration
• SDK docker buildx build duration
• prune duration and pre/post docker buildx du in the benchmarks batch loop

This should go into the exact historical branches / SHAs under test so the numbers are comparable.

Phase 2: run a reduced isolation matrix

Use isolated image namespaces for every run so cache-from / cache-to state does not bleed between experiments.

Run these cells:

• A. pre-2bfcc6c benchmarks + old SDK b498a699 (cold only)
• B. 2bfcc6c code path + old SDK b498a699 (cold only)
• C. pre-2bfcc6c benchmarks + new SDK bde715c1 (cold + warm)
• D. full 2bfcc6c + new SDK bde715c1 (cold + warm)

Why this trimmed matrix:

• historical evidence already shows the old SDK can warm successfully, so we should not spend two extra 500-image runs proving A/B warm again
• the key open question is whether the new SDK can warm successfully at all, or whether prune pressure keeps it effectively cold between batches

These first runs are independent and should be dispatched in parallel once isolated namespaces are in place.

Phase 3: bisect the SDK hot path with real historical checkpoints

If Phase 2 points to the SDK bump, test these exact SDK refs against the same benchmarks commit and workflow inputs:

1. b498a699 (baseline)
2. 35d75e3a (cache-tag truncation change in _base_slug())
3. 97731fe5 (Python 3.12 change)
4. 5d65f389 (--extra boto3)
5. bde715c1 (final bundled SDK ref)

Why include 35d75e3a:

• _base_slug() changed from splitting on the first _tag_ to the last _tag_
• for some long SWE-bench image names, that changes the actual buildcache-* tag values
• this can create partial cache misses independently of the Python 3.12 / boto3 changes

This phase should tell us whether the main jump comes from:

• cache tag mismatch for a subset of images
• Python 3.12 base-image / layer changes
• --extra boto3 layer growth
• or the combination

Phase 4: fix the real regression and the correctness bug

1. Reintroduce the benchmarks helper refactor separately from any SDK bump.
2. Replace early from openhands.sdk import get_logger imports in benchmarks utility modules with stdlib logging so workers do not inherit SDK/Rich logger state before ProcessPoolExecutor forks.
3. If the SDK Dockerfile / dependency profile is confirmed as the main regression, fix that in the SDK build path rather than only tuning prune settings. Likely directions:

• make benchmark-oriented source-minimal builds use a lighter dependency profile
• avoid installing extras such as boto3 unless they are required for that target
• scope Python-version workarounds to the targets that actually need them

4. Keep the useful sdist-reuse optimization from #499, but treat it as a follow-up optimization after the primary regression is fixed.

Phase 5: make cold-cache runs survivable

Cold-cache events will happen again whenever the SDK Dockerfile changes materially. Even if the SDK build profile is improved, the infrastructure should tolerate those transitions.

Treat this as co-equal with reducing SDK layer footprint, not as a minor operational footnote.

Candidate changes:

• use a larger-disk runner or higher BUILDKIT_PRUNE_KEEP_GB (for example 150-200) for the first seed run after major SDK Dockerfile changes
• reduce max-workers for intentionally cold-cache runs to limit concurrent disk pressure
• optionally run a smaller warm-up build before the full 500-image build after an SDK Dockerfile change
• add timeout-minutes and explicit prune timing logs so pathological runs fail faster and are easier to diagnose

Suggested execution order

1. Confirm #503 restores build health.
2. Dispatch the reduced Phase 2 matrix with isolated namespaces.
3. If the SDK bump is implicated, run the five-checkpoint SDK bisection.
4. Land the low-risk correctness fix for stdlib logging in benchmarks utilities.
5. Land the helper refactor without the SDK bump.
6. Land the SDK-side fix for the benchmark build profile and/or cold-cache seed strategy.

Exit criteria

We should consider this fixed when we can show, with pinned refs and isolated namespaces, that:

• a 500-image cold-cache run completes without pathological prune/rebuild behavior
• a corresponding warm-cache run stays fast and within a stable disk envelope
• the benchmarks refactor can be carried without reintroducing the regression
• SDK logger initialization is no longer happening in utility modules before process fork

Sub-issues

• SWT-Bench cold image builds regress badly under shared registry cache export #510

[simonrosenberg]

Update: Root Cause Identified and Fix Implemented

Root Cause

The primary regression is uv build --sdist running once per image (~15s × 500 = ~2 hours of pure overhead). The SDK's _make_build_context() creates an identical sdist for every image build — same SDK code, just different base images/tags. This was introduced in the SDK build path between b498a699 and bde715c1.

The secondary issue (stdlib logging to prevent Rich/fork deadlocks) was already fixed in PR #505.

Fix: Pre-build SDK sdist Once (PR #505, commit ff70858)

The fix adds three things to benchmarks/utils/build_utils.py:

1. _pre_build_sdist() — builds the SDK sdist once before the batch loop starts (~15s total instead of ~2h)
2. _build_with_cached_sdist() — extracts the pre-built sdist and runs docker buildx build directly, bypassing the SDK's per-image uv build --sdist
3. OPENHANDS_CACHED_SDIST env var — set by build_all_images() and inherited by forked worker processes

Why This Works for Any Future SDK Version

The fix operates entirely in the benchmarks repo. It does not depend on a specific SDK SHA:

• The sdist is built from whatever SDK version the submodule points to
• The docker buildx command mirrors the SDK's own build() logic (same tags, same cache strategy, same build args)
• If the pre-build fails for any reason, it falls back to the SDK's native build() function (per-image sdist)
• The SDK submodule can be bumped to any future version and builds will still benefit from the caching

The fix can also be complemented by SDK-side changes (e.g., adding native OPENHANDS_CACHED_SDIST support to _make_build_context()), but it doesn't require them.

Key Requirement

Any solution must support evaluating any future version of the SDK. We regularly bump the SDK submodule to test new versions, and the image build pipeline must handle this without multi-hour regressions. Pinning to a specific SDK SHA is not acceptable as a long-term fix — it's only useful as a temporary workaround.

Current Status

• PR fix: pre-build SDK sdist once to eliminate 500-image build regression (#504) #505 has the fix (branch fix/504-build-regression-sdk-revert-and-logging)
• CI builds triggered with the sdist caching fix — monitoring for results
• Previous runs (SDK pin only, no sdist caching) completed in ~52min (swebench) and ~38min (swtbench)
• With sdist caching, expecting further improvement since the ~10min sdist overhead is eliminated

[simonrosenberg]

Results: Sdist Caching Fix Verified

Both 500-image builds completed successfully with the sdist caching fix (commit ff70858):

Benchmark	Images	Build Step	Total Run	Failures
SWE-bench	500	28 min	41 min	0
SWT-bench	433	18 min	32 min	0

Comparison with previous runs

Run	SWE-bench build	SWT-bench build	Fix applied
Pre-regression baseline	~52 min	N/A	None needed
Post-regression (5+ hours)	5h49m+ (cancelled)	N/A	None
SDK pin only (no sdist cache)	~52 min	~38 min	SDK pin to 30819566
SDK pin + sdist cache	~28 min	~18 min	Sdist caching

Evidence from CI logs

Pre-building SDK sdist from .../vendor/software-agent-sdk ...
Pre-built SDK sdist in 3.5s: /tmp/shared-sdist-.../unknown-0.0.0.tar.gz

The sdist was built once in 3.5 seconds and reused across all 500 images, eliminating the ~2 hour overhead of running uv build --sdist per image.

Summary

The sdist caching fix reduces build times below even the pre-regression baseline. The fix works for any SDK version since it builds from whatever submodule SHA is checked out.

[simonrosenberg]

Summary from the latest investigation and full-run attempts on March 12, 2026.

What is fixed:

• The original uv build --sdist regression is fixed. We now prebuild one SDK sdist and reuse it through a real SDK API (prebuilt_sdist) instead of rebuilding an sdist per image.
• We also added a shared SDK registry cache namespace in the SDK build path so common builder layers can be reused across different SWE/SWT base images.
• Workflow worker count and batch size are now explicit workflow inputs and are passed through correctly instead of being silently overridden.

What we validated in the latest runs:

• SWE run: https://github.com/OpenHands/benchmarks/actions/runs/23017371628
• SWT run: https://github.com/OpenHands/benchmarks/actions/runs/23017371689
• Both runs are on benchmarks 3d93862f394ba608f2547062f16287a96efcd741 and SDK fc962c4c8d7fd6eb0e91db06a5ec9911b29589ac.
• The new settings are definitely active:
  • SWE is running with --max-workers 32 --build-batch-size 50
  • SWT is running with --max-workers 16 --build-batch-size 50
• The SDK fix is definitely active in the logs:
  • repeated Reusing pre-built sdist
  • repeated shared=buildcache-shared-source-minimal

Important observation about the GitHub Actions logs:

• The top-level job log looks misleadingly stale because each worker redirects build stdout/stderr into per-image log files.
• The main progress bar only advances when a future completes, so a long period with identical top-level log lines does not mean the job is idle.

Measured throughput from the latest log snapshots:

• SWE reached 50/500 at 1:34:18 after image builds started, which is about 0.53 images/min.
• SWT reached 40/433 at 1:27:20, which is about 0.46 images/min.
• SWE later begins to show some already exists. Skipping build. lines, so its later progress is partially inflated by skips; the cleanest cold-build signal is still the first 50 images in ~94 minutes.

Current conclusion:

• The bottleneck is no longer Python packaging / uv build --sdist.
• The remaining cost is in docker buildx build --push for cold images.
• The new shared cache helps only the SDK builder stage. It does not remove the per-base-image work in the Dockerfile, especially the base-image-minimal stage that still has to run uniquely for each distinct base image.
• The shared cache is also being populated too late to help the first cold wave: the first set of parallel builds all start before the shared cache has been seeded by a completed build.
• On top of that, many parallel builds are currently exporting to the same shared cache ref, which likely adds registry/export contention.

Most likely next fixes:

1. Seed the shared cache with one serial warm-up build before the big fan-out.
2. After warm-up, use the shared cache as cache-from for the rest of the builds, but do not have every parallel build also write cache-to for that same shared ref.
3. Re-tune concurrency for cold remote builds after the warm-up change. The current 32/16 settings are active, but they do not by themselves solve the throughput problem.
4. Longer term, reduce or restructure the per-base-image runtime stage in the SDK Dockerfile, because that is still a major cold-build cost.

So at this point we have fixed the original SDK packaging regression, but we have not yet achieved acceptable end-to-end cold-build throughput for 500-image runs. The next work should focus on cache warm-up / cache-write strategy and then, if needed, Dockerfile restructuring.

[simonrosenberg]

Correction to my previous report: the “latest local logs” I referred to there were from newer runs on different refs, not from the actual feature-branch runs.

This corrected report is based only on the two runs that used the intended fix path:

• SWE: https://github.com/OpenHands/benchmarks/actions/runs/23017371628
• SWT: https://github.com/OpenHands/benchmarks/actions/runs/23017371689

Those runs used:

• benchmarks: 3d93862f394ba608f2547062f16287a96efcd741 (fix/issue-504-cached-sdist)
• software-agent-sdk: fc962c4c8d7fd6eb0e91db06a5ec9911b29589ac (fix/prebuilt-sdist-api / SDK PR #2399)

What actually happened in the feature-branch runs

The fix path was definitely active

In both runs:

• the job checked out the correct branch + SDK SHA
• there were zero per-image $ uv build --sdist calls in the main logs
• the SDK repeatedly logged Reusing pre-built sdist
• the shared cache path was active (shared=buildcache-shared-source-minimal)

Counts from the run logs:

SWE run 23017371628:

• Reusing pre-built sdist: 69
• $ uv build --sdist: 0
• $ docker buildx build: 69
• completed manifest rows before cancellation: 58
• skip hits: 21
• failed builds: 0

SWT run 23017371689:

• Reusing pre-built sdist: 60
• $ uv build --sdist: 0
• $ docker buildx build: 60
• completed manifest rows before cancellation: 71
• skip hits: 27
• failed builds: 0

So the feature worked exactly as intended on packaging: the repeated SDK sdist build regression was gone.

What did not improve

Despite that, end-to-end throughput was still poor.

SWE:

• first completion: 1h04m53s
• 50/500 completed at 1h34m18s
• 58/500 completed by cancellation
• 13 of the first 50 were skips
• so only about 37 real builds completed in the first 94.3 minutes
• early real-build rate: about 0.39 real builds/min

SWT:

• first completion: 25m04s
• 50/433 completed at 2h00m52s
• 71/433 completed by cancellation
• 8 of the first 50 were skips
• so only about 42 real builds completed in the first 120.9 minutes
• early real-build rate: about 0.35 real builds/min

Important observations from the feature-branch runs

1. This was not a correctness failure.

• both runs were 0 failures up to cancellation
• the problem was throughput only

2. These runs were not fully cold.

• both already hit skip cases in batch 1
• so even these numbers are not from a pure no-cache / no-existing-tag run

3. Disk pressure was not the bottleneck.

• SWE after batch 1: 13.10% BuildKit usage, no prune needed
• SWT after batch 1: 13.37% BuildKit usage, no prune needed
• final /var/lib/buildkit usage stayed under 20%

4. The shared-cache change did not materially improve the initial cold wave.

• SWE still took 64m53s just to get the first completion
• SWT still took 25m04s just to get the first completion
• the packaging optimization did not translate into a strong end-to-end throughput win

Historical apples-to-apples comparison

SWE-Bench

Recent successful full 500/500 SWE runs fall into two groups:

Warm/no-op runs:

• 22985173176: 33m17s, 500 skips
• 22989697696: 36m46s, 501 skips
• 23000725941: 27m34s, 500 skips
• 22921613845: 29m57s, 500 skips

These are not valid cold-build baselines.

Partially-cold runs:

• 22906744352: 2h55m26s, 328 skips, about 172 real builds
• 22967520137: 4h02m23s, 369 skips, about 131 real builds

I still do not have a recent successful SWE 500/500 run with low skip count that qualifies as a clean cold full-build baseline.

So the honest SWE conclusion is:

• the feature-branch run definitely fixed the repeated-sdist regression
• but it did not demonstrate a restored end-to-end throughput improvement
• it remained slower than we want, and there is no strong recent full cold SWE success that proves current behavior is back to normal

SWT-Bench

SWT has much better true cold historical baselines.

Warm/no-op runs:

• 22985173172: 21m42s, 433 skips
• 22989698608: 25m06s, 435 skips
• 23000734281: 17m36s, 433 skips

Cold / mostly-cold full runs:

• 21870877504 (Feb 10): 66m06s, 0 skips
  • 50/433 at 18m29s
  • 100/433 at 40m52s
• 22120331118 (Feb 18): 2h03m36s, 4 skips
  • 50/433 at 47m39s
  • 100/433 at 1h09m41s
• 22328944424 (Feb 23): 2h20m06s, 23 skips
  • 50/433 at 29m11s
  • 100/433 at 53m30s

Feature-branch run 23017371689:

• 50/433 at 2h00m52s
• only 42 of those first 50 were real builds

That is still dramatically worse than historical SWT cold performance.

Updated conclusion

My corrected view is:

• We did fix one specific regression: the repeated per-image uv build --sdist behavior.
• The two feature-branch runs prove that the SDK prebuilt_sdist API from PR #2399 was actually being used.
• However, the fix did not solve the end-to-end image-build throughput problem.
• On SWT in particular, the feature-branch runs are still far slower than historical cold full-build baselines.
• So the broader performance regression is still unresolved.

The remaining bottleneck is not the Python packaging step anymore. It is still in the actual Docker/buildx/cache path.

[juanmichelini]

Notice https://github.com/OpenHands/benchmarks/actions/runs/23043936501/job/66928367859 succeeded because it relied on build
https://github.com/OpenHands/benchmarks/actions/runs/23033839708 both built the same sdk 8e8223b24dfd041875fe845b13326b0a1238b793
so the one that succeed started with a 203 head start
✅ Done:  47%|████▋     | 203/433 [00:20<00:09, 24.25it/s, ✅ 203  ❌ 0  🏃 47
...
✅ Done: 100%|██████████| 433/433 [4:10:33<00:00, 17.59s/it, ✅ 433  ❌ 0  🏃 0]