novox/hq
6
0
Fork 0
Code Issues Pull Requests 7 Releases Wiki Activity

Merge pull request 'Issue 306: a check on the control node ran past its timeout' (#191) from issues/306-a-check-on-the-control-node-ran-past-its-timeout into main

Browse Source
This commit was merged in pull request #191.
This commit is contained in:
mesh-admin
2026-10-08 08:34:59 +00:00
parent 37e82fb9fc db0fea6067
commit fcb76ca29d
2 changed files with 135 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files
04-ISSUES/306-a-check-on-the-control-node-ran-past-its-timeout/00-report.md
+73
View File
@@ -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
+62
View File
@@ -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.