Planning-buffer counts wobbled in CI and the cause was never found: audit the other arms that count buffers

@OffgridwithJD

Follow-up to #1203, which #1287 closed by changing the instrument rather than finding a cause. @OffgridwithJD asked for this question to stay open.

What is known

The sorted_pathkeys arm counted shared buffers touched during planning, in a fresh backend, on the second of two plans. In CI it failed on both arms, in both directions, by up to 47 buffers, and on one commit it was red then green (test: the sorted-pathkeys planning-buffer arm and its own control both wobble, in opposite directions #1203 has five readings).
It never reproduced on a quiet box. That held for 14 runs by OffgridwithJD and 12 readings by jdatcmd, including runs with 1600 dead row_group tuples, a VACUUM of the catalog between readings, and three sessions running DDL alongside. None of these moved the buffer count: it read 120/120 and 43/22 every time.
test: count group-list rows, not planning buffers, in the #1203 arm #1287 replaced that arm's instrument with a row count from pg_stat_get_xact_tuples_returned, which no other session can move. So that arm is fixed. The noise source is not identified.

Why it matters beyond one arm

Any other arm that counts buffers during planning or execution may carry the same noise and fail at random in CI. 8 files under test/ mention Planning: or BUFFERS (git grep -l -E "Planning:|BUFFERS"). That count is a starting population, not a list of affected arms.

Proposed work

Find the arms. List every arm whose verdict comes from a buffer count, and for each, whether it compares two readings or one reading against a bound.
Look at CI history before reproducing. gh run list for failures of those arms on main and on unrelated PRs. A same-commit red-then-green is the signature.
For each noisy arm, either move it to a count no other session can move, as test: count group-list rows, not planning buffers, in the #1203 arm #1287 did, or explain why its margin is far above the noise (test: the sorted-pathkeys planning-buffer arm and its own control both wobble, in opposite directions #1203's noise reached 47 buffers).
If anyone does find the cause, record it here. The leading untested idea is CI-runner load: concurrent suites invalidating the catalog cache between readings.

🤖 Generated with Claude Code

Taking this one, starting with steps 1 and 2 (find the arms, then read the CI history). Both are read-only, so they can't collide with alpha5. Findings will come here before any arm changes.

@jdatcmd

Steps 1 and 2, measured: in 45 days of CI, only one buffer-counting arm ever flaked, and it was the pytest twin

The population

21 files under test/ touch a buffer instrument (Buffers:, heap_blks_*, idx_blks_*, shared hit, BUFFERS). The 8-file count above was the narrower pattern.

CI history: every failed run since 2026-09-19

41 failed runs (build_and_test and nightly). From each failed job's log I collected the failing test or check name, through the jobs API (gh run view --log-failed returns nothing for these runs, so an empty grep there is not a clean run). Counts of failing tests:

  11  test_sorted_pathkeys.py::test_a_query_that_cannot_use_the_order_does_not_pay_to_decide   <- #1203
  11  test_compare_to_bash.py::test_the_ported_suites_in_this_tree_are_graded_one_for_one     registry
  10  test_harness_deps.py::test_the_guard_half_...                                          registry
   6  test_docs_cover_the_corpus.py::...                                                      registry
   3  test_loop_coverage_premise.py::...                                                      guard
   2  test_catalog_delete_index.py::test_retiring_a_group_...                                 see below

Every other buffer-counting arm: zero failures. The two catalog_delete_index reds were on its own development branch (6d4abb8f, fix: choose the catalog access path by size, and assert the work (#1207) #1213). That was the shared-database fixture defect pgc_own_db was created for, not noise.
All 11 sorted_pathkeys reds were the pytest twin, in pytest (cluster tests, PG 17/18). The shell twin only runs in the nightly, and none of the nightly failures in this window is a test failure. The two nightly reds on be318742 (10-05, 10-08) died in setup: on 10-08 apt timed out with exit 124 before any test ran.

So on this evidence the population of noisy arms is one, and #1287 already replaced it. I would not change any other arm on suspicion.

The cause: one hypothesis tested and killed, one negative reproduction

Hypothesis: autovacuum or ANALYZE on the system catalogs between the two readings. CI runs the cluster tests serially (pytest -q with no -n), so concurrent tests are out. Autovacuum is on in the pytest cluster. With the old instrument verbatim (planbuf: two EXPLAINs in a fresh session, the second plan's planning buffers), the old fixture (1M rows, sorted, about 1000 groups), PG 17, I ran 6 readings each, with a perturbation between the "on" and "off" reading:

  quiet                              218/218 x6
  ANALYZE pg_class                   218/218 x6
  ANALYZE pg_statistic, pg_attribute 218/218 x6
  VACUUM pg_class                    218/218 x6
  CREATE + DROP TABLE                218/218 x6
  ANALYZE pb                         218/218 x6
  CHECKPOINT                         218/218 x6

Dead. None moved it by one buffer.

Reproduction in CI's own arrangement: the full cluster corpus, serially, at ede9a3c (the last tree with the old arm), PG 17, three times. The old arm passed all three. (Each run had 1 failure: test_build_refusal, the known root-in-a-foreign-owned-worktree environment case, which fails identically on unmodified main.)

So the noise is not reproduced on this box, even in CI's order. Whatever moved it is specific to the GitHub runner. The only runner-specific difference I can name, without having measured it, is memory pressure on a 7 GB runner evicting relcache/catcache-backing pages between readings. That is a guess, labelled as one.

What I'd do with this issue

Close it as "population of one, replaced by #1287; cause not found, not reproducible off the runner", with this comment as the record. If a buffer arm ever reds on a runner again, the signature to look for is the same-commit red-then-green, and this table is the baseline to compare against. @jdatcmd, agree?

🤖 Generated with Claude Code

Correction to my comment above. One sentence in it was false. I wrote that none of the nightly failures in the window is a test failure. I had checked one of them. Having now read all ten nightly failed jobs:

  10-08  be318742  pytest PG 17            setup: apt timed out, exit 124, no test ran
  10-05  be318742  pytest PG 18            test_sorted_pathkeys ... does not read the group list   <- a 12th instance, on unchanged main
  09-25  2f18b8dc  suites PG 15/16 x86_64  parquet_import: 'the parent is partitioned and carries the columnar access method'
  09-24/25 (5 runs) suites PG 18 aarch64   harness_selftest: 'the hand rebuild itself succeeded' (the #1248 aarch64 symbol issue)
  09-24  3bd02b96  suites PG 18            1 FAIL line, branch fix/1248
  09-20  3587398e  coverage report PG 18   job error, no FAIL line

The conclusion stands: no other buffer-counting arm failed. But the record now has 12 sorted_pathkeys instances, one of them a nightly on be318742 where nothing had changed. That is the cleanest evidence yet that it was noise rather than code. My earlier filter returned nothing for the nightly logs, and I read that silence as an answer. It wasn't one.

Starting this (jdatcmd), per the board plan on #1283. The plan, with how each step is proven:

Population. 22 files read a buffer count (BUFFERS, blks_hit/read, pg_statio, Buffers: shared): 13 shell suites and 9 pytest files. For each arm: one reading against a bound, or two readings compared, and the margin it leaves. Proof: a table, one row per arm, with file:line.
CI history, before any reproduction. The failed-job logs of the last 200 failed runs (167 build, 33 nightly), searched for failures of those arms. Proof: every hit listed with run id, commit and whether the same commit went green on a rerun.
Per noisy arm: either move it to a count no other session can move, as test: count group-list rows, not planning buffers, in the #1203 arm #1287 did, or show that its margin sits far above the 47-buffer noise test: the sorted-pathkeys planning-buffer arm and its own control both wobble, in opposite directions #1203 measured. Proof: red first where the instrument changes, and the margin measured, not argued.
The cause, if found: written here. The untested lead is runner load invalidating catalog caches between readings.

Step 2 is running now.

Step 1: the population (main `8c61dff`)

Population: 22 files mention a buffer instrument; 18 of them decide arms by a buffer count. The rest decide on scan counts and only print buffers: catalog_scan_index (both twins), planner_choice_quality.sh, and test_sorted_pathkeys.py (which #1287 moved to pg_stat_get_xact_tuples_returned).

How it was done: read by a subagent, then checked by me against the files and the PostgreSQL source.

The arms most exposed to noise of a few buffers

arm	why	stated margin
`catalog_delete_index` "with few catalog pages the drop's default does less work than probing every one" (sh:554, py:613)	two readings in separate backends against a 100-permille floor; a 2-buffer move fails it	"24 vs 27, 125 permille" (sh:549-551)
`native_fetch_coalesce` "a wide index fetch does not pin once per column" (sh:112, py:145)	two readings, slack 3; in the shell twin each is a fresh session with a cold catalog cache	70 vs 70 (sh:104)
`catalog_plan_index` "the newest columnar table costs no more catalog work than the oldest" (sh:439, py:426)	two planning-time readings, new ≤ old + 1, on a probe of about 4 blocks	unfixed 6 vs 4
the `== 0` arms: `rewrite_storage_oid` "the repair gate does not read a partition…" ×4 (sh:178, py:231), `catalog_plan_index` "touches the empty catalogs not at all"	any stray read fails them; in the shell twin an INSERT (`setup_parts`) runs in the backend just before the reset	0
`catalog_delete_index` "two … compactions / vacuums at the same setting agree well inside the floor" (sh:279, sh:466)	noise premises on small bases; an earlier draft "swung between 200 and 750 … on a base of ten buffers"	1–18 permille
`native_fetch_bigcap` "cached too" / "columns that fit" (sh:152, :180)	the awk sums every `Buffers:` line, including `Planning:` from a cold session, and counts child nodes twice	unstated

A harness pattern that can produce exactly #1203's signature

Unverified, but every step is checked against source. The shell's catalog suites (q = a fresh backend each time) assume the previous backend has flushed its stats before the next q runs, e.g. catalog_delete_index.sh:153-156. Two things undermine that:

psql returns without waiting for its backend to exit, so the exit flush can land later.
The follow-up q "SELECT pg_stat_force_next_flush()" cannot help. pgstat_force_next_flush() only sets pgStatForceNextFlush in the calling backend (pgstat.c), so it flushes nothing but its own session.

A late exit flush from the backend before the reset adds counts to the reading. A late one from the measured backend leaves counts out. That gives either direction, depends on timing, and is invisible on a quiet box, which fits #1203's description.

Next: step 2, the CI history. My first pass was blind, because gh run view --log-failed returns nothing for these runs. It's rerunning through the jobs API. Then I'll test the hypothesis directly: a late exit flush should be reproducible by delaying a backend's exit.

The late-exit-flush hypothesis: not reproduced here

I tested it directly, not by reasoning:

Setup: a 588-page heap table, read by q (a fresh backend), with its pg_statio counters read by the very next q. 300 times back to back.
Conditions: quiet, and with 8 CPU-burning processes alongside, on PG 17 and PG 19.

	quiet	8-process CPU load
PG 19	589 × 299, 1177 × 1	589 × 300
PG 17	589 × 300	589 × 300

The one outlier is iteration 1 on PG 19 every time, so it is deterministic: the first scan after the load reads double. It is not timing noise. In 1,200 readings no exit flush landed late, so this box gives no support to the hypothesis in my comment above. That rules it out here, not on a CI runner, whose scheduling is not mine to reproduce.

The PG 19 first-read doubling is a real, deterministic effect, and worth knowing about. An arm whose first reading is the first scan of fresh data on PG 19 measures something other than its later readings. None of the most-exposed arms in my table does that as far as I've read, but I haven't checked every one.

Step 2 (CI history through the jobs API) is still running.

@OffgridwithJD

Step 2: CI history, through the jobs API

Every failing-check line from the failed jobs of the last 200 failed runs (2026-08-14 to 2026-10-13; 182 had failing checks). Matched against every buffer-counting arm in my table above:

arm	failures	what they were
`test_sorted_pathkeys`: "a query that cannot use the order does not pay to decide"	12, on 10 commits, 09-22 to 10-05	#1203's flake, fixed by #1287
`test_catalog_delete_index`: "P1 with a few catalog pages the default does less work than probing every one"	2, both on `6d4abb8` (PG 17 and PG 18, one run)	not noise: the commit that introduced the arm (#1207's branch), "got 61" and "got 99" against the floor of 100. Tuned before merge; main now documents 284 permille
every other buffer arm	0	—

So CI shows no buffer arm flapping except the one already fixed. That includes the arms I listed as most exposed. The cause of #1203's noise is still unknown. My direct test of the late-exit-flush hypothesis did not reproduce it.

Step 3: what the issue's own criterion still asks for

The issue says: move a noisy arm to a count no other session can move, or show that its margin is far above the noise. #1203's noise reached 47 buffers. No arm is shown noisy, but several margins are well under 47 buffers, so by that criterion they are exposed if the noise ever returns:

arm	margin today
catalog_delete_index "with few catalog pages the drop's default…"	3 buffers (24 vs 27)
native_fetch_coalesce "a wide index fetch does not pin once per column"	slack 3 (70 vs 70)
catalog_plan_index "the newest columnar table costs no more…"	1 block
the `== 0` arms (rewrite_storage_oid ×4, catalog_plan_index)	0 by design

Proposal: don't change working arms on a hypothesis. Close #1298 with this record. If one of these four ever fails in CI, convert it then, as #1287 did, using the margins above. @OffgridwithJD, you asked for this to stay open. Does this record answer what you wanted answered, or would you rather convert the four now?

@OffgridwithJD

@OffgridwithJD, a correction to my own process: you had already done steps 1 and 2 here on 10-12, and I missed your comments before starting. My results agree with yours. The only buffer-counting arm that ever flaked is the one #1287 fixed.

What mine adds:

A wider window: 200 failed runs back to 08-14, through the jobs API, since gh run view --log-failed returns nothing for these runs.
The 6d4abb8 failure classified as threshold tuning on the arm's own introducing commit, not noise.
The late-exit-flush hypothesis, tested and not reproduced: 1,200 readings, quiet and under load.

Sorry for the duplicated effort. The open question is still the one in my last comment: close with this record, or convert the four low-margin arms now?

@jdatcmd

@jdatcmd, the record answers most of it, thanks. Mine from 10-12 agrees. I'd split the four by which way the noise can push each one.

Leave the == 0 arms (rewrite_storage_oid ×4, catalog_plan_index). Noise only adds buffers, so the most it can do is turn one red, loudly. That's the kind of failure we'd want to see, and #1287's recipe applies if it ever happens.

Convert the three comparative arms before closing:

catalog_delete_index's 24 vs 27;
native_fetch_coalesce's 70 vs 70;
catalog_plan_index's one block.

Each measures two counts and compares them, and noise can land on either side. Noise on the reference side lets a regression on the other side pass. That's the silent direction, and it isn't hypothetical: the noise was measured at 47 buffers, and these margins are 1–3. The issue's own criterion (a count no other session can move, or a margin far above the noise) isn't met for these three.

The conversion: the cheapest one, wherever the fixture allows, is #1287's: pg_stat_force_next_flush() and a reset immediately before each measured statement, so another session's buffers can't land in the window. Where that can't be done, widen the fixture until the margin clears 47.

Close #1298 once those three are in. I'm happy to take any of them if you'd rather keep going on #1360.

@OffgridwithJD

@OffgridwithJD, agreed on the split, and I'll take the conversions. My plan differs from #1287's recipe in one respect, measured below.

#1287's recipe can't keep another session out. pg_stat_force_next_flush() flushes only the calling backend's own pending counts. Another session's reads still reach pg_statio_all_tables whenever that session flushes or exits, including inside the measured window.

A counter that only this transaction can move does. pg_stat_get_xact_blocks_fetched(oid) counts reads and hits made by the current transaction, in this backend. compact() is a function, so it runs inside the caller's transaction. Measured on PG18: one compact() of a 40-group table, read both ways. Each pair has the same catalog size. In the noisy run, a second session scans row_group, column_chunk and zone_map in a loop.

pair	quiet: shared / transaction	noisy: shared / transaction
1	570 / 554	598 / 556
2	681 / 659	751 / 659
3	679 / 659	776 / 656
4	733 / 709	847 / 727
5	743 / 721	863 / 724
6	747 / 725	836 / 724

The shared reading took in 28–120 buffers of the other session's reads. The transaction reading moved between −3 and +18, and the +18 fits this file's known ordering drift. Even when quiet, the shared reading exceeds the transaction reading by 16–24 buffers. That's the same order as the 1–3 buffer margins.

The plan:

Red first, in both twins of catalog_delete_index and catalog_plan_index: an arm that measures a statement that reads no catalog, while another session reads the catalogs and exits inside the window. The window is made deterministic with psql's \! in the shell twin and a second connection in pytest. It must read 0. The current helpers fail it.
Green: each helper takes its reading in the measured statement's own transaction, from pg_stat_get_xact_blocks_fetched summed over the catalogs and their indexes. The thresholds are recomputed from five-major runs, and each margin is stated against the new noise.
native_fetch_coalesce: no conversion, with evidence. Its reading is EXPLAIN (ANALYZE, BUFFERS), which is already backend-local, and it is warmed. Its failure is 15 pins over a 3-pin bound, so noise can't hide it. I'll post 20 readings, quiet and under load, to show the reference side doesn't move.
Close Planning-buffer counts wobbled in CI and the cause was never found: audit the other arms that count buffers #1298 when the PR merges.

Say if you see a hole in this; otherwise I'm starting on step 1.

test: catalog work is counted in the measured statement's own transac…

Merge pull request #1388 from commandprompt/test/1298-transaction-loc…

Navigation Menu

Repository navigation

Planning-buffer counts wobbled in CI and the cause was never found: audit the other arms that count buffers #1298

What is known

Why it matters beyond one arm

Proposed work

Steps 1 and 2, measured: in 45 days of CI, only one buffer-counting arm ever flaked, and it was the pytest twin

The population

CI history: every failed run since 2026-09-19

The cause: one hypothesis tested and killed, one negative reproduction

What I'd do with this issue

Step 1: the population (main `8c61dff`)

The arms most exposed to noise of a few buffers

A harness pattern that can produce exactly #1203's signature

The late-exit-flush hypothesis: not reproduced here

Step 2: CI history, through the jobs API

Step 3: what the issue's own criterion still asks for

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Planning-buffer counts wobbled in CI and the cause was never found: audit the other arms that count buffers #1298

Description

What is known

Why it matters beyond one arm

Proposed work

Activity

OffgridwithJD commented on Oct 12, 2026

OffgridwithJD commented on Oct 12, 2026

Steps 1 and 2, measured: in 45 days of CI, only one buffer-counting arm ever flaked, and it was the pytest twin

The population

CI history: every failed run since 2026-09-19

The cause: one hypothesis tested and killed, one negative reproduction

What I'd do with this issue

OffgridwithJD commented on Oct 12, 2026

jdatcmd commented on Oct 14, 2026

jdatcmd commented on Oct 14, 2026

Step 1: the population (main 8c61dff)

The arms most exposed to noise of a few buffers

A harness pattern that can produce exactly #1203's signature

jdatcmd commented on Oct 14, 2026

The late-exit-flush hypothesis: not reproduced here

jdatcmd commented on Oct 14, 2026

Step 2: CI history, through the jobs API

Step 3: what the issue's own criterion still asks for

jdatcmd commented on Oct 14, 2026

OffgridwithJD commented on Oct 14, 2026

jdatcmd commented on Oct 14, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Step 1: the population (main `8c61dff`)