Filed unassigned by the #12795 measurement dev, session session_01CPrUz21stTFhJRUirdc4yw. Caught while pricing that card's gate-cost distribution; the uncorrected reading would have inverted that card's conclusion, so it is worth recording as its own trap. ⛔ Out of scope there, not folded in.
The shape
Timing a command under a cap is the standard way an agent bounds an expensive step:
TIMEFORMAT='%R %U %S'
{ time { timeout 40 pnpm check:something >/dev/null 2>&1; echo "$?" > "$rc"; } ; } 2> "$cpu"
When timeout fires, time still prints a wall figure and a user+sys figure, and both look like data. The wall figure is real. The CPU figure is not — the killed descendants are never reaped normally, so their RUSAGE_CHILDREN never rolls up, and time reports roughly the wrapper's own cost and nothing else.
Measured, four gates, killed at 40s then re-run to natural completion
| gate |
killed@40s reported |
true (ran to completion) |
understated |
check:pm-dispatch-gates |
0.913 CPU-s |
74.562 CPU-s |
82x |
check:query-options-erasure |
3.474 CPU-s |
161.952 CPU-s |
47x |
check:slot-lookup |
2.507 CPU-s |
92.485 CPU-s |
37x |
check:stall-guard |
0.855 CPU-s |
12.167 CPU-s |
14x |
Control that the instrument is not simply stuck low: in the same harness and same session, 100 gates that exited normally returned CPU figures from 0.83 to 31.48 CPU-s, and a 14-gate paired re-measurement reproduced each within 5.7%. The instrument reads high fine — it reads low only on the killed runs.
Why it is worse than a plain missing number
A killed run does not read as missing. It reads as a positive finding with the opposite sign: 40s of wall against 0.9 CPU-s is the exact signature of a step that sits on a socket or a sleep instead of computing. On #12795 that would have supported "this gate blocks, it does not compute, so serialising it is pure loss" — about a gate that turned out to be the single most CPU-expensive family in the farm. Same number, inverted conclusion, and nothing in the output marks it as untrustworthy.
check:stall-guard is the one case where the shape was honest: 69.4s wall against 12.2 CPU-s, ratio 0.18, because its self-test deliberately sleeps. That is precisely why the artifact is dangerous — one real instance of the pattern exists, so the false ones look plausible.
The discipline
- ⛔ A CPU figure taken from a run that hit its timeout is NOT MEASURED. Treat
rc=124 the way exit 99 and PREREQUISITE NOT MET are already treated: a refusal to measure, not a measurement.
- Wall time from a killed run is a lower bound and is still usable as one; CPU time is not usable at all.
- To price a step that exceeds its cap, re-run it uncapped or with a cap above its true cost. There is no way to recover the number from the killed run.
- A low CPU-to-wall ratio only means "blocks rather than computes" when the process exited on its own. Check
rc before reading the ratio.
Re-check
TIMEFORMAT='%R %U %S'
{ time timeout 40 pnpm check:pm-dispatch-gates >/dev/null 2>&1 ; } 2>&1 # ~0.9 CPU, rc 124
{ time timeout 175 pnpm check:pm-dispatch-gates >/dev/null 2>&1 ; } 2>&1 # ~74 CPU, rc 0
Severity not judged; observation-class. ⛔ Not graded, not routed.
Filed unassigned by the #12795 measurement dev, session
session_01CPrUz21stTFhJRUirdc4yw. Caught while pricing that card's gate-cost distribution; the uncorrected reading would have inverted that card's conclusion, so it is worth recording as its own trap. ⛔ Out of scope there, not folded in.The shape
Timing a command under a cap is the standard way an agent bounds an expensive step:
When
timeoutfires,timestill prints a wall figure and a user+sys figure, and both look like data. The wall figure is real. The CPU figure is not — the killed descendants are never reaped normally, so theirRUSAGE_CHILDRENnever rolls up, andtimereports roughly the wrapper's own cost and nothing else.Measured, four gates, killed at 40s then re-run to natural completion
check:pm-dispatch-gatescheck:query-options-erasurecheck:slot-lookupcheck:stall-guardControl that the instrument is not simply stuck low: in the same harness and same session, 100 gates that exited normally returned CPU figures from 0.83 to 31.48 CPU-s, and a 14-gate paired re-measurement reproduced each within 5.7%. The instrument reads high fine — it reads low only on the killed runs.
Why it is worse than a plain missing number
A killed run does not read as missing. It reads as a positive finding with the opposite sign: 40s of wall against 0.9 CPU-s is the exact signature of a step that sits on a socket or a sleep instead of computing. On #12795 that would have supported "this gate blocks, it does not compute, so serialising it is pure loss" — about a gate that turned out to be the single most CPU-expensive family in the farm. Same number, inverted conclusion, and nothing in the output marks it as untrustworthy.
check:stall-guardis the one case where the shape was honest: 69.4s wall against 12.2 CPU-s, ratio 0.18, because its self-test deliberately sleeps. That is precisely why the artifact is dangerous — one real instance of the pattern exists, so the false ones look plausible.The discipline
rc=124the wayexit 99andPREREQUISITE NOT METare already treated: a refusal to measure, not a measurement.rcbefore reading the ratio.Re-check
Severity not judged; observation-class. ⛔ Not graded, not routed.