Progress reporting framework, v6: measurements ============================================== Base: master a054b77e40d. v5 is the version posted on 06-10, applied on the same base. Builds: meson, debugoptimized, cassert, with and without -DPROGRESS_DEBUG. The whole meson test suite passes in all three modes (without the option, with it, and with trace_progress on in every node). 1. Where the trace is written Server log bytes written by the whole meson test suite (check-world-afuera.sh, 04-11; master measured on 02-11, same base): master, no PROGRESS_DEBUG 70.22 MB v6, no PROGRESS_DEBUG 70.33 MB, 0 progress lines v5, PROGRESS_DEBUG 1762.1 MB (trace always on) v6, PROGRESS_DEBUG, trace_progress off 135.47 MB of which test_progress's own trace 65.15 MB everything else 70.32 MB, 0 progress lines v6, PROGRESS_DEBUG, trace_progress on in every node (PG_TEST_INITDB_EXTRA_OPTS) 1800.4 MB regress alone: master 3.11 MB; v5 with PROGRESS_DEBUG 183.1 MB; v6 with PROGRESS_DEBUG 3.10 MB. (Run to run, master's own log varies by a few hundred bytes.) v5's 002_doc_phases built an index on 200,000 rows before the test proper; with the index built first and 2,000 rows it writes 25 kB of trace and reports the same phases per command. 2. Without PROGRESS_DEBUG Object code of master and of v6, object by object: 1397 objects, 0 with a different instruction stream; 2 differ in operands only, the source line numbers in elog calls of backend_progress.c and backend_status.c. test_progress then runs one check (the description of progress.h) and skips the rest. Wall-clock of the whole meson test suite (tiempos-afuera.sh, 04-11; builds without assertions, 8 cores, 5 rounds, the three trees in a rotating order in each round after one untimed run each, every run on a settled disk; lane and disk checked clean before and after): median of the 5 rounds master 84.2 s v6 84.9 s v6 + option 92.0 s paired difference with master, same round, median and bootstrap 95% CI: v6 +0.69 s [-2.53, +1.01] no measurable difference v6 + option +7.34 s [+5.76, +8.28] All 15 runs took 83.7-96.4 s; the slowest run of each tree came in the same round (round 5: 89.1, 90.0 and 96.4 s). The option's 7 s are test_progress's scenarios, which run only when it is compiled in. test_progress alone, 10 runs each: v6 0.36 s [0.34, 0.38]; v6 + option 10.43 s [10.31, 10.62]. 3. Progress fixes committed in 2026, reverted one at a time 99ea4a55270 CIC validation scan, last block v5 no v6 yes 3be29d9346d three blips, heap and GIN v5 yes v6 yes 0765b48874a REPACK (CONCURRENTLY) rebuilds v5 yes v6 yes 4b445479f9e TOAST index build, rebuild count v5 yes v6 yes e9810253f09 data checksums NULLs, blocks_done v5 (*) v6 yes 4dd037286e0 REPACK by sort, index_relid v5 no v6 yes cedd2cec7d5 incremental backup estimate v5 no v6 yes 422e54e3092 table sync COPY not ended v5 no v6 yes 55f0a13e96b failed base backup not cleared v5 no v6 yes 92a734bf5c7 parallel autovacuum delay timing v5 no v6 no (*) only the blocks_done part. The checks that catch the last five were written knowing these fixes, from two rules rather than from the bugs: every parameter of every command is checked by value or listed with the reason, and a command has ended when its process reports itself idle. The check of 99ea4a55270 is new since v5. 92a734bf5c7 changes code that runs only when track_cost_delay_timing is changed while a parallel autovacuum runs. Without 99ea4a55270, two tests of 284 fail, both counting the blocks of CREATE INDEX CONCURRENTLY. 4. Bugs nobody chose: mutation of every progress call The fixes above are bugs I knew. To measure the rest, every call that reports progress in src/backend and contrib (187 calls) was mutated blindly: the call deleted, its value +1 or 0, its parameter swapped with the next one, a multi-parameter update one parameter short: 572 mutants, all of which compile. The protocol, the mutants and a random sample of 150 (seed 20261103) were fixed and hashed before the first run. A reserve of 301 more, by other operators (the value -1, the parameter index ^ 2, the first parameter of a multi-update dropped, the call made twice, relid 0), was hashed before any check was changed and not looked at until the end. Round 1 judged the test as it was on 2026-11-02; the checks added since were written against the 572 alone. Round 2 judged v6 as posted, sealed before it ran. Same judge: an assert build, each mutant compiled and the whole test_progress suite run. round 1 round 2 (v6) the sample of 150 84 56.0% 144 96.0% (CI 91.5-98.2) all 572 342 59.8% 548 95.8% (CI 93.8-97.2) the reserve, 301, held out 194 64.5% 285 94.7% (CI 91.5-96.7) (95% Wilson intervals.) The reserve is the number that says whether the checks hold on bugs they were not written against: it is caught at the same rate as the 572. PostgreSQL's tests today (all of meson test but test_progress) catch 10 of the 150 (6.7%, CI 3.7-11.8%), all also caught by test_progress. One of the 10 is an infrastructure failure: m0183 (a subphase reported as 0) failed 216 TAP suites in 73 s, and passes them all when judged again. The other 9 are COPY counters (6 through copy.sql, which reads pg_stat_progress_copy, 1 through test_copy_callbacks) and the base backup command (001_stream_rep.pl reads pg_stat_progress_basebackup). Executed is not checked: with gcov, today's tests execute 179 of the 187 calls. No mutant was caught by a crash: each catch is a check naming what is wrong. What survives, listed by id with the reason in nocfbot-mutation-benchmark.txt: of the 572, 24: 15 the trace cannot tell apart (a value the parameter already has, a phase written again later), 9 not deterministic (the delay time, a wait count that depends on other sessions) of the reserve, 16: 9 not deterministic, 3 the trace cannot tell apart, 4 a check could catch (a parameter the view does not show written, backup_total -2 for -1, index_relid not reset between partitions, failsafe after an index pass). These are left as they are: a check written now would be written knowing them. 5. Each rule, broken on purpose in the backend One mutant per rule; each makes 001 fail with the rule, the parameter, the values and the log line, e.g. # decrease: PROGRESS_VACUUM_HEAP_BLKS_SCANNED decreased from 52 to 0 decrease reset bound phase foreign nested continuity -> 9 of 9 completeness (new macro) coverage (new, unchecked) -> caught idle: the reverts of 422e54e3092 and 55f0a13e96b above 6. Other checks test_progress --repeat 100 200 of 200 passed clang 23 -Werror, both modes builds; test_progress passes headerscheck, cpluspluscheck same messages as master progress reported inside START_CRIT_SECTION(), cassert, trace on: logged, backend fine initdb / single-user, trace on nothing logged (1035 lines for the same statements under postmaster) not run: Windows, 32-bit