Hydra.nixos.org: fixes from nixos build infra#1825
Merged
Conversation
stepnr is computed as MAX(stepnr) + 1 inside the insert. Transactions inserting steps for the same build at the same time pick the same number: the loser blocks on the winner's uncommitted unique-index entry, hits ON CONFLICT DO NOTHING once the winner commits and retries. The queue monitor substitutes outputs of a build concurrently (buffer_unordered(10), also across derivations of the same build), so this happened constantly. Each blocked insert held a connection from the pool. Observed while processing a 120-build nixos-small evaluation against an empty binary cache: 260 slow statement warnings, single inserts taking up to 15s and unrelated queries waiting 3s for a pool connection. Take pg_advisory_xact_lock(class, build_id) before the insert. Writers for the same build now queue up for the duration of a short transaction instead of fighting over the same stepnr.
upload_to_store opened the local build log and treated any error as fatal for the whole message, so paths without a log were never copied to the binary cache and their builds failed. Logs are legitimately absent for steps that did not run on this instance: substituted paths or builds finished before a queue runner restart. Observed on a 120-build nixos-small evaluation: 53 'Failed to upload ... uploader state I/O' errors in 10 minutes and 65 builds failing with status 2, with the corresponding build-logs directories empty. Skip the log upload with a warning when the file does not exist. Other I/O errors still fail the upload.
create_step first checks if a dep is finished and later adds the dep to the step. These are two separate atomic sections. If the dep finishes in between, its wakeup (make_rdeps_runnable) runs before the dep is added. The step then waits forever on a dep that is already finished. Today the only rescue is the global sweep at the end of process_new_builds. But the create_step call sites in succeed_step (dynamic rdeps) and in the CA-resolution path have no sweep after them. A step created there can hang until some unrelated queue run happens. Fix: split create_step into two phases. 1. prefetch_step_facts (async): all IO. Read the derivation, check which outputs exist locally and remotely, try substitutes, look up cached failures. Results go into a StepFacts struct. No graph changes here. 2. attach_step (sync): all graph changes. Mark finished, add deps, set the created flag, collect runnable steps. Deps are added with the new Step::add_dep_if_unfinished. It checks the finished flag while holding the step's lock. make_rdeps_runnable needs the same lock to remove deps. So either we see the dep as finished and skip it, or its cleanup runs after our insert and removes it. No window in between. No call site depends on the global sweep anymore. The forward-dep add in succeed_step had the same race and now also uses add_dep_if_unfinished. Steps::create stays before the IO phase on purpose: it deduplicates concurrent create_step calls for the same drv. attach_step needs no postgres, nix-daemon or S3, so the race now has unit tests that replay the exact interleaving.
create_step marked a step as finished when its outputs were valid in the *local* store. With presigned uploads, builders fetch inputs from the remote binary cache instead. So a parent step could be dispatched while its inputs were not uploaded yet. The builder then substituted or rebuilt the whole dependency chain itself. This is why many high-level jobs showed near-identical runtimes in production. It was even worse for steps that already existed in memory: that code path scheduled no upload at all and never woke the rdeps. The inputs would never appear in the remote cache. Fix: add OutputAvailability::PendingUpload. A step gets this state when its outputs are valid locally but missing remotely and presigned uploads are on. Such a step is created without deps, but it is neither finished nor runnable. Its upload is scheduled with a notify marker. A new completion loop in State reacts when the uploader reports back: it marks the step finished, wakes the rdeps and marks direct builds as cached successes. A failed upload also reports completion, so a broken cache falls back to the old behaviour instead of blocking the queue forever. Without a remote store, or when builders import inputs from the queue runner's local store (no presigned uploads), local validity is still enough. Uploads then stay fire-and-forget. This decision is explicit in prefetch_step_facts and revalidate_locally_valid_step. Also fixed on the way: the revalidation path now schedules the missing upload and wakes rdeps when a step finishes, and the CA-resolution path no longer dispatches a resolved step that still waits for its upload. The notify marker is persisted with the uploader state. After a restart, a notification for a step that no longer exists is ignored; the queue monitor revalidates that step on its next run.
HasPath and FetchRequisites went through the nix-daemon and so competed for pooled daemon connections with NAR uploads, which hold a connection for minutes each. Even with a separate upload pool the closure walk does one daemon round trip per path while holding a connection, so FetchRequisites took up to 126s and timed out under upload backlog: is_valid_path failed: timeout: acquiring connection from pool failed to compute closure e=timeout: acquiring connection from pool Both RPCs are pure reads. Query /nix/var/nix/db/db.sqlite directly (read-only, WAL-aware, long busy timeout like libnixstore) so they never wait on the daemon. Falls back to the daemon when the database cannot be opened.
Uploads streamed NARs through the nix-daemon (NarFromPath), holding a pooled daemon connection for the whole stream. With up to concurrent_upload_limit uploads of multi-hundred-MB closures in flight, uploads monopolized the connection pool, and even with a dedicated upload pool the closure walk and listing still competed with everything else for connections. harmonia-cache already serves binary caches without the daemon: metadata from the Nix SQLite database and NAR bytes serialized directly from /nix/store (NarByteStream). Do the same here: - copy_path/copy_paths take the store directory instead of a daemon connection pool; NAR and listing streams come from the filesystem - the uploader resolves upload closures and path infos from the Nix SQLite database (LocalNixDb::query_closure_infos), falling back to the daemon when the database cannot be opened GC of a path mid-upload is not a concern in practice: hydra pins build outputs via gcroots before scheduling the upload. The daemon pool is now only used for writes and substitutions, which are short-lived, so uploads can no longer starve other daemon users.
remove_machine failed in-flight steps with PreparingFailure, so every builder disconnect and every queue runner shutdown wrote status=Failed buildstep rows for steps that did not fail. After one day of deploys 278 such rows had accumulated, misrepresenting build history; a glibc step killed by a deploy restart was shown as a build failure. The machine going away says nothing about the step. Record it as Aborted, matching what clear_busy writes for busy steps on shutdown. BuildResultState::Aborted also sets can_retry, so the rescheduling behaviour is unchanged.
'Failed to realise drv ... e=state logic error' hides the actual cause; thiserror's Display does not include source errors. Render the chain so livelocked steps (309 identical errors in 30 minutes for the same three drvs) can be diagnosed.
try_resolve_force resolved input output paths only through the build history (buildsteps/buildstepoutputs with status=0). Inputs without a successful step row cannot be resolved, even though for input-addressed derivations the output path is fixed by the derivation file. Rows can legitimately be missing: paths that were already valid when the step was created get no row, and a step aborted by a queue runner restart after the build finished is recorded as Aborted. Observed as a dispatch livelock: glibc-2.42's step was aborted by a restart, dependents (glibc-simple-program, gcc-simple-program, bootstrap-stage0-stdenv) then failed realise_drv_on_valid_machine with 'failed to resolve derivation' on every dispatch, 309 times in 30 minutes, while their builds sat in the queue forever. Fall back to reading the input's .drv file and using its declared output path when the database lookup finds nothing. CA-floating outputs have no path in the drv file and still resolve only via the database.
fail_step writes a buildsteps row for every attempt. For retryable failures (preparing/import/upload/post-processing) the row was written with status Failed even though the step is going to be retried. The retry plan only lives in memory, so: - after a queue runner restart the Failed rows are all that remains, poisoning the rebuilt step graph: requeued builds attached to such a step cascade into 'dependency failed' (one bison step killed by a deploy restart dep-failed 65 of 120 builds) - when the retry budget is exhausted, dependents are marked DepFailed and the outputs can land in the failed-paths cache, although no build ever failed The C++ queue runner records these attempts as bsAborted (builder.cc catches the error with canRetry = true and stepStatus = bsAborted); only bsFailed propagates DepFailed and enters failedPaths. Match that: mark retryable completed failures as Aborted. Genuine build failures (BuildResultState::BuildFailure) still record Failed.
upload_file logged a failed multipart upload, aborted it and returned Ok(()). copy_path then uploaded the .narinfo for a NAR that was never stored, leaving a poisoned cache entry whose nar URL is a 404, and the queue runner marked the step's outputs as available in the remote store, dispatching dependents against a missing input. Only large files hit this; the single-PUT path already propagated errors. Observed in the sandbox as a mid-stream chunk read error inside run_multipart_upload that was logged as a warning while the upload counted as done. Return the error after aborting the multipart upload.
With presigned uploads, builders substitute inputs from the binary cache that all builders write to continuously. The nix-daemon caches negative narinfo lookups for narinfo-cache-negative-ttl (default 3600s), assuming a cache that was missing a path will keep missing it. That assumption is wrong here: a dependency's narinfo appears seconds after its build finishes. Observed: builder-x86-3 queried systemtap-5.4's output before building it, caching the 404. The queue runner aborted that step in a restart and retried it on builder-x86-4, which built and uploaded it. The dependent step was then dispatched back to builder-x86-3, whose daemon answered the substitution from the cached 404 and failed the build with DependencyFailed; recorded as Failed, it dep-failed 80 of 250 queued builds. Send narinfo-cache-negative-ttl=0 with the per-connection client options for the build, but only when presigned uploads are on: without them inputs are imported from the queue runner and the negative cache keeps its value against upstream substituters. Building the ClientOptions moved to the call site, where the BuildMessage fields live, instead of growing request_build past the argument lint.
The nix-daemon reports the failure kind in BuildResult (FailureStatus: TimedOut, LogLimitExceeded, ...), but hydra-builder flattened it into an error string and reported the generic BuildFailure result state, so the database recorded every build failure as Failed (1). The C++ queue runner recorded bsTimedOut (7) and bsLogLimitExceeded (10), and the web UI distinguishes them. Observed: nixos.tests.acme builds carry meta.timeout = 180, the ruby-3.4.9 dependency step exceeded it, and the database showed a plain failure with no errormsg; the timeout was only visible in the builder journal. Carry the two statuses the database distinguishes through the gRPC BuildResultState enum and map them in the queue runner. Other failure kinds keep reporting BuildFailure.
A step's max_silent_time/timeout is the maximum over its referring builds, which protects shared steps as long as one referrer carries a generous budget. But when every referrer is a build with a small meta.timeout, that budget applies to the step too. On an empty binary cache, nixos.tests.acme (meta.timeout = 180) was the only referrer of the ruby-3.4.9 step, which was killed after 180s and dep-failed all acme tests. A build's meta.timeout describes its own derivation, not the cost of realising its dependency closure. For steps that are not the top-level of any referring build, raise the limits to at least the hydra-eval-jobs defaults (3600s silent, 36000s total). Top-level steps keep the build's exact budget.
… None process_new_builds keeps 10 process_single_build futures in flight and only pushes the next build id after handling a Some result. Builds that resolve to None (already known, or handled through a sibling with the same derivation) skip that refill, so each one permanently shrinks the in-flight set; after ten the run ends with most of the backlog unread. Ingesting a full nixpkgs eval (149k queued builds) stopped after ~5k builds per queue run because of this. Refill for every completed future, before inspecting the result.
The evaluation transaction updates Builds rows of the jobset (the iscurrent flags and new members) while the queue runner concurrently updates the same rows as builds finish. When Postgres resolves the resulting lock cycle it aborts the evaluation, losing the whole eval. Observed on a full-nixpkgs jobset (~150k builds) with a busy queue: ERROR: deadlock detected, eval rolled back, no JobsetEval row created. Retry the transaction; the jobs list is already in memory so a retry only repeats the DB phase.
checkBuild reuses a previous build when the first output path matches. Output paths are computed modulo fixed-output inputs, so a change to an FOD's recipe (extra mirror, overrideModAttrs, fetcher swap with the same hash) leaves the old build with its old drvpath in the new eval and the queue runner keeps rebuilding the broken closure. Update the build's drvpath and clear finished when it differs; the runner then realises the new closure under the same build id. Unblocked ~1k builds on a no-substituter nixpkgs run after xmlsec/lato mirror additions and a git-lfs overrideModAttrs fix.
The WithRdeps sort ranks runnable steps by direct dependent count, which prefers wide-shallow steps over the deep chains that determine eval latency. A discrete-event replay of a real nixos-small eval graph (6818 x86_64 steps, historical durations from buildsteps) shows rdeps-priority finishing 3-7% behind critical-path priority on one eval, and 17-57% behind once several independent evals share the fleet (8 evals on 16 machines: 19.97h vs 14.85h, ideal 12.69h). Estimate quality barely matters: pure chain depth (no durations) already recovers 80% of the gap, so this starts with depth only. Add cp_length: the number of steps on the longest chain of unfinished reverse dependencies, recomputed by an iterative DFS over the step graph, and a WithCriticalPath sort fn that uses it in place of rdeps_len. Default remains WithRdeps. The recomputation is throttled to once a minute: with a full nixpkgs eval loaded (~150k steps, 47k runnable) perf showed the per-dispatch DFS at 12% of runner CPU, the largest single item. New steps sort last until the next recomputation, which is acceptable for a priority heuristic.
Inserting a full nixpkgs eval (~80k builds) takes ~20 minutes after nix-eval-jobs has already finished, because every build does row-at-a-time DBIx::Class creates: one for the build, one per output and one per jobsetevalmembers row, all through single-threaded Perl (observed ~80 builds/s, evaluator pegging one core while the rest of the host is idle). Keep the per-build insert (its id is needed for the build map and the build_queued notify), but collect output rows and eval members and insert them with populate() in bulk after the loop. This roughly halves the statement count per build.
With a full nixpkgs eval loaded (23k runnable steps, 8 machines at their job limit) the dispatcher used two thirds of a core: every finished build triggers a round, and every round pushes every runnable step through machine matching even though no slot is free. Skip a system's queue when no machine of that system has capacity, stop scanning once capacity runs out mid-round (feature mismatches still fall through to later steps), and pause 500ms between rounds to coalesce trigger bursts. On the same workload (full nixpkgs from source, 35k runnable steps, all machines saturated) runner CPU drops from ~70% to ~11% of a core, with dispatch at 11 rounds/30s of ~100ms each; machine matching and the critical-path DFS no longer appear in the perf profile. The remaining cost is re-submitting all runnable steps to the queues each round, which is left for a follow-up.
Each dispatch round clones every runnable step, builds a StepInfo and offers it to the queues, where all but the new ones are rejected by the duplicate check. With 35k runnable steps this re-submission is the dominant cost of an otherwise idle round. Track on the step whether it is currently held in the queues and skip queued steps when collecting work. The flag is cleared on every path that drops a step from the queues, so such steps can be re-offered later exactly as before.
BuildQueue::insert_new_jobs linearly scans the whole queue for every inserted step even though InnerQueues::insert_new_jobs, its only caller, already filters out steps present in its jobs map. With ~200k runnable steps during full-nixpkgs ingestion this scan was ~24% of runner CPU.
Each dispatch round called Steps::clone_runnable, walking the whole step map and cloning every runnable step only for the queued flag to discard almost all of them. At ~170k runnable steps this scan plus the per-step get_system/StorePath work was the bulk of the remaining dispatcher CPU. Steps now push themselves onto a pending list when they become runnable and the dispatcher drains it, making a round O(new) instead of O(all). A full scan still runs every 300s as a safety net for steps that left the queues without finishing; the queued flag keeps it idempotent.
upload_many joins up to concurrent_upload_limit upload futures inside the single uploader task, so they only interleave on one worker thread and NAR compression is limited to one core. Spawn each upload as its own task so concurrent uploads compress on separate worker threads.
Queue-run ingestion is bound by per-output narinfo HEAD requests to the binary cache, so reading a cold full-nixpkgs backlog (149k builds) takes over an hour at 10 builds in flight. The work is I/O-bound; 50 keeps S3 fan-out and DB connection use well below their limits.
Each Step retained the fully parsed Derivation (env, args, inputs) for its whole lifetime. With ~290k unfinished steps from a full nixpkgs eval this accounted for most of the runner's resident memory. Scheduling only needs the system, statically-known output paths, required system features and whether outputs are CA-floating, so store just that per step and re-read the derivation from the local store when the step is realised. With a full nixpkgs eval queued (~273k unfinished steps, ~121k builds) resident memory drops from 5.5 GB to 1.0 GB.
…action The mass updates of Builds.iscurrent (clear all, then mark the new eval's builds) lock every build of the jobset for the lifetime of the evaluation transaction - minutes on a full-nixpkgs jobset - and are the main source of deadlocks against the queue runner, which updates the same rows as builds finish. Create the eval and its members in the transaction as before (inserts only, no contention) and afterwards point the iscurrent flags at the new eval in id-ordered batches of 10k with a per-batch deadlock retry. The flags are briefly out of sync with the latest eval, which only affects UI filtering, not scheduling.
…base Ingestion checked every output of every queued build against the binary cache with ~165ms narinfo requests, so a cold pass over a full nixpkgs backlog spends hours just rediscovering outputs that Hydra itself already built and uploaded. The database records the outputs of every succeeded build step, and every such step was uploaded to the cache. Consult buildstepoutputs (indexed on path) first and only fall back to narinfo requests for paths the database does not know about.
Queue ingestion validated drv and output paths through the nix-daemon, where the pooled connections are also held for minutes by NAR uploads. Under load this starves the queue monitor, which surfaces as thousands of 'nix daemon error' failures in the monitor loop. Use the read-only SQLite database access that already exists for the gRPC handlers, so ingestion never waits on the daemon.
Not sure how these clippy errors crept in.
create_step opened a daemon connection per step for output-validity reads, and the recursion fans out, so an ingestion burst opened thousands. The daemon forks a worker per connection on a single accept thread, hammering one nix-daemon. Carry a per-pass DaemonConnPool in the ingestion context that caps live connections and reuses them, so a pass costs a fixed number of handshakes instead of one per step. The pool drops when the pass returns. A connection left desynced by a failed query is dropped rather than returned.
Profiling showed propagate_priorities at ~37% of CPU in the queue monitor loop, ~25% of all samples in StorePath hashing. The walk dedups visited steps with HashSet<Arc<Step>>, hashing each Step by its drv_path (20-byte hash plus name string) on every dependency edge. The Steps registry only yields one Arc<Step> per derivation, so pointer identity matches content identity. Key the set by Arc pointer instead, reducing each membership check to a usize hash. ByPtr holds the Arc rather than a raw pointer to pin the address for the walk; a freed step's address could otherwise be reused by a concurrently created step and cause a false "already visited" hit.
add_root() created a gcroot with a bare symlink() and was never called. A bare symlink can land after a running collector has scanned the gcroots directory, so the rooted output races that collection and can be deleted. Route rooting through the daemon's addPermRoot, which pins the path with a temp root (synchronising with a running GC over its socket), writes the symlink atomically and registers the indirect root, under the GC lock. Call it on build success, but only without presigned uploads: with them the builder pushes NARs straight to the remote cache and downstream builders fetch inputs from there, so outputs need not live locally.
Ordering by step numer is local to a build closure and jumps around a lot.
complete_build ran the finalize in a detached task and acked the builder immediately. If that task failed, the error was only logged: remove_job never ran, so the machine slot stayed allocated until the next restart. On a long-running queue runner these dead slots accumulate on idle builders. Run the finalize inline and return a non-OK status on failure. The builder retries complete_build, so a failed finalize reschedules instead of leaking the slot.
acquire() used sqlx's 30s default and surfaced a momentary pool spike as a hard error, failing callers on the critical path (build finalization). Shorten the per-attempt timeout and retry a bounded number of times so a spike is waited out; only sustained exhaustion fails. Other errors return immediately.
create_step recurses with per-level buffered concurrency, so a deep build graph fans out into many more in-flight prefetches than one level, each acquiring a DB connection. A large graph drains the pool and starves build finalization, which then times out on acquire. Cap prefetches with a semaphore sized to a quarter of the pool. The permit is released before create_step recurses, so it cannot deadlock.
The queue runner pins non-presigned build outputs with a GC root until a dependent build consumes them. This test simulates the output going missing, so nix-store --delete hits that live root and fails. Delete with --ignore-liveness, matching the test's intent of forcefully removing it.
The evaluator updates builds rows in a large transaction while the queue runner marks builds finished, so Postgres occasionally aborts one side of the lock cycle. The evaluator already retries; the queue runner did not, so a completion that lost the deadlock was rolled back and the build stayed unfinished. Add retry_serialization_failures in the db crate (retries on 40001/40P01) and wrap the queue runner's build-finishing transactions in it.
The evaluator held Builds row locks for the entire evaluation (observed ~13 minutes on nixpkgs) because it repointed builds at their new derivation inline in the large evaluation transaction. That lock window deadlocked the queue runner finishing builds of the same jobset, and a contended jobset could exhaust the retry budget and lose the evaluation. Defer the repoint: record which builds need it and apply the updates after the evaluation transaction commits, in a short id-ordered transaction with its own deadlock retry. The evaluation transaction no longer writes existing Builds rows.
succeed_step and fail_step update several build rows per transaction but iterated them in arbitrary order (Vec in weak-ref order, HashSet). Two concurrent completions with overlapping build sets could lock the same rows in opposite orders and deadlock. Sort both by build id so completion transactions lock rows in a consistent order.
get_jobset_build_steps wrapped stopTime in to_timestamp() before
comparing against the time window. The planner cannot use
indexbuildstepsonstoptime as a range bound on a transformed value, so it
scans the whole index. On nixpkgs jobsets this took over a minute and
blocked queue-runner startup.
Compare stopTime directly against an integer epoch so the index becomes
a range scan.
Before:
Parallel Index Scan ... indexbuildstepsonstoptime
Filter: to_timestamp(stoptime) > now() - '240:00:00'
Rows Removed by Filter: 57685544
Execution Time: 74536 ms
After:
Parallel Index Scan ... indexbuildstepsonstoptime
Index Cond: stoptime > EXTRACT(epoch FROM now())::bigint - 864000
Execution Time: 2204 ms
Also drop the accidental "* 10" on the scheduling window: those extra 9
days are pruned back to SCHEDULING_WINDOW anyway.
"starting dispatch", "create_step: ... already finished ... skipping", and "step ... is now runnable" fire for every dispatch loop and every step scanned, flooding the journal on large jobsets. They are routine scan progress, not notable events, so log them at debug.
Pulls in the harmonia-store-remote change that logs the daemon handshake at debug instead of info, which the queue runner triggered on every RPC.
The daemon's error_msg appends the last N build-log lines and a "For full logs" footer. Hydra already stores and links the full log, so this only bloated the errormsg shown in the web UI. Build the errormsg from the FailureStatus instead.
This makes nixos-unstable with the many big test closures progress very slowly.
The client options sent "max-log-size", which is not a Nix setting name (the setting is max-build-log-size, alias build-max-log-size). The daemon ignores unknown settings, so the log size limit was never enforced.
latestbuilds/nrbuilds warn "Use of uninitialized value" whenever the optional project/jobset/job/system parameters are omitted. Check definedness before comparing against the empty string.
Cover meta.maxSilent, meta.timeout, maxLogSize and maxOutputSize through the full evaluator -> queue-runner -> builder -> daemon path, and verify that a job's meta.maxSilent overrides the queue-runner's maxSilentTime default instead of being capped by it.
hydra-eval-jobset baked 7200/36000 into every build without meta.maxSilent/meta.timeout, so the queue-runner's maxSilentTime and buildTimeout settings never applied to top-level jobs. Store NULL instead and fall back to the queue-runner's configured defaults.
Mic92
changed the title
Ericson2314
approved these changes
Jul 14, 2026
Ericson2314
approved these changes
Jul 14, 2026
Ericson2314
left a comment
Ericson2314
left a comment
Member
There was a problem hiding this comment.
I only reviewed the pre/post rebase diff. I am trusting this overall because it has been in production, and I don't want to nit-pick battle-tested code.
I think there are improvements that can come after this that come from deeper architectural changes.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
No description provided.