|
| 1 | +# Should CPU-heavy `check:*` runs be routed through `os-verify-lock`? — the measurement |
| 2 | + |
| 3 | +**Date:** 2026-08-31 · **Box:** one container, 4 cores, 16 GB, 3-4 sibling dev agents live |
| 4 | +throughout · **Instrument:** `scripts/pm/os-verify-lock.sh --report` ledger + direct timing |
| 5 | + |
| 6 | +This audit delivers the four quantities `scripts/pm/os-verify-lock.sh` names as unmeasured in |
| 7 | +its `WHAT THIS LOCK DOES NOT COVER` header. It **implements nothing** and changes nothing about |
| 8 | +what the lock serialises. The routing decision it feeds is a separate, maintainer-facing call — |
| 9 | +this file is only the number that call was waiting on. |
| 10 | + |
| 11 | +> ⚠️ **Shared-box seconds throughout.** Every absolute below was taken on a box carrying other |
| 12 | +> agents' unlocked work; ambient load ranged from 1.2 to 19.6 across the session. The header's |
| 13 | +> own prescription applies to this file too: **quote the ratios, not the absolutes.** Where a |
| 14 | +> conclusion depends on an absolute, it is stated as a bound and the direction of the bound is |
| 15 | +> named. |
| 16 | +
|
| 17 | +--- |
| 18 | + |
| 19 | +## Answer in one line |
| 20 | + |
| 21 | +**Every routing policy measured is worse than routing nothing, on the quantity that decides it.** |
| 22 | +Today 2.0% of locked runs return exit 99 (a NOT MEASURED run). Across a 64-cell sweep of four |
| 23 | +routing policies, four demand levels and four levels of CPU credit handed to routing, **the best |
| 24 | +cell is 4.0% and the worst is 65.7%** — no cell reaches today's 2.0%. Routing converts |
| 25 | +measurements into non-measurements at 2x to 33x the current rate. |
| 26 | + |
| 27 | +--- |
| 28 | + |
| 29 | +## Quantity 1 — Gate-run cost distribution · MEASURED |
| 30 | + |
| 31 | +All 116 `check:*` families in the root `package.json`, each run once as `pnpm check:NAME`, wall |
| 32 | +time captured with the exit code taken before any pipe. Two families hit the 120 s harness |
| 33 | +timeout and were re-run uncensored; their real values are used below. |
| 34 | + |
| 35 | +| bucket | families | % of families | gate-seconds | % of total cost | |
| 36 | +|---|---:|---:|---:|---:| |
| 37 | +| under 1 s | 6 | 5.2% | 5.8 s | 0.5% | |
| 38 | +| 1-2 s | 48 | 41.4% | 64.7 s | 5.6% | |
| 39 | +| 2-5 s | 31 | 26.7% | 96.0 s | 8.3% | |
| 40 | +| 5-10 s | 20 | 17.2% | 146.3 s | 12.7% | |
| 41 | +| 10-30 s | 6 | 5.2% | 99.5 s | 8.6% | |
| 42 | +| 30-100 s | 3 | 2.6% | 206.4 s | 17.9% | |
| 43 | +| over 100 s | 2 | 1.7% | 534.5 s | 46.3% | |
| 44 | + |
| 45 | +**Whole farm, run serially: 1153 s (19.2 min). p50 = 2.3 s, p90 = 9.5 s, p95 = 23.1 s, max = 305.5 s.** |
| 46 | + |
| 47 | +The heavy tail: |
| 48 | + |
| 49 | +| rank | family | cost | gap to next | |
| 50 | +|---:|---|---:|---:| |
| 51 | +| 1 | `check:pm-dispatch-gates` | 305.5 s | x1.33 | |
| 52 | +| 2 | `check:query-options-erasure` | 229.0 s | **x2.33** | |
| 53 | +| 3 | `check:slot-lookup` | 98.3 s | x1.41 | |
| 54 | +| 4 | `check:stall-guard` | 69.9 s | **x1.83** | |
| 55 | +| 5 | `check:engine-double-contract` | 38.2 s | **x1.65** | |
| 56 | +| 6 | `check:changeset-gate-self-tests` | 23.1 s | x1.09 | |
| 57 | +| 7 | `check:entry-guard` | 21.1 s | x1.18 | |
| 58 | + |
| 59 | +**Is there a clean threshold?** Partly, and the honest answer has two halves. |
| 60 | + |
| 61 | +- **The concentration is extreme and real.** 5 families (4.3% of the farm) carry **64.3%** of all |
| 62 | + gate-seconds; the top 2 alone carry **46.3%**. |
| 63 | +- **The cut point is defensible but not razor-sharp.** Ranks 1-5 are separated by steps of x1.33, |
| 64 | + x2.33, x1.41 and x1.83, and rank 5 stands x1.65 clear of rank 6. Below rank 6 the distribution is |
| 65 | + **smooth** — every consecutive gap is x1.30 or less, most under x1.10. So a threshold exists at |
| 66 | + roughly **30 s**, isolating exactly 5 families, and there is nothing resembling a threshold |
| 67 | + anywhere below that. |
| 68 | + |
| 69 | +### ⚠️ Correction to the premise: "most are sub-second" is false as invoked, true as scripted |
| 70 | + |
| 71 | +The card records the farm as *"176 families; most are sub-second."* As measured, **only 6 of 116 |
| 72 | +families finish in under a second, and the fastest is 934 ms.** The reason is not that the gates |
| 73 | +are heavy — it is that the invocation is: |
| 74 | + |
| 75 | +| measurement | time | |
| 76 | +|---|---:| |
| 77 | +| `pnpm check:node-version` (three reps) | 966 / 989 / 971 ms | |
| 78 | +| `node scripts/check-node-version.mjs` (the same gate, no pnpm) | **101 ms** | |
| 79 | +| `node scripts/check-console-sha.mjs` | **57 ms** | |
| 80 | +| `node -e 'process.exit(0)'` (control) | 39 ms | |
| 81 | + |
| 82 | +**For the light families roughly 97% of the measured wall time is pnpm's own startup, not gate |
| 83 | +work.** Both readings are true of different things, and the routing question needs the first: what |
| 84 | +would be routed is the command an agent types, and that command costs ~970 ms before the gate |
| 85 | +begins. The farm count has also moved — `dispatch-gates.mjs` now discovers **190** families across |
| 86 | +29 workflow files, against the card's 176. |
| 87 | + |
| 88 | +--- |
| 89 | + |
| 90 | +## Quantity 2 — Queue-depth effect · MEASURED, and the sign is not the one the card allowed for |
| 91 | + |
| 92 | +The card leaves open that *"serialised-but-uncontended can beat parallel-but-thrashing on 4 |
| 93 | +cores."* It does not, at any concurrency measured. One fixed CPU-bound gate was run at W = 1, 2, 4 |
| 94 | +and 8 concurrent copies; aggregate throughput is the figure of merit, because W = 1 **is** the |
| 95 | +routed world for gate runs. |
| 96 | + |
| 97 | +| sweep | ambient load | W=1 | W=2 | W=4 | W=8 | |
| 98 | +|---|---|---:|---:|---:|---:| |
| 99 | +| `check:objectql-double-limit`, rep 1 | 2.0 - 3.1 | 4.12 | 7.31 | **9.80** | 7.57 | |
| 100 | +| `check:adr-anchors` | 8.5 - 11.3 | 9.40 | 9.27 | 9.28 | **10.13** | |
| 101 | +| `check:objectql-double-limit`, rep 2 | 11.6 - 19.6 | 4.34 | 5.94 | 5.26 | **6.64** | |
| 102 | + |
| 103 | +(gates per minute; **bold** = best in row) |
| 104 | + |
| 105 | +**W = 1 is never the throughput maximum — in three sweeps out of three.** Two regimes: |
| 106 | + |
| 107 | +- **Box not already saturated** (rep 1, load ~2-3): parallelism pays hard. Serialising costs |
| 108 | + **2.38x aggregate gate throughput**. |
| 109 | +- **Box already saturated** (`adr-anchors` and rep 2, load 8.5-19.6): the curve goes flat. |
| 110 | + Serialising costs approximately nothing, because the cores were already the binding constraint. |
| 111 | + |
| 112 | +So the trade is asymmetric in a way that settles the sign: **the best case for routing is "costs |
| 113 | +nothing", and the ordinary case is "costs 1.8x to 2.4x". There is no measured case where it wins.** |
| 114 | +Even 2x over-subscription (W = 8 on 4 cores, plus siblings) beat serialisation by 1.53x-1.84x. |
| 115 | + |
| 116 | +⛔ **What this instrument cannot see.** The ledger lives in the container's `/tmp`, so it answers |
| 117 | +only within one container lifetime; the current file spans 16.1 h across 2 boots. Per-agent |
| 118 | +**end-to-end wall time** — the card's preferred framing for (2) — is **NOT MEASURED**: nothing |
| 119 | +records when an agent's card starts or ends, and no ledger field carries an agent identity. What is |
| 120 | +measured is aggregate gate throughput at the box, which bounds it: an agent cannot finish its gate |
| 121 | +work faster than the box completes gate work. |
| 122 | + |
| 123 | +--- |
| 124 | + |
| 125 | +## Quantity 3 — Budget fit · MEASURED, and it is decisive |
| 126 | + |
| 127 | +The acquisition budget is **540 s** (`HARD_CAP_S`), unchanged. A run that cannot acquire inside it |
| 128 | +returns exit 99, and exit 99 is a **NOT MEASURED** run — no gate was decided by it. |
| 129 | + |
| 130 | +### Baseline, from the real ledger (99 records, 16.1 h, 2 boots) |
| 131 | + |
| 132 | +| quantity | value | |
| 133 | +|---|---| |
| 134 | +| server utilisation | **rho = 23.5%** | |
| 135 | +| arrival rate | 6.14 locked runs / h | |
| 136 | +| mean service time | 148 s (p50 125 s, p90 387 s, max 1118 s) | |
| 137 | +| acquisition wait, over runs that waited at all | n = 26, p50 151 s, **p90 536 s**, max 540 s | |
| 138 | +| queue-timeouts (exit 99) | **2 of 99 = 2.0%** | |
| 139 | +| queue depth on arrival | p50 1, p90 1, max 2 | |
| 140 | + |
| 141 | +Two facts about that baseline decide most of the question before any simulation: |
| 142 | + |
| 143 | +1. **The wait distribution is already pressed flat against the cap.** p90 of the waiting |
| 144 | + population is **536 s** against a 540 s budget. There is no headroom to spend. |
| 145 | +2. **The lock is idle 76.5% of the time, and still 2% of runs time out.** The load is not high, it |
| 146 | + is *bursty and heavy-tailed* — which is exactly the regime where adding work is punished |
| 147 | + super-linearly. |
| 148 | + |
| 149 | +### The arithmetic that needs no model |
| 150 | + |
| 151 | +The two heaviest families cost **305.5 s + 229.0 s = 534.5 s**. The acquisition budget is 540 s. |
| 152 | + |
| 153 | +> **Routing just the top two families means one gate sweep can occupy 99.0% of another caller's |
| 154 | +> entire acquisition budget, by itself, with the lock otherwise empty.** |
| 155 | +
|
| 156 | +### Trace-driven simulation |
| 157 | + |
| 158 | +The ledger's `ts`, `held` and `waited` fields reconstruct each run's arrival time exactly |
| 159 | +(`arrival = ts - held - waited`). Replaying those arrivals through a FIFO single server with a |
| 160 | +540 s budget — a job whose wait would exceed the budget never acquires and consumes no server |
| 161 | +time — reproduces the observed record: |
| 162 | + |
| 163 | +| | simulated | observed | |
| 164 | +|---|---|---| |
| 165 | +| exit 99 | 2 (2.0%) | 2 (2.0%) | |
| 166 | +| waited-at-all n | 27 | 26 | |
| 167 | +| wait p50 / p90 | 151 s / 536 s | 151 s / 536 s | |
| 168 | + |
| 169 | +⚠️ The quantiles match, and the direction of the residual error is known and favourable to |
| 170 | +routing: the trace cannot contain holders it never recorded (a free-hand `flock` holder takes no |
| 171 | +ticket and writes no ledger row), so **every routed figure below is a lower bound on the harm.** |
| 172 | + |
| 173 | +Synthetic gate sweeps were then injected at rate G and the build population re-measured. |
| 174 | +`f` is the build service-time multiplier once gates no longer run alongside a holder — i.e. the |
| 175 | +credit routing is given for the CPU it frees. `f = 1.00` gives routing no credit; `f = 0.60` |
| 176 | +assumes builds get 40% faster, which is **more** than the concurrency sweep above can support |
| 177 | +(removing ~1 competing process was worth x1.12; removing 3 was worth x1.68). |
| 178 | + |
| 179 | +**Build exit-99 rate. Today's value is 2.0%.** |
| 180 | + |
| 181 | +| policy | added rho | f=1.00 | f=0.85 | f=0.70 | f=0.60 | |
| 182 | +|---|---:|---:|---:|---:|---:| |
| 183 | +| **route ALL 116** (1153 s/sweep) G=1 | 32% | 13.1% | 10.1% | 7.1% | 6.1% | |
| 184 | +| G=2 | 63% | 23.2% | 20.2% | 14.1% | 8.1% | |
| 185 | +| G=4 | 129% | 45.5% | 42.4% | 38.4% | 40.4% | |
| 186 | +| G=8 | 256% | 59.6% | 60.6% | 59.6% | 65.7% | |
| 187 | +| **route >= 10 s, 11 fams** (840 s/sweep) G=1 | 23% | 8.1% | 8.1% | 9.1% | 7.1% | |
| 188 | +| G=2 | 46% | 17.2% | 13.1% | 13.1% | 12.1% | |
| 189 | +| G=4 | 94% | 40.4% | 35.4% | 38.4% | 36.4% | |
| 190 | +| G=8 | 186% | 58.6% | 59.6% | 59.6% | 61.6% | |
| 191 | +| **route >= 30 s, 5 fams** (741 s/sweep) G=1 | 20% | 8.1% | 7.1% | 7.1% | **4.0%** | |
| 192 | +| G=2 | 41% | 16.2% | 13.1% | 13.1% | 9.1% | |
| 193 | +| G=4 | 83% | 36.4% | 29.3% | 30.3% | 29.3% | |
| 194 | +| G=8 | 164% | 48.5% | 46.5% | 48.5% | 48.5% | |
| 195 | +| **route >= 60 s, 4 fams** (703 s/sweep) G=1 | 19% | 8.1% | 5.1% | 7.1% | **4.0%** | |
| 196 | +| G=2 | 39% | 17.2% | 14.1% | 12.1% | 8.1% | |
| 197 | +| G=4 | 79% | 33.3% | 36.4% | 29.3% | 31.3% | |
| 198 | +| G=8 | 156% | 45.5% | 48.5% | 50.5% | 50.5% | |
| 199 | + |
| 200 | +**No cell reaches the 2.0% baseline.** The minimum over all 64 cells is 4.0% — double today's |
| 201 | +rate — and it occurs only at the lowest demand, the narrowest policy, and a CPU credit larger than |
| 202 | +the measurement supports. |
| 203 | + |
| 204 | +### What demand is realistic |
| 205 | + |
| 206 | +A real derived family for an ordinary card is **7 families** (measured: `dispatch-gates.mjs` on |
| 207 | +this PR's own diff), rising to 16 once a changeset exists — not 116. At the measured median of |
| 208 | +2.3 s that is roughly 20-40 s per sweep. But a card touching a gate script or `scripts/pm/` pulls |
| 209 | +the self-test families in, and those sweeps cost 300-800 s. With 4 agents sweeping ~2-3 times per |
| 210 | +card, plausible fleet demand lands at **added rho ~7-25%** — the G=1 to G=2 rows, where the build |
| 211 | +exit-99 rate is **4.0% to 23.2%**, i.e. 2x to 12x today. |
| 212 | + |
| 213 | +⛔ **Fleet gate-run arrival rate is NOT MEASURED, and cannot be measured with this instrument.** |
| 214 | +Gate runs are unlocked today, so they take no ticket and write no ledger row — the ledger is blind |
| 215 | +to exactly the population routing would add. G is therefore swept rather than fitted, and the |
| 216 | +conclusion is stated as its robustness across the sweep, not as a point estimate. |
| 217 | + |
| 218 | +--- |
| 219 | + |
| 220 | +## Quantity 4 — The partial option · MEASURED. It wins its bracket and loses the question. |
| 221 | + |
| 222 | +Routing only the heavy families **does** dominate routing everything, monotonically. At G=4, |
| 223 | +f=1.00: route ALL 45.5%, `>=10 s` 40.4%, `>=30 s` 36.4%, `>=60 s` 33.3%. |
| 224 | + |
| 225 | +But the improvement is small, and the reason is structural rather than incidental: |
| 226 | + |
| 227 | +| policy | families | gate-seconds per sweep | % of the whole farm's cost | |
| 228 | +|---|---:|---:|---:| |
| 229 | +| route ALL | 116 | 1153 s | 100% | |
| 230 | +| route >= 10 s | 11 | 840 s | 72.8% | |
| 231 | +| route >= 30 s | 5 | 741 s | 64.3% | |
| 232 | +| route >= 60 s | 4 | 703 s | 61.0% | |
| 233 | + |
| 234 | +> **Dropping 112 of 116 families removes only 39% of the routed load, because the heavy families |
| 235 | +> *are* the load.** There is no version of "route only the expensive ones" that is also "route |
| 236 | +> only a little" — the threshold from quantity 1 selects precisely the families whose service times |
| 237 | +> are a large fraction of the whole 540 s budget. |
| 238 | +
|
| 239 | +So the partial option is the **best routing policy** and is still **worse than not routing**. Its |
| 240 | +one genuine merit is orthogonal to CPU: the 5 heavy families are the ones whose unlocked runs most |
| 241 | +distort a concurrent holder's timings, so routing them buys *measurement hygiene* even though it |
| 242 | +costs measurement *availability*. That trade is a judgement, not a number, and it belongs to |
| 243 | +whoever takes the routing decision. |
| 244 | + |
| 245 | +--- |
| 246 | + |
| 247 | +## What this measurement did not touch |
| 248 | + |
| 249 | +- **No routing was implemented.** Nothing about what the lock serialises changed. The only edit |
| 250 | + beside this file is a header pointer in `scripts/pm/os-verify-lock.sh` retiring the sentence that |
| 251 | + called this trade unmeasured. |
| 252 | +- **The lock is not the expensive part.** Acquire-plus-release on a free lock measured **~90 ms** |
| 253 | + (4 consecutive reps: 88, 93, 93, 94 ms) — an order of magnitude *cheaper* than the ~970 ms pnpm |
| 254 | + startup every routed gate would pay anyway. A fifth rep, taken first, cost 58 106 ms because a |
| 255 | + sibling held the lock; that is the contention, not the mechanism. |
| 256 | +- **The `#12538` premise needs a correction.** The wait budget was **not** raised: `HARD_CAP_S` |
| 257 | + and `DEFAULT_WAIT_S` are both still 540, and the script's own header argues at length that this |
| 258 | + constant cannot be raised, because the budget is spent inside one foreground turn that a ~600 s |
| 259 | + harness ceiling kills. What that card moved is `SLOT_MAX_AGE_S` (now `HARD_CAP_S * 3` = 1620 s), |
| 260 | + re-based on last relinquish. Any reasoning that assumed a larger acquisition budget is wrong in |
| 261 | + the other direction. |
| 262 | + |
| 263 | +## Reproducing |
| 264 | + |
| 265 | +``` |
| 266 | +bash scripts/pm/os-verify-lock.sh --report # the baseline population |
| 267 | +bash scripts/pm/os-verify-lock.sh --show-budget # the 540 s cap under test |
| 268 | +node scripts/pm/dispatch-gates.mjs # a real derived family for a card |
| 269 | +``` |
| 270 | + |
| 271 | +The per-family timings, the concurrency sweep and the simulation were produced by throwaway |
| 272 | +harnesses in the run's scratchpad; every input they consumed is either the ledger named by |
| 273 | +`--report` or a `pnpm check:NAME` invocation timed directly, and both are reproducible from the |
| 274 | +commands above. |
0 commit comments