fix(runner-controller): stop queued jobs waiting behind busy capacity, and measure pickup latency

supernaut kommenterad

2026-08-02 15:56:11 +00:00

Ägare

Closes #327, closes #328.

#327 — queued jobs were waiting behind busy capacity.

reconcile() subtracted active_count from the desired pool size, and active_count counts VMs
that have already claimed a job and are busy running it. So a queued job created no capacity while
any other VM was busy: it waited for that VM to finish, power off, be seen SHUTOFF and be reaped
before one was booted for it.

Measured over 7 days and 345 runs: median pickup 33 s, but p90 137 s, with 20 % of runs
averaging 187 s. 301 cycles carried the starvation signature. One run waited 93 s of which 61 s
was the controller declining to boot into free capacity with half the pool idle.

One deliberate deviation from the formula in the issue. The issue proposes
min(cap, queued + running + min_idle) - active; this implements the stated intent — count only
idle capacity:

idle      = max(0, active_count - running_jobs)
to_create = clamp(queued + min_idle - idle, 0, max_total - active_count)

Identical in every ordinary state. They diverge when running > active — a job left running after
its VM was reaped. The additive form boots a VM for a job no runner can ever claim, which then idles
until the two-hour backstop. There is a test locking that in. A failed running-jobs read reproduces
the old conservative formula exactly, and max_total remains a hard ceiling in every branch.

The per-attempt handle alternative was assessed and declined for now: it changes the cloud-init
contract, depends on semantics unverified against this instance, and is incompatible with the warm
buffer, since nothing can pre-boot against a handle that does not exist yet. Recorded as a TODO; it
plausibly belongs after the controller extraction.

The running-jobs snapshot is now read once and shared with orphan-cancel, so no extra API call.

#328 — nothing measured latency.

Every number above had to be reconstructed by hand, which is why a stall affecting a fifth of all
runs went unnoticed for weeks despite a dedicated dashboard and two alert rules. Adds boot, ready and
pickup durations, all derived from reads the loop already makes — no new API calls per cycle —
exported through the existing atomic textfile writer, plus a dashboard row and a companion alert for
sub-minute systematic stalls, which a duration-based queue alert is structurally blind to.

"Ready" keys on the runner's status leaving offline rather than on registration membership: the
registration is minted before the VM boots, so membership would time nothing.

Verification

47 checks pass, up from 17, written before the implementation. The three named acceptance criteria
pass explicitly. reconcile() was also driven end-to-end against fakes and logs the acceptance case
verbatim. ruff clean, ansible-lint 0 failures across 191 files, syntax-check clean, textfile
smoke test 12 ok.

Caveats, documented in code and the runbook

Sampling is once per cycle, so every figure over-estimates by up to one interval; and a job cancelled
while queued records as a short pickup. Correcting the latter costs a second read per cycle for no
operational gain. #327's acceptance criterion that p90 drops to ~35 s is only verifiable after an
apply.

Closes #327, closes #328. **#327 — queued jobs were waiting behind busy capacity.** `reconcile()` subtracted `active_count` from the desired pool size, and `active_count` counts VMs that have already claimed a job and are busy running it. So a queued job created no capacity while any other VM was busy: it waited for that VM to finish, power off, be seen SHUTOFF and be reaped before one was booted for it. Measured over 7 days and 345 runs: median pickup **33 s**, but **p90 137 s**, with 20 % of runs averaging **187 s**. 301 cycles carried the starvation signature. One run waited 93 s of which 61 s was the controller declining to boot into free capacity with half the pool idle. **One deliberate deviation from the formula in the issue.** The issue proposes `min(cap, queued + running + min_idle) - active`; this implements the stated intent — count only *idle* capacity: ```python idle = max(0, active_count - running_jobs) to_create = clamp(queued + min_idle - idle, 0, max_total - active_count) ``` Identical in every ordinary state. They diverge when `running > active` — a job left `running` after its VM was reaped. The additive form boots a VM for a job no runner can ever claim, which then idles until the two-hour backstop. There is a test locking that in. A failed running-jobs read reproduces the old conservative formula exactly, and `max_total` remains a hard ceiling in every branch. The per-attempt `handle` alternative was assessed and declined for now: it changes the cloud-init contract, depends on semantics unverified against this instance, and is incompatible with the warm buffer, since nothing can pre-boot against a handle that does not exist yet. Recorded as a TODO; it plausibly belongs after the controller extraction. The running-jobs snapshot is now read once and shared with orphan-cancel, so no extra API call. **#328 — nothing measured latency.** Every number above had to be reconstructed by hand, which is why a stall affecting a fifth of all runs went unnoticed for weeks despite a dedicated dashboard and two alert rules. Adds boot, ready and pickup durations, all derived from reads the loop already makes — **no new API calls per cycle** — exported through the existing atomic textfile writer, plus a dashboard row and a companion alert for sub-minute systematic stalls, which a duration-based queue alert is structurally blind to. "Ready" keys on the runner's status leaving `offline` rather than on registration membership: the registration is minted before the VM boots, so membership would time nothing. ### Verification 47 checks pass, up from 17, written before the implementation. The three named acceptance criteria pass explicitly. `reconcile()` was also driven end-to-end against fakes and logs the acceptance case verbatim. `ruff` clean, `ansible-lint` 0 failures across 191 files, syntax-check clean, textfile smoke test 12 ok. ### Caveats, documented in code and the runbook Sampling is once per cycle, so every figure over-estimates by up to one interval; and a job cancelled while queued records as a short pickup. Correcting the latter costs a second read per cycle for no operational gain. #327's acceptance criterion that p90 drops to ~35 s is only verifiable after an apply.

supernaut lade till 2 incheckningar

2026-08-02 15:56:11 +00:00

fix(runner-controller): count only idle capacity when sizing the pool 76e59cfb08

`active_count` includes ephemeral VMs that have already claimed a job and are
busy running it, so `min(max_total, queued + min_idle) - active` treated a busy
VM as spare capacity: with min_idle=0 a newly queued job created no capacity at
all while any other VM was working. It waited for that VM to finish, power off,
be seen SHUTOFF and be reaped before one was booted for it.

Measured over 7 days / 345 runs: median pickup 33 s but p90 137 s, with 20 % of
runs averaging 187 s; 301 cycles carried the `active > desired >= 1, create=0`
starvation signature. One 93 s wait was 61 s of the controller declining to boot
into a half-idle pool.

Demand is now offset only against IDLE capacity (active minus jobs running on
the label), clamped to the max_total headroom. Implemented as the pure
`_compute_capacity`, unit-tested with the starvation case, the read-failure
fallback and the cap.

Two deliberate details:

- The idle-capacity form is used rather than the arithmetically simpler
  `min(cap, queued + running + min_idle) - active`. They agree everywhere except
  when running exceeds active — a job stuck `running` after its VM was reaped —
  where the additive form would boot a VM for a job no runner can ever claim.
- A failed running-jobs read yields None, which falls back to the previous
  conservative formula rather than guessing. max_total stays a hard ceiling.

The running-jobs snapshot is read once per cycle and shared with orphan-cancel,
which previously fetched it itself, so this adds no API call when that path is
enabled.

Closes #327.

feat(runner-controller): instrument CI pickup latency per stage

ci / ci (pull_request) Successful in 1m58s

Detaljer

b155bce53b

The controller exported health (active_vms, queued_jobs, last_loop_ok, …) but no
latency at all: nothing recorded how long a triggered job waited to start, or
where that time went. Every figure in the capacity bug had to be reconstructed by
hand from the Forgejo API cross-correlated against the log store — which is why a
60-200 s stall on 20 % of runs went unnoticed for weeks despite a dedicated
dashboard and two alert rules, and why any boot-time work was unverifiable.

Three stages are now timed, each from data the reconcile loop already reads, so
this adds no OpenStack or Forgejo calls per cycle:

  boot   - create_server to the VM observed ACTIVE   (the server list)
  ready  - create_server to its runner online        (the runners list)
  pickup - a job first seen queued to it being claimed (the jobs list)

"Ready" keys on the runner's status flipping off `offline`, not on registration
membership: the registration is minted before the VM boots, so membership would
time nothing. Pickup follows individual job ids across cycles, so
`_list_queued_jobs` now returns the waiting jobs rather than a bare count.

Exported as last/p50/p90/samples gauges over a 6h rolling window through the
existing atomic textfile writer — no new scrape target, no new dependency. -1
reuses the established "unknown" sentinel. Percentiles are nearest-rank: with the
sample counts a small pool produces, an interpolated p90 would invent a value
that never happened.

Also adds the Pickup latency dashboard row (three p90 tiles, a sample count so a
p90 over two samples is not read as a distribution, and a stage-comparison
timeseries), and RunnerPickupSlow. That alert is a companion to the queue alerts
rather than a retune of them: theirs is a duration test tuned for outages, which
is structurally blind to a systematic sub-minute stall; this one watches the
distribution.

Sampling is once per controller cycle, so every figure is an over-estimate by up
to one poll interval, and a job cancelled while queued reads as a fast pickup.
Both caveats are documented in the runbook alongside how to read the three stages
against each other.

Closes #328.

supernaut tvångsskickade fix/runner-capacity-and-latency från b155bce53b

ci / ci (pull_request) Successful in 1m58s

Detaljer

till a8292cda9d

ci / ci (pull_request) Successful in 1m27s

Detaljer

2026-08-02 16:15:24 +00:00

Jämför

supernaut tvångsskickade fix/runner-capacity-and-latency från a8292cda9d

ci / ci (pull_request) Successful in 1m27s

Detaljer

till 256b381db4