From 1c6e736ed048f9bb88811bb2018fdb2465ac5c66 Mon Sep 17 00:00:00 2001 From: OffgridwithJD Date: Thu, 24 Sep 2026 15:41:54 -0600 Subject: [PATCH] test: derive the wide-table ANALYZE bound from the run and floor it (#1252) The arm read `an_ms < scan_ms * 20`. It went red on a CI runner against a branch of five test and docs files that cannot reach the ANALYZE path, and passed when the same jobs were re-run at the same commit. BOTH HALVES OF THAT RATIO WERE WRONG. Measured on pgcolumnar-audit, pg17a, five interleaved rounds, with the same psql_run wrapper around `SELECT 1` as the control and the fixture's row count asserted before any timing printed: empty 7.8 ms insert 316.6 ms scan 20.0 ms analyze 115.2 ms The scan carried ~12 ms of work above an ~8 ms floor -- 1.5x its own noise -- so the ratio measured the floor as much as the scan. And the terms did not move together: on the failing CI run ANALYZE was 3.1x this box while the scan was 0.7x it. The bound is now max(5000, insert_ms * 20). The insert reads and writes the same rows the ANALYZE samples, so it tracks the machine and the data volume; the floor stops a future faster write path squeezing the bound into a flake, which is how the old one got here -- its 20x was justified against "341 ms against a 155 ms scan" and no machine has measured a 155 ms scan since. THE BUG IS A HANG, NOT A SLOWDOWN, so the bound need not be tight. By removal against f82bdcd's parent, same fixture: UNFIXED did not complete within 180 s (an unbounded run was killed at 10m52s of 99.9% CPU, still running) against 206 ms fixed. THE DECISION IS A FUNCTION DRIVEN WITH LITERALS, so the branch a healthy machine never takes is judged here rather than by a box that happens to be slow. FOUR MUTATIONS, AND A AND B ARE DISJOINT: A the floor removed 3 arms x 5 majors B the scaling removed 2 arms x 5 majors disjoint from A C the input guard removed 1 arm x 5 majors isolates what A also hits D the floor moved by one 4 arms x 5 majors the only one reaching the tie C REDDENED NOTHING ON ITS FIRST RUN. The guard was uncovered, not redundant: 0, "", "abc" and a negative all reach the floor anyway because `$(( ))` reads them as 0. The input it defends is a PARTIALLY numeric token, where bash raises an arithmetic error and the function prints nothing. An arm was added to cover it rather than the guard deleted. analyze_stats ENTERS THE MUTATION LEDGER, which is most of this diff. It had ZERO rows; recording that the new arms redden means merging a RUN of the suite, and the tool refuses partial runs: ledger rows 1700 + 40 = 1740 never 1540 + 34 = 1574 32 pre-existing arms + 2 of the new 8 dated 160 + 6 = 166 1574 + 166 == 1740 suites_not_covered 249 -> 248 Two of the eight new arms arrive `never` and cannot honestly be mutated here: a `type -t` premise, and the timing arm itself, whose evidence is the removal proof against a different tree rather than a same-tree mutation. Verified: analyze_stats 40, harness_selftest 1198, docs_style 55 -- all PASSED on pg17a and pg18a, rc=0, zero FAIL rows. Real run: ANALYZE 121 ms against a 6340 ms cap (insert 317 ms). Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01MpajdQbkVJ9ey1XyYHcikP --- CHANGELOG.md | 35 +++++++++++++++ test/analyze_stats.sh | 82 +++++++++++++++++++++++++++++++----- test/check_ledger.tsv | 42 +++++++++++++++++- test/check_ledger_budget.txt | 47 ++++++++++++++++++++- 4 files changed, 193 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c835c3ee..ed578085 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -458,6 +458,41 @@ true until the next version shipped. ### Fixed +- `analyze_stats`' wide-table bound is derived from the run and floored, instead + of being a ratio over a 20 ms scan that was mostly process startup (#1252). + + The arm read `an_ms < scan_ms * 20`. It went red on a CI runner against a + branch of five test and docs files that cannot reach the ANALYZE path, and + passed when the same jobs were re-run at the same commit. + + Measured on `pgcolumnar-audit`, pg17a, five interleaved rounds, with the same + `psql_run` wrapper around `SELECT 1` as the control: + + ``` + empty 7.8 ms insert 316.6 ms scan 20.0 ms analyze 115.2 ms + ``` + + The scan carried about 12 ms of work above an 8 ms floor -- 1.5x its own noise + -- so the ratio measured the floor as much as the scan. The two terms did not + move together either: on the failing CI run ANALYZE was 3.1x this box while + the scan was 0.7x it. + + The bound is now `max(5000, insert_ms * 20)`. The insert reads and writes the + same rows the ANALYZE samples, so it tracks the machine and the data volume; + the floor stops a future faster write path squeezing the bound into a flake, + which is how the old one arrived here -- its 20x was justified against "341 ms + against a 155 ms scan" and no machine has measured a 155 ms scan since. + + The bug being defended is a hang, not a slowdown, so the bound does not need + to be tight. Measured by removal against `f82bdcd`'s parent, same fixture: + the unfixed build did not complete within 180 s, and an unbounded run was + killed at 10m52s of 99.9% CPU still running, against 206 ms fixed. + + The decision is a function driven with literals, so the branch a healthy + machine never takes is judged rather than left to a box that happens to be + slow. `analyze_stats` also enters the mutation ledger for the first time: + `suites_not_covered` falls from 249 to 248. + - The hand-rebuild diagnosis can no longer be silent, which is how the first version of it still told the 2026-09-24 nightly nothing (#1248). diff --git a/test/analyze_stats.sh b/test/analyze_stats.sh index 7ca27724..f00448b4 100755 --- a/test/analyze_stats.sh +++ b/test/analyze_stats.sh @@ -302,6 +302,7 @@ check "having an index available saves the point lookup real work" \ # and on the fixed build 341 ms against a 155 ms scan, which is why the threshold # has room. The reference is a full scan of the same table: ANALYZE reads a # sample and must not cost multiples of reading everything. +_as_t0=$(date +%s%N) psql_run "DROP TABLE IF EXISTS as_w; CREATE TABLE as_w (a bigint, b int, c int, d int, e timestamptz, f text, g text, h text) USING pgcolumnar; @@ -309,23 +310,84 @@ psql_run "DROP TABLE IF EXISTS as_w; '2020-01-01'::timestamptz + (g || ' sec')::interval, repeat('x', 200) || g, repeat('y', 200) || g, repeat('z', 200) || g FROM generate_series(1, ${PGC_ANALYZE_WIDE_ROWS:-40000}) g;" >/dev/null +_as_t1=$(date +%s%N) +ins_ms=$(( (_as_t1 - _as_t0) / 1000000 )) t0=$(date +%s%N) psql_run "ANALYZE as_w;" >/dev/null t1=$(date +%s%N) an_ms=$(( (t1 - t0) / 1000000 )) -t0=$(date +%s%N) -psql_run "SET pgcolumnar.enable_vectorization = off; - SELECT count(h) FROM as_w;" >/dev/null -t1=$(date +%s%N) -scan_ms=$(( (t1 - t0) / 1000000 )) - -echo "-- wide-table ANALYZE ${an_ms} ms against a ${scan_ms} ms full scan" +# THE BOUND IS DERIVED FROM THE RUN AND FLOORED (#1252). It used to be +# `an_ms < scan_ms * 20`, and both halves of that were wrong. +# +# THE OLD DENOMINATOR WAS MOSTLY NOT A SCAN. `psql_run` spawns a psql process +# and connects over TCP, and the timed region includes that. Measured on +# pgcolumnar-audit, pg17a, five interleaved rounds, the same wrapper around +# `SELECT 1` as the control: +# +# empty 7.8 ms insert 316.6 ms scan 20.0 ms analyze 115.2 ms +# +# so the scan carried ~12 ms of work above an ~8 ms floor -- 1.5x its own noise +# -- while the insert carried ~309 ms, 40x it. A ratio over the scan measures the +# floor as much as the scan, which is why the same guard read 5.8 locally and +# 25.2 on a CI runner and went red there on a branch that could not reach ANALYZE. +# +# AND THE TWO TERMS DID NOT MOVE TOGETHER. On that CI run ANALYZE was 3.1x this +# box while the scan was 0.7x it. The insert reads and writes the same rows the +# ANALYZE samples, so it tracks the same hardware and the same data volume. +# +# THE FLOOR IS NOT DECORATION. A relative guard tightens silently whenever its +# baseline improves, which is exactly how the old one arrived here: the comment +# above justified 20x against "341 ms against a 155 ms scan", and no machine has +# measured a 155 ms scan since. The floor means a future faster write path +# cannot squeeze this bound into a flake. +# +# THE BUG IS A HANG, NOT A SLOWDOWN, so the bound does not need to be tight. +# Measured by removal against f82bdcd's parent, same fixture, each tree building +# its own .so: UNFIXED did not complete within 180 s (an unbounded run was killed +# at 10m52s of 99.9% CPU, still running) against 206 ms fixed. At least 3000x. +pgc_analyze_cap_ms() { # pgc_analyze_cap_ms INSERT_MS -> the ceiling for ANALYZE + local _i="${1:-0}" _d + [ "$_i" -gt 0 ] 2>/dev/null || _i=0 + _d=$(( _i * 20 )) + [ "$_d" -gt 5000 ] && echo "$_d" || echo 5000 +} -check "ANALYZE on a wide table is not many times a full scan of it" \ - "$(awk -v a="$an_ms" -v s="$scan_ms" \ - 'BEGIN { print (s > 0 && a < s * 20) ? "yes" : "no (" a "ms against a " s "ms scan)" }')" \ +cap_ms=$(pgc_analyze_cap_ms "$ins_ms") +echo "-- wide-table ANALYZE ${an_ms} ms against a ${cap_ms} ms cap (insert ${ins_ms} ms)" + +# THE DECISION IS DRIVEN WITH LITERALS FIRST, so the branch a healthy machine +# never takes is judged here rather than only by a box that happens to be slow. +check_num "premise: the cap is exposed as a function, not written inline" \ + "$([ "$(type -t pgc_analyze_cap_ms)" = function ] && echo 1 || echo 0)" "1" +check_num "a fast machine still gets the floor, not a bound that shrinks with it" \ + "$(pgc_analyze_cap_ms 1)" "5000" +check_num "and a slow one gets a budget proportional to its own insert" \ + "$(pgc_analyze_cap_ms 1000)" "20000" +check_num "the floor and the derived bound meet where they should" \ + "$(pgc_analyze_cap_ms 250)" "5000" +check_num "and one millisecond past it the derived bound takes over" \ + "$(pgc_analyze_cap_ms 251)" "5020" +check_num "a missing or zero insert time still yields the floor, not zero" \ + "$(pgc_analyze_cap_ms 0)" "5000" +# THE INPUT GUARD WAS UNCOVERED UNTIL THIS ARM (#1236's taxonomy). Removing it +# reddened NOTHING on five majors, and the reason is that 0, "", "abc" and a +# negative all reach the floor anyway -- `$(( ))` reads them as 0. The one input +# it actually defends is a PARTIALLY numeric token, where bash raises an +# arithmetic syntax error and the function prints nothing at all: +# +# pgc_analyze_cap_ms 12abc with the guard 5000 +# without it +# +# So it is an uncovered guard rather than a redundant condition, and it is +# covered rather than deleted. +check_num "a malformed insert time yields the floor rather than an arithmetic error" \ + "$(pgc_analyze_cap_ms '12abc' 2>/dev/null)" "5000" + +check "ANALYZE on a wide table completes well inside its derived cap" \ + "$(awk -v a="$an_ms" -v c="$cap_ms" \ + 'BEGIN { print (c > 0 && a < c) ? "yes" : "no (" a "ms against a " c "ms cap)" }')" \ "yes" # --- 6. the fetch cost keeps the planner off an unclustered ordered index (#355) -- diff --git a/test/check_ledger.tsv b/test/check_ledger.tsv index 04624999..f94a81f0 100644 --- a/test/check_ledger.tsv +++ b/test/check_ledger.tsv @@ -1,3 +1,43 @@ +analyze_stats analyze_stats ANALYZE now collects statistics at all 15;16;17;18;19 never - +analyze_stats analyze_stats ANALYZE on a wide table completes well inside its derived cap 15;16;17;18;19 never - +analyze_stats analyze_stats a fast machine still gets the floor, not a bound that shrinks with it 15;16;17;18;19 2026-09-24 the cap loses its absolute floor, so the bound shrinks with the machine it runs on;the floor moved by one, so the boundary where floor and derived bound meet is off by one +analyze_stats analyze_stats a late column's wide decode prefix costs it off the index (#363) 15;16;17;18;19 never - +analyze_stats analyze_stats a malformed insert time yields the floor rather than an arithmetic error 15;16;17;18;19 2026-09-24 the cap loses its absolute floor, so the bound shrinks with the machine it runs on;the floor moved by one, so the boundary where floor and derived bound meet is off by one;the input guard removed, so a partially numeric insert time raises an arithmetic error and the cap prints nothing +analyze_stats analyze_stats a missing or zero insert time still yields the floor, not zero 15;16;17;18;19 2026-09-24 the cap loses its absolute floor, so the bound shrinks with the machine it runs on;the floor moved by one, so the boundary where floor and derived bound meet is off by one +analyze_stats analyze_stats a point lookup on an indexed column still uses the index after ANALYZE 15;16;17;18;19 never - +analyze_stats analyze_stats a selective equality is estimated from the data, not the 0.5% default 15;16;17;18;19 never - +analyze_stats analyze_stats a small LIMIT still reaches the index through the fetch penalty (#376) 15;16;17;18;19 never - +analyze_stats analyze_stats a vacuumed columnar table can reach an index-only scan (#507) 15;16;17;18;19 never - +analyze_stats analyze_stats an early column's short decode prefix leaves it on the index (#363) 15;16;17;18;19 never - +analyze_stats analyze_stats and a slow one gets a budget proportional to its own insert 15;16;17;18;19 2026-09-24 the cap stops scaling with the run, so a slow machine gets the same budget as a fast one +analyze_stats analyze_stats and one millisecond past it the derived bound takes over 15;16;17;18;19 2026-09-24 the cap stops scaling with the run, so a slow machine gets the same budget as a fast one +analyze_stats analyze_stats correlation on an ascending column is near 1 15;16;17;18;19 never - +analyze_stats analyze_stats growth without vacuum does not inflate the all-visible saving (#507) 15;16;17;18;19 never - +analyze_stats analyze_stats having an index available saves the point lookup real work 15;16;17;18;19 never - +analyze_stats analyze_stats most_common_vals holds the same set as heap 15;16;17;18;19 never - +analyze_stats analyze_stats n_distinct on a clustered column is within 10% of the truth 15;16;17;18;19 never - +analyze_stats analyze_stats n_distinct on nullable matches heap 15;16;17;18;19 never - +analyze_stats analyze_stats n_distinct on status matches heap 15;16;17;18;19 never - +analyze_stats analyze_stats n_distinct on v matches heap 15;16;17;18;19 never - +analyze_stats analyze_stats no row is offered to the sampler twice 15;16;17;18;19 never - +analyze_stats analyze_stats null_frac matches heap within 0.02 15;16;17;18;19 never - +analyze_stats analyze_stats premise: VACUUM recorded all-visible pages to price with (#507) 15;16;17;18;19 never - +analyze_stats analyze_stats premise: both estimates were taken (#507) 15;16;17;18;19 never - +analyze_stats analyze_stats premise: the cap is exposed as a function, not written inline 15;16;17;18;19 never - +analyze_stats analyze_stats premise: the selective range has its rows (#507) 15;16;17;18;19 never - +analyze_stats analyze_stats reltuples is within 2% of the true row count 15;16;17;18;19 never - +analyze_stats analyze_stats the all-visible fraction does not hand every query to the index (#507) 15;16;17;18;19 never - +analyze_stats analyze_stats the bound does not disable the penalty for a full ordered read (#376) 15;16;17;18;19 never - +analyze_stats analyze_stats the fetch penalty leaves a clustered ORDER BY on its index (#355 must not over-fire) 15;16;17;18;19 never - +analyze_stats analyze_stats the fetch penalty leaves a selective point lookup on the index (#355 vs #171) 15;16;17;18;19 never - +analyze_stats analyze_stats the fetch penalty makes an unclustered ORDER BY sort rather than fetch per row (#355) 15;16;17;18;19 never - +analyze_stats analyze_stats the floor and the derived bound meet where they should 15;16;17;18;19 2026-09-24 the floor moved by one, so the boundary where floor and derived bound meet is off by one +analyze_stats analyze_stats the join plans as a join rather than degenerating 15;16;17;18;19 never - +analyze_stats analyze_stats the penalty is applied before the columnar path is offered, so it can still win (#362) 15;16;17;18;19 never - +analyze_stats analyze_stats the sampled tuples carry a valid item pointer 15;16;17;18;19 never - +analyze_stats analyze_stats the server survived ANALYZE 15;16;17;18;19 never - +analyze_stats analyze_stats without the fetch penalty an unclustered ORDER BY takes the index (#355 premise) 15;16;17;18;19 never - +analyze_stats analyze_stats without the penalty a selective scattered condition takes the index (#362 premise) 15;16;17;18;19 never - base_scan_io base_scan_io a base scan is not priced from sibling projection pages 15;16;17;18;19 2026-09-21 projPages = 0 (keep whole-file pages) base_scan_io base_scan_io premise: a covering projection exists 15;16;17;18;19 never - base_scan_io base_scan_io premise: adding the projection enlarged the relation file 15;16;17;18;19 never - @@ -1438,8 +1478,8 @@ harness_selftest 580-a-hand-rebuild-must-record a log that is not there also pro harness_selftest 580-a-hand-rebuild-must-record a log with content produces a diagnosis to print 15;16;17;18;19 2026-09-24 rebuild.sh forced to fail after its stamp AND _hr_diagnose gutted, so the failure prints no reason harness_selftest 580-a-hand-rebuild-must-record a rebuild that failed skips them rather than reading a stamp it did not write 15;16;17;18;19 2026-09-24 driven alone, with no forced rebuild failure, because these two arms call the gate with literals and the rebuild's status never reaches them;the gate reverted so a failed rebuild still runs the arms beneath it harness_selftest 580-a-hand-rebuild-must-record a rebuild that succeeded runs the arms that read its stamp 15;16;17;18;19 2026-09-24 the gate always skips, so a successful rebuild runs none of the arms that read its stamp -harness_selftest 580-a-hand-rebuild-must-record and any other status skips too, rather than being read as success 15;16;17;18;19 2026-09-24 driven alone, with no forced rebuild failure, because these two arms call the gate with literals and the rebuild's status never reaches them;the gate reverted so a failed rebuild still runs the arms beneath it harness_selftest 580-a-hand-rebuild-must-record an empty log still produces a diagnosis, because silence is the bug 15;16;17;18;19 2026-09-24 _hr_diagnose restored to its silent `[ -s ] || return 0` form, so an empty or missing rebuild.log prints nothing at all +harness_selftest 580-a-hand-rebuild-must-record and any other status skips too, rather than being read as success 15;16;17;18;19 2026-09-24 driven alone, with no forced rebuild failure, because these two arms call the gate with literals and the rebuild's status never reaches them;the gate reverted so a failed rebuild still runs the arms beneath it harness_selftest 580-a-hand-rebuild-must-record and it distinguishes missing from empty, so the two causes do not merge 15;16;17;18;19 2026-09-24 _hr_diagnose restored to its silent `[ -s ] || return 0` form, so an empty or missing rebuild.log prints nothing at all harness_selftest 580-a-hand-rebuild-must-record and it names the log as empty rather than printing a bare banner 15;16;17;18;19 2026-09-24 _hr_diagnose restored to its silent `[ -s ] || return 0` form, so an empty or missing rebuild.log prints nothing at all harness_selftest 580-a-hand-rebuild-must-record and it reads a different source as stale rather than fresh 15;16;17;18;19 2026-09-23 the record call removed from rebuild.sh, so no stamp is written at all diff --git a/test/check_ledger_budget.txt b/test/check_ledger_budget.txt index f2e677f8..9534ebef 100644 --- a/test/check_ledger_budget.txt +++ b/test/check_ledger_budget.txt @@ -15,7 +15,7 @@ # # Adding a check to a suite that is already covered does not move it, which is # what makes it safe to bound. -suites_not_covered 249 +suites_not_covered 248 # # checks_never_observed_red -- A CENSUS. NOT a ceiling, and it must not become # one. @@ -1050,4 +1050,47 @@ suites_not_covered 249 # The name the unguarded sweep invents for the second is `a quoted arm that only # exists in prose` -- an arm that exists nowhere, which is worse than a # mis-attributed real one. Only the mutation found this; the suite was green. -checks_never_observed_red 1540 + +# #1252: 1540 -> 1574, AND suites_not_covered 249 -> 248. THE SUITE ITSELF +# ARRIVES IN THE LEDGER, which is most of this diff and needs saying plainly. +# +# `analyze_stats` had ZERO rows on main. Recording that the new arms redden +# means merging a RUN of the suite they live in, and the tool refuses to +# attribute a mutation across partial or multiple runs -- so registering all 40 +# of its checks is the mechanism, not scope added on top. Decomposed: +# +# ledger rows 1700 + 40 = 1740 +# never 1540 + 34 = 1574 32 pre-existing arms + 2 of the new 8 +# dated 160 + 6 = 166 the 6 arms four mutations redden +# 1574 + 166 == 1740 +# +# suites_not_covered falls by exactly one, which is the direction that ceiling +# is allowed to move. 20 suites covered before, 21 now. +# +# FOUR MUTATIONS, AND A AND B ARE DISJOINT. That is worth stating because the +# last two changes I made had mutations that were not: +# +# A the floor removed 3 arms x 5 majors +# B the scaling removed 2 arms x 5 majors disjoint from A +# C the input guard removed 1 arm x 5 majors isolates what A also hits +# D the floor moved by one 4 arms x 5 majors the only one reaching the tie +# +# C REDDENED NOTHING ON ITS FIRST RUN and the guard was uncovered, not redundant. +# 0, "", "abc" and a negative all reach the floor anyway because `$(( ))` reads +# them as 0. The input it actually defends is a PARTIALLY numeric token: +# +# pgc_analyze_cap_ms 12abc with the guard 5000 +# without it arithmetic error, no output +# +# So an arm was added to cover it rather than the guard deleted -- #1236's +# taxonomy, and the measurement is what chose between the two readings. +# +# TWO OF THE EIGHT NEW ARMS ARRIVE `never` AND CANNOT HONESTLY BE MUTATED HERE. +# `premise: the cap is exposed as a function` is a `type -t` check, and every +# mutation replaces a body while keeping the name. And `ANALYZE on a wide table +# completes well inside its derived cap` has a removal proof rather than a +# mutation: against f82bdcd's parent the unfixed build did not complete in 180 s +# -- an unbounded run was killed at 10m52s of 99.9% CPU -- against 206 ms fixed. +# That is a different tree, so it is not expressible as a same-tree mutation and +# the row stays `never` rather than being dated on evidence of another kind. +checks_never_observed_red 1574