No instrument prices a CI lane's wall clock, so a lane at 97% of its timeout is a failure nobody has met yet #285

Closed
opened 2026-09-17 13:26:48 +02:00 by buildagent · 1 comment
Member

The measurement

The native-Windows lane's durations, in order:

run 816  beabeb8   2h53m38s   success      ← 97% of a 3h ceiling
run 818  38ca96d   2h46m00s   failure      (a real test failure)
run 824  4e3106f   3h00m04s   CANCELLED    ← the ceiling, met
run 827  935c1f2   1h17m47s   cancelled by a push
run 829  d4ea649     56m08s   success      ← after #283

Nothing reported a problem at run 816. It was green. The lane had seven minutes of headroom and no instrument was counting, so the margin was invisible until a later commit spent it.

Why that matters more than it sounds

The commit that "broke" the lane did not break anything. blast_radius_hook added roughly an hour of legitimate integration testing to a budget that was already gone. The failure was attributed to the new test — by me, twice, in commit messages — when the actual cause was a pre-existing cost nobody had priced.

That is the specific damage of an unmeasured margin: it misattributes. The next person to land a slow thing here will also be told it is their fault, and will also be wrong.

The underlying cost turned out to be #283 — code-index query paying a fifteen-minute daemon-startup budget per invocation, ~10 minutes each on Windows. That is now fixed and the lane is at 56m. The margin is healthy again, and still nothing is measuring it.

What exists, and what does not

This project prices things carefully where it prices them at all:

  • tests/corpus/baseline.json + corpus_cost — SQLite work per indexing pass, ratcheted, with cost_attribution naming the statement.
  • startup_payload_budget_e2e — the MCP startup payload in tokens, with a RESERVE that fails before the ceiling does, and a per-category split.
  • POPULATION_FLOOR in the precision gate — fails when the population it measures against shrinks.

Every one of those was built because an unmeasured number moved and nobody noticed. Wall-clock per CI lane is the same shape and has none of it.

Note the pattern in startup_payload_budget_e2e specifically: it does not merely fail at the ceiling, it fails once the RESERVE is spent, and its message is "TRIM, do not raise: a raise is a bill sent to every session." That is exactly the instrument this is missing — a lane that reports at 80% rather than dying at 100%.

What would close this

A gate that reads each lane's recent durations and fails — or warns loudly — when one crosses a reserve short of its timeout. Specifically:

  1. The ceiling has to be readable. Today the 3h limit is the runner's, discovered by being cancelled. It should be stated somewhere a gate can compare against.
  2. A reserve, not just a ceiling. 80% is a reasonable first cut: run 816 would have reported at 2h24m, well before anything was cancelled.
  3. Attribution when it fires, in the spirit of cost_attribution: "this lane is at 97%, and the three slowest test binaries in it are X, Y, Z." A duration alone says a lane is slow; it does not say what to trim. The evidence for #283 came from reading per-test timestamps out of a 22,000-line log by hand.
  4. Per-lane, not aggregate. The main CI lane has been ~1h throughout and is nowhere near trouble. An average across lanes would have hidden this entirely.

The data is already in the forge's API (duration per run, per-job status), so this is a gate reading an endpoint rather than new instrumentation.

Scope note

This is deliberately NOT "make the Windows lane faster" — #283 did that, and the lane is fine today. It is that the lane was at 97% while green, and the only thing that ever told anyone was a cancellation three commits later.

## The measurement The native-Windows lane's durations, in order: ``` run 816 beabeb8 2h53m38s success ← 97% of a 3h ceiling run 818 38ca96d 2h46m00s failure (a real test failure) run 824 4e3106f 3h00m04s CANCELLED ← the ceiling, met run 827 935c1f2 1h17m47s cancelled by a push run 829 d4ea649 56m08s success ← after #283 ``` Nothing reported a problem at run 816. It was green. The lane had **seven minutes** of headroom and no instrument was counting, so the margin was invisible until a later commit spent it. ## Why that matters more than it sounds The commit that "broke" the lane did not break anything. `blast_radius_hook` added roughly an hour of legitimate integration testing to a budget that was already gone. The failure was attributed to the new test — by me, twice, in commit messages — when the actual cause was a pre-existing cost nobody had priced. That is the specific damage of an unmeasured margin: **it misattributes.** The next person to land a slow thing here will also be told it is their fault, and will also be wrong. The underlying cost turned out to be #283 — `code-index query` paying a fifteen-minute daemon-startup budget per invocation, ~10 minutes each on Windows. That is now fixed and the lane is at 56m. The margin is healthy again, and still nothing is measuring it. ## What exists, and what does not This project prices things carefully where it prices them at all: * `tests/corpus/baseline.json` + `corpus_cost` — SQLite work per indexing pass, ratcheted, with `cost_attribution` naming the statement. * `startup_payload_budget_e2e` — the MCP startup payload in tokens, with a RESERVE that fails before the ceiling does, and a per-category split. * `POPULATION_FLOOR` in the precision gate — fails when the population it measures against shrinks. Every one of those was built because an unmeasured number moved and nobody noticed. **Wall-clock per CI lane is the same shape and has none of it.** Note the pattern in `startup_payload_budget_e2e` specifically: it does not merely fail at the ceiling, it fails once the RESERVE is spent, and its message is "TRIM, do not raise: a raise is a bill sent to every session." That is exactly the instrument this is missing — a lane that reports at 80% rather than dying at 100%. ## What would close this A gate that reads each lane's recent durations and fails — or warns loudly — when one crosses a reserve short of its timeout. Specifically: 1. **The ceiling has to be readable.** Today the 3h limit is the runner's, discovered by being cancelled. It should be stated somewhere a gate can compare against. 2. **A reserve, not just a ceiling.** 80% is a reasonable first cut: run 816 would have reported at 2h24m, well before anything was cancelled. 3. **Attribution when it fires**, in the spirit of `cost_attribution`: "this lane is at 97%, and the three slowest test binaries in it are X, Y, Z." A duration alone says a lane is slow; it does not say what to trim. The evidence for #283 came from reading per-test timestamps out of a 22,000-line log by hand. 4. **Per-lane, not aggregate.** The main CI lane has been ~1h throughout and is nowhere near trouble. An average across lanes would have hidden this entirely. The data is already in the forge's API (`duration` per run, per-job status), so this is a gate reading an endpoint rather than new instrumentation. ## Scope note This is deliberately NOT "make the Windows lane faster" — #283 did that, and the lane is fine today. It is that the lane was **at 97% while green**, and the only thing that ever told anyone was a cancellation three commits later.
Author
Member

Closed by PR #289 (d119359). All four requirements are met: the ceiling is declared with its basis (1), a reserve reports short of it (2), a breach names the offending jobs (3), and it is per job rather than aggregate (4).

Your headline number was re-measured against the API rather than quoted: ci-windows.yml's max successful run is 10418s = 2h53m38s, which is 96.5% of 10800s. Confirmed, not stale.

Three things worth recording, because two of them correct the issue's own framing.

1. The ceiling is per JOB, not per lane — and that changes the arithmetic. The issue reasons in lane durations, which is right for ci-windows.yml because it has exactly one job. It is wrong for ci.yml: a workflow's duration is a critical path over 14 parallel jobs and nothing cancels it. What cancelled run 824 was the runner's per-job timeout. Pricing a 14-job workflow's total against a per-job ceiling would have read as reassuring while measuring the wrong thing. Every job is priced instead, which also delivers requirement 3 for free.

2. "The data is already in the forge's API" is true, but one field lies. A job's duration looks derivable as updated_at - run_started_at, and for recent rows it is EXACT — runs 854 and 852 derive 3301s and 3485s against the runs endpoint's authoritative 3301 and 3485. I validated on those two and generalised, which was the mistake.

updated_at is the ROW's last-modified time. This forge bulk-touched old rows: 736 of 907 success rows carry 2026-09-18T00:00:00+02:00 exactly, deriving cargo fmt durations of up to eight days against a real 56s. Every derived duration is now cross-checked against the run's authoritative duration — a job cannot outlast its run — and that clause is pinned by a test, because without it the reporting path prints 1432.46% consumed, -143906s left — OVER for four jobs whose real durations are minutes. A gate that loud and that wrong is worse than the silence it replaced.

3. It warns rather than fails, by explicit decision. The issue offers "fails — or warns loudly"; warn-only was chosen. House precedent points the other way (headroom::Ceiling::grade asserts; startup_payload_budget_e2e fails with "TRIM, do not raise"), so the divergence is recorded at the script's exit, in the CI job, and in the test, and pinned by the_gate_warns_rather_than_failing so that flipping it is deliberate rather than silent.

The reasoning is this issue's own: a lane's wall clock is a shared, slowly-drifting cost, and the person whose push would redden is almost never the person who spent the margin — which is the misattribution described here. The obligation that comes with warn-only is that the warning must be actionable, so it names the jobs and what they cost rather than printing a percentage. If a reserve breach here is ever ignored for weeks, that is the evidence for promoting it to a failure, and this issue should be reopened with it.

Current reading, from a real runner

25 jobs across three lanes, every one inside its reserve:

HEADROOM ci-windows.yml :: fmt+clippy+build+test: 3485s of 10800s (32.27%), 7315s left — OK
HEADROOM ci.yml :: cargo test:                    2969s of 10800s (27.49%), 7831s left — OK
HEADROOM ci.yml :: OSS corpus (tier 1):           2519s of 10800s (23.32%), 8281s left — OK

Known to fire: at a ceiling lowered to 3600s, ci-windows reads 96.81% — reproducing this incident almost exactly.

Verified by dispatch on run 857: the job measured (zero UNMEASURED), priced 23 jobs, and disclosed that attribution covered 78 of 101 recent rows rather than implying it covered all of them.

🤖 Generated with Claude Code

https://claude.ai/code/session_0126PDDLB4wNHxKXvWM1VNmu

Closed by PR #289 (`d119359`). All four requirements are met: the ceiling is declared with its basis (1), a reserve reports short of it (2), a breach names the offending jobs (3), and it is per job rather than aggregate (4). Your headline number was re-measured against the API rather than quoted: `ci-windows.yml`'s max successful run is **10418s = 2h53m38s**, which is 96.5% of 10800s. Confirmed, not stale. Three things worth recording, because two of them correct the issue's own framing. **1. The ceiling is per JOB, not per lane — and that changes the arithmetic.** The issue reasons in lane durations, which is right for `ci-windows.yml` because it has exactly one job. It is wrong for `ci.yml`: a workflow's `duration` is a critical path over 14 parallel jobs and nothing cancels it. What cancelled run 824 was the runner's **per-job** timeout. Pricing a 14-job workflow's total against a per-job ceiling would have read as reassuring while measuring the wrong thing. Every job is priced instead, which also delivers requirement 3 for free. **2. "The data is already in the forge's API" is true, but one field lies.** A job's duration looks derivable as `updated_at - run_started_at`, and for recent rows it is EXACT — runs 854 and 852 derive 3301s and 3485s against the runs endpoint's authoritative 3301 and 3485. I validated on those two and generalised, which was the mistake. `updated_at` is the ROW's last-modified time. This forge bulk-touched old rows: **736 of 907** success rows carry `2026-09-18T00:00:00+02:00` exactly, deriving `cargo fmt` durations of up to **eight days** against a real 56s. Every derived duration is now cross-checked against the run's authoritative `duration` — *a job cannot outlast its run* — and that clause is pinned by a test, because without it the reporting path prints `1432.46% consumed, -143906s left — OVER` for four jobs whose real durations are minutes. A gate that loud and that wrong is worse than the silence it replaced. **3. It warns rather than fails, by explicit decision.** The issue offers "fails — or warns loudly"; warn-only was chosen. House precedent points the other way (`headroom::Ceiling::grade` asserts; `startup_payload_budget_e2e` fails with "TRIM, do not raise"), so the divergence is recorded at the script's exit, in the CI job, and in the test, and pinned by `the_gate_warns_rather_than_failing` so that flipping it is deliberate rather than silent. The reasoning is this issue's own: a lane's wall clock is a shared, slowly-drifting cost, and the person whose push would redden is almost never the person who spent the margin — which is the misattribution described here. The obligation that comes with warn-only is that the warning must be actionable, so it names the jobs and what they cost rather than printing a percentage. **If a reserve breach here is ever ignored for weeks, that is the evidence for promoting it to a failure, and this issue should be reopened with it.** ## Current reading, from a real runner 25 jobs across three lanes, every one inside its reserve: ``` HEADROOM ci-windows.yml :: fmt+clippy+build+test: 3485s of 10800s (32.27%), 7315s left — OK HEADROOM ci.yml :: cargo test: 2969s of 10800s (27.49%), 7831s left — OK HEADROOM ci.yml :: OSS corpus (tier 1): 2519s of 10800s (23.32%), 8281s left — OK ``` Known to fire: at a ceiling lowered to 3600s, `ci-windows` reads **96.81%** — reproducing this incident almost exactly. Verified by dispatch on run [857](https://git.h-dv.de/h-dv/code-index/actions/runs/857): the job measured (zero `UNMEASURED`), priced 23 jobs, and disclosed that attribution covered 78 of 101 recent rows rather than implying it covered all of them. 🤖 Generated with [Claude Code](https://claude.com/claude-code) https://claude.ai/code/session_0126PDDLB4wNHxKXvWM1VNmu
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
h-dv/code-index#285
No description provided.