diff --git a/04-ISSUES/306-a-check-on-the-control-node-ran-past-its-timeout/00-report.md b/04-ISSUES/306-a-check-on-the-control-node-ran-past-its-timeout/00-report.md new file mode 100644 index 00000000..eb8eac1e --- /dev/null +++ b/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..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. diff --git a/04-ISSUES/306-a-check-on-the-control-node-ran-past-its-timeout/01-diagnosis.md b/04-ISSUES/306-a-check-on-the-control-node-ran-past-its-timeout/01-diagnosis.md new file mode 100644 index 00000000..627d446d --- /dev/null +++ b/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-`) 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.