From 193340a3cdac7983fd0c2d0e91c696a388529e6d Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 28 Aug 2026 06:13:36 +0000 Subject: [PATCH] fix(pm): head --report's hold bucket by the filter it actually applies (#12823) `mode_report` builds all three distributions with one shared filter, `v > 0`. That filter fits the `waited` heading exactly -- a recorded `waited` of 0 IS "did not wait at all" -- and it does not fit an acquisition. `held` is written by every terminal outcome, so `held=0` names two disjoint things: a run that never acquired at all, and a run that acquired and released inside one clock tick. The heading claimed the bucket held the second kind while the filter drops it -- measured, 3 of 69 rows on the ledger this was filed from, one of which had waited 78s for the lock before holding it briefly. The dropped rows are the FASTEST holds, so p50 and p90 read high, and they read higher the better the fleet gets at holding the lock briefly. Presentation only. The filter is NOT changed: admitting held=0 would move n, p50 and p90 for every ledger past and future, so a figure quoted from an older report would stop matching a re-run over the same rows. That is a change of definition and is carved out to its own card. Every number this report prints is unchanged by this commit. Two things measured while writing it, which shaped the wording: - `held` is a difference of two whole-second clock reads (`now_s`), so the obvious spelling -- "over runs that held it for at least a second" -- is itself false: a 200ms hold straddling a tick records 1 and a 900ms hold inside one records 0. The heading says RECORDED. - `run_unlocked` writes `ledger_append unlocked 0 "$ran" ...`, so on a host with no usable flock the command's RUNTIME lands in the `held` field although the lock was never taken. Those rows are IN this bucket. Annotated, not filtered out. The `n` gap the report never explained now has a line of its own, and `waited`'s heading -- already true of its filter -- is untouched, with a self-test case pinning it present so the likeliest wrong repair (making the three headings "consistent") reds. Six --self-test cases: the new heading present, the old one GONE rather than annotated, the three explanatory lines, and the `waited` heading still there. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01CPrUz21stTFhJRUirdc4yw --- scripts/pm/os-verify-lock.sh | 63 +++++++++++++++++++++++++++++++++++- 1 file changed, 62 insertions(+), 1 deletion(-) diff --git a/scripts/pm/os-verify-lock.sh b/scripts/pm/os-verify-lock.sh index 2afbffdf0b..ae71376ace 100755 --- a/scripts/pm/os-verify-lock.sh +++ b/scripts/pm/os-verify-lock.sh @@ -1862,10 +1862,47 @@ mode_report() { printf ' n=%s p50=%s p90=%s max=%s\n' \ "$(wc -l < "${tmp}/waited" | tr -d ' ')" "$(pct_of "${tmp}/waited" 50)" \ "$(pct_of "${tmp}/waited" 90)" "$(pct_of "${tmp}/waited" 100)" - printf 'lock hold, over runs that acquired (seconds):\n' + # ⚠ THE FILTER, NOT THE ACQUISITION. `v > 0` above is shared by all three + # buckets, and it is the `waited` heading it fits: a recorded `waited` of 0 IS + # "did not wait at all", so that one describes its population and ⛔ must not be + # touched. It does NOT describe an acquisition. `held` is written by every + # terminal outcome, so `held=0` names two disjoint things at once -- a run that + # never acquired (queue-timeout, lock-unusable and filter-matches-nothing each + # record a literal 0) and a run that acquired and released inside one clock + # tick -- and the old heading, "over runs that acquired", claimed the bucket + # held the second kind while the filter drops it. Measured: 3 of 69 rows on the + # ledger this was filed from, one of which had waited 78s for the lock. The + # direction is the awkward one -- the dropped rows are the FASTEST holds, so + # p50 and p90 read high, and they read higher the better the fleet gets at + # holding the lock briefly. + # + # ⛔ THE REPAIR IS THE HEADING AND NOT THE FILTER, and that is not a matter of + # taste. Admitting `held=0` here would move `n`, `p50` and `p90` for every + # ledger, past and future: a figure quoted from an older report would stop + # matching a re-run over the very same rows, with nothing in either report + # saying why. That is a change of DEFINITION and it is carved out to its own + # card; this line only stops the report naming a population it does not have. + # + # ⛔ AND IT SAYS "RECORDED", not "held it for at least a second" -- the obvious + # spelling, and measurably false. `held` is a difference of two whole-second + # clock reads (`now_s`), so a 200ms hold that straddles a tick records 1 while + # a 900ms hold inside one records 0. The filter admits a recorded VALUE; + # promoting that to a claim about true duration would rebuild this card's own + # defect one line further down. + printf 'lock hold, over runs whose RECORDED hold is 1s or more (seconds):\n' printf ' n=%s p50=%s p90=%s max=%s\n' \ "$(wc -l < "${tmp}/held" | tr -d ' ')" "$(pct_of "${tmp}/held" 50)" \ "$(pct_of "${tmp}/held" 90)" "$(pct_of "${tmp}/held" 100)" + printf ' ⇒ this n is BELOW the record count at the top, and the gap is not rounding:\n' + printf ' every row recording held=0 is absent. That is the runs that never acquired\n' + printf ' AND the runs that acquired and let go inside one clock tick, so the fastest\n' + printf ' holds are the missing ones and p50/p90 read high by exactly that omission.\n' + printf ' ⇒ 1 is not a claim that a full second was held: the field is a difference of\n' + printf ' whole-second clock reads, so a sub-second hold records 0 or 1 depending only\n' + printf ' on where it fell against the tick.\n' + printf ' ⇒ an `unlocked` run is IN this bucket and held nothing -- on a host with no\n' + printf ' usable flock the command runs unserialized and its RUNTIME lands in this\n' + printf ' field. Read the outcomes block above before reading these as contention.\n' # ⚠ THE LABEL, NOT THE RECORD. The field counts the arriving run itself: the # depth is read AFTER `take_ticket` has minted this call's own ticket, so its # floor is 1 and a completely uncontended fleet printed "1 waiter already @@ -2727,6 +2764,30 @@ mode_self_test() { st_case 'and the off-by-one heading itself is gone, not merely annotated' \ "$(printf '%s\n' "$rpt" | grep -c 'waiters already ahead):')" 0 + # The hold bucket's heading, which is the SAME defect one line up and was + # filed while the depth heading above was being repaired: `v > 0` drops every + # sub-second hold, and the heading said "over runs that acquired" -- a run + # that acquired, and one that waited 78s to do it, did acquire. The last two + # cases are the load-bearing ones and they guard opposite mistakes. Asserting + # only that the true wording is PRESENT would also pass on a report that kept + # the old heading beside it, which is how a heading defect survives a fix; and + # ⛔ the `waited` heading is CORRECT -- `waited > 0` literally is "waited at + # all" -- so it is pinned present here, because the likeliest way to get this + # repair wrong is to make the three headings "consistent" and break the one + # that was already true. + st_case 'and --report heads the hold bucket by what its filter admits' \ + "$(printf '%s\n' "$rpt" | grep -c 'whose RECORDED hold is 1s or more')" 1 + st_case 'and accounts for the gap between that n and the record count' \ + "$(printf '%s\n' "$rpt" | grep -c 'the gap is not rounding')" 1 + st_case 'and refuses to read a recorded 1 as a full second actually held' \ + "$(printf '%s\n' "$rpt" | grep -c 'not a claim that a full second was held')" 1 + st_case 'and names the unlocked rows sitting in a bucket titled about holds' \ + "$(printf '%s\n' "$rpt" | grep -c 'run is IN this bucket and held nothing')" 1 + st_case 'and the acquisition-shaped heading is gone, not merely annotated' \ + "$(printf '%s\n' "$rpt" | grep -c 'over runs that acquired')" 0 + st_case 'and the wait heading, which was already true of its filter, is untouched' \ + "$(printf '%s\n' "$rpt" | grep -c 'over runs that waited at all')" 1 + # --- the scope of the population, and the clock that names its floor ------ # # The report used to state its span and never its POSITION: `records: N,