Issue 306: a check on the control node ran past its timeout

Store-bound packages ran five to seven times slower there while the rest
ran alike: the throwaway store flushes to a disk the mesh's own data keeps
busy. And a holder recreated mid-check left its store and bus running.

04-ISSUES/306-a-check-on-the-control-node-ran-past-its-timeout/00-report.md

@@ -0,0 +1,73 @@
+---
+status: located
+opened: 2026-10-08
+located-in: [mesh-controller internal/builder (check.go, the throwaway store; kill.go), mesh-controller cmd/mesh-builder (the holder's start)]
+fixed-by: novox/mesh-controller PR #133
+amended-design:
+---
+
+# 306. A check on the control node ran past its timeout
+
+## Symptom
+
+On 2026-10-07 and 2026-10-08, the controller's pull request checks took 19 to 21 minutes in flight
+whenever the control node held them. The same suite took 7 to 8 minutes on the home server, the
+laptop and the workstation. Three checks of the controller failed with the suite's own thirty-minute
+timeout, `FAIL cmd/mesh-controller 1800.0…s`, and every one of them ran on the control node. One
+check was recorded as `build.<id>.lost` while a plan recreated the control node's build agent.
+
+Every controller check that landed on the control node in those two days ran past thirty minutes.
+None that landed elsewhere did.
+
+The control node also runs the controller, the bus, the store and the forge. So the first guess was
+plain overload. The numbers below say it is narrower than that.
+
+## Measured
+
+The verdict's report keeps each package's time. Here are three controller checks of the same pull
+request, run on three holders, read from the delivery's comments on the pull request:
+
+| package | home server | workstation | control node |
+|---|---|---|---|
+| `internal/catalogue` (no store) | 3.7 s | 4.2 s | 4.4 s |
+| `internal/builder` (no store) | 1.3 s | 1.5 s | 2.1 s |
+| `internal/lease` (no store) | 17.7 s | 17.7 s | 17.7 s |
+| `internal/store` | 10 s | 26 s | 77–95 s |
+| `internal/identity` | 44–54 s | 51 s | 234–256 s |
+| `internal/licences` | 40–51 s | 51 s | 240–252 s |
+| `internal/link` | 74–82 s | 89 s | 366–371 s |
+| `internal/inventory` | 250–285 s | 230 s | 1744 s, then past 1800 s |
+| `cmd/mesh-controller` | 401–432 s | 369 s | past 1800 s, both runs |
+
+The packages that never touch a store run at the same speed everywhere, so the control node's
+processor is not the bottleneck. The packages that do touch one run five to seven times slower
+there. The goroutine dump at the timeout shows the running test waiting on the store's connection.
+The test running when the timer fired had been running only 6 s or 35 s, so this is a slow suite,
+not one hung test.
+
+Each throwaway store the build seat raises on the control node wrote 16 to 20 GB to disk over its
+check, according to the runtime's per-container block I/O. On the control node that disk is shared
+with the mesh's own store (174 GB written since it started), the database server, the object store,
+the bus and the forge.
+
+## Two more things found on the way
+
+**Throwaway containers outlive a holder that is recreated mid-check.** One check of 2026-10-08 was
+delivered four times. It went to the home server, the workstation, the control node and finally the
+laptop, because a plan rolling out the build agent recreated each holder in turn while it held the check. The laptop
+passed it in 5 m 41 s. The first three deliveries each left their throwaway store and bus running.
+A redelivery removes what an earlier delivery left (issue 285), but only on the machine it reaches,
+and this one never came back to the same machine. Across the mesh, eleven such pairs were still
+running: five on the control node, three on the workstation, two on the laptop and one on the home
+server. The oldest dated from 2026-10-06.
+
+**The check's 19–21 minutes in flight is the sum of several attempts, not one run.** Rolling out
+the build agent ends the check it is running, and the queue hands the check to the next free
+holder. When that holder is the control node, the next roll-out of the agent usually arrives before the suite
+can finish there.
+
+## What was not measured
+
+The mesh has no tool that reports a machine's load, I/O wait or disk latency. The runtime's
+per-container statistics and the suite's own package times are the evidence above. "Disk flushes
+on the control node are slow" is concluded from them, not read off a gauge.

04-ISSUES/306-a-check-on-the-control-node-ran-past-its-timeout/01-diagnosis.md

@@ -0,0 +1,62 @@
+# 306 — diagnosis
+
+**2026-10-08.** Read-only, through the mesh's tools. In order:
+
+1. **The queue and the controller's journal.** For each controller check of the two days, the
+   journal names the holder that ran it. Every one that ran on the control node failed at the
+   suite's timeout (three). The fourth was ended after 27 minutes in the suite, when a plan recreated the build agent. Every
+   one that ran elsewhere finished.
+2. **The build logs.** The steps before the suite take the same time on every holder: cloning, the
+   facts, raising the store and the bus, and building the judge. The gate on the control node takes
+   about twice as long, 2 m 15 s to 2 m 24 s against 1 m 11 s to 1 m 48 s. The gate also works on
+   the throwaway store. The repository's script takes 3.5 minutes on the laptop and more than 27 on
+   the control node.
+3. **The per-package times** in the verdicts' reports (table in the report). These separate CPU from
+   the store. Packages without a store run alike on every holder, and packages with a store run five
+   to seven times slower on the control node.
+4. **The runtime's statistics on the control node.** The real store, the forge and the bus are not
+   saturating the processor: the forge was at 30 % of one core and the store at 6 % when sampled.
+   The throwaway stores wrote 16–20 GB each. The control node has 12 cores and 64 GB of memory. The
+   home server has 24 cores. That is a difference, but the packages that use no store show it does
+   not matter here.
+5. **The build agent's code** (mesh-controller `internal/builder`, `cmd/mesh-builder`):
+   - one ask at a time per holder, pulled by whichever holder is free. So no node runs two checks
+     at once, and nothing prefers or avoids the control node;
+   - the store is raised as the release's stock image with stock settings, so every commit and every
+     `CREATE DATABASE` waits for the disk to flush. The suite creates a database per test;
+   - the check's own bound is 45 minutes. The 30 minutes that fired is the repository's
+     `go test -timeout 30m`;
+   - a holder's containers are removed by the check's own deferred cleanup, by a kill, or by the
+     next delivery of the same ask on the same machine. Nothing removes them when the holder process
+     dies before its deferred cleanup runs and the ask goes elsewhere. A recreate does exactly that.
+
+**Ruled out:**
+- *Processor overload*: the store-free packages run equally fast everywhere.
+- *A cold Go build cache*: the cache is in the build seat's workspace, which is kept across
+  recreates. Building the judge takes 3–10 s on every holder.
+- *Parallel checks on one node*: a holder takes one ask at a time.
+- *The stray containers competing*: they were idle (0 % CPU, about 80 MB each) when sampled. They
+  are waste, but they do not explain the slowdown.
+
+**Located.** Two places, both in mesh-controller:
+
+- `internal/builder/check.go` raises the throwaway store with full durability. On a machine whose
+  disk is busy with the mesh's own data, each flush waits. A store that lives for one check and is
+  removed after it needs none of that.
+- `cmd/mesh-builder` never removes what an earlier holder on its own machine left.
+
+**Fix**, in novox/mesh-controller PR #133:
+
+- the throwaway store is raised with `fsync`, `synchronous_commit` and `full_page_writes` off. It is
+  still the release the mesh runs; only crash safety is gone. On the laptop the store-bound packages
+  wrote 604 MB instead of 2.07 GB and finished in 43 s instead of 47 s. The laptop's disk is fast
+  and idle, so the time saved there is small. The control node is where it should show;
+- a holder that starts removes every container labelled with an ask of the seat (`build-<n>`) before
+  it takes anything. A container labelled with another id is left alone, such as a check a person
+  runs by hand or a test's. The plan that sends the fix recreates every build agent, and that clears the eleven pairs.
+
+**Resolved when** a controller check that lands on the control node finishes inside the suite's
+timeout and in about the time the other holders take, and when the holder's start leaves no
+`build-*` containers behind. If the control node is still much slower after this, the next step is
+to keep the store's data in memory (`--tmpfs`) or to stop the control node taking checks, by pausing
+its holder through `node-build-agent.pause`. That is a decision for the operator, not a code change.