My fault: I sent the new patch on its own, and the CFBot takes only the attachments of the last message, so it tried to apply a patch that adds files under src/test/modules/test_progress/ to a tree that does not have that directory yet. Hence "needs rebase" on the entry.
Here is the whole series, rebased on master (07c73f45063). Nothing changed in 0001-0005; 0006 is the documentation cross-check I posted an hour ago. Rebasing it did turn up something worth mentioning, since it is the sort of thing this series exists to catch. With only the last three patches applied on current master, the trace checker fails: CREATE INDEX 1 violation parallel GIN build 1 CREATE INDEX CONCURRENTLY 1 REPACK 5 REPACK (CONCURRENTLY) 3 all of them resets that do not reset: PROGRESS_SCAN_BLOCKS_DONE went from 14 to 1, not to 0 PROGRESS_CREATEIDX_TUPLES_DONE went from 800 to 1, not to 0 Those are the two index-build bugs that 0001 and 0002 fix, so this is not a regression, it is the checker doing its job on a tree that is missing the fixes. I am noting it because it is a decent demonstration of what the series buys: drop two fixes from a five-patch series and the test tells you exactly which counters stopped being reset, with the log line that proves it. With the six applied: make check passes, and test_progress passes while still reporting the one thing it is meant to report, the REPACK phase table listing "catch-up" before "rebuilding index" when execution does the opposite. Regards, Manu
>From faa12649bede9f5a3a76d41588ad0408c52c2646 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v2 1/6] Fix blocks_done of an index build's heap scan on its first block heapam_scan_get_blocks_done() computes how many blocks a scan has done from the block it is on and the block it started at, allowing for a synchronized scan that wrapped around the end of the relation. When the current block is the start block, which only happens on the first block, it took the wrap-around branch and returned the number of blocks in the relation. So CREATE INDEX reported blocks_done = blocks_total as soon as the scan started, and then went back to 1 on the next block. Found with the PROGRESS_DEBUG tracing proposed in the same thread. Oversight in ab0dfc961b6. --- src/backend/access/heap/heapam_handler.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/backend/access/heap/heapam_handler.c b/src/backend/access/heap/heapam_handler.c index 6adb760b54f..499e426479c 100644 --- a/src/backend/access/heap/heapam_handler.c +++ b/src/backend/access/heap/heapam_handler.c @@ -1965,9 +1965,10 @@ heapam_scan_get_blocks_done(HeapScanDesc hscan) /* * Might have wrapped around the end of the relation, if startblock was - * not zero. + * not zero. The scan ends before coming back to startblock, so the + * current block is only startblock at the start, when no block is done. */ - if (hscan->rs_cblock > startblock) + if (hscan->rs_cblock >= startblock) blocks_done = hscan->rs_cblock - startblock; else { -- 2.55.0
>From 126bb729d236dc943379bf37b8ce1f764d736542 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v2 2/6] Reset the index build progress counters for every index build Index AMs report their subphase, tuple counts and scan block counts whether or not index_build() was asked to report progress, but index_build() only reset those counters when it was. When one command builds several indexes without progress for each of them, as REPACK and VACUUM FULL do when rebuilding a table's indexes, or CREATE INDEX does for the partitions of a partitioned table, each build started from the counts left by the previous one: tuples_done could be above the new tuples_total until the AM got to its first update. Reset those counters in every build. They are the parameters whose numbers were chosen not to collide with those of the commands that build indexes, so writing them under another command is fine. The phase is still only set when progress is reported, since REPACK uses that number for index_rebuild_count. Found with the PROGRESS_DEBUG tracing proposed in the same thread. Oversight in caec9d9fadf, which made the whole reset conditional. --- src/backend/catalog/index.c | 23 ++++++++++++++++------- 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/src/backend/catalog/index.c b/src/backend/catalog/index.c index 2a46cc4de19..09e716fadd2 100644 --- a/src/backend/catalog/index.c +++ b/src/backend/catalog/index.c @@ -3175,24 +3175,33 @@ index_build(Relation heapRelation, save_nestlevel = NewGUCNestLevel(); RestrictSearchPath(); - /* Set up initial progress report status */ - if (progress) + /* + * Set up initial progress report status. + * + * Index AMs report their subphase, tuple and block counts whether or not + * the caller asked for progress, so reset those in any case: otherwise + * they would start from the values left by an earlier index build of the + * same command. Their parameter numbers are reserved so as not to + * collide with those of the commands that build indexes. The phase is + * only set when progress is reported. + */ { const int progress_index[] = { - PROGRESS_CREATEIDX_PHASE, PROGRESS_CREATEIDX_SUBPHASE, PROGRESS_CREATEIDX_TUPLES_DONE, PROGRESS_CREATEIDX_TUPLES_TOTAL, PROGRESS_SCAN_BLOCKS_DONE, - PROGRESS_SCAN_BLOCKS_TOTAL + PROGRESS_SCAN_BLOCKS_TOTAL, + PROGRESS_CREATEIDX_PHASE }; const int64 progress_vals[] = { - PROGRESS_CREATEIDX_PHASE_BUILD, PROGRESS_CREATEIDX_SUBPHASE_INITIALIZE, - 0, 0, 0, 0 + 0, 0, 0, 0, + PROGRESS_CREATEIDX_PHASE_BUILD }; - pgstat_progress_update_multi_param(6, progress_index, progress_vals); + pgstat_progress_update_multi_param(progress ? 6 : 5, + progress_index, progress_vals); } /* -- 2.55.0
>From b833712c6868ef1fc6591768c304d09216c70add Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v2 3/6] Reset VACUUM's dead item progress counters after each index cycle pg_stat_progress_vacuum documents num_dead_item_ids and dead_tuple_bytes as what was collected since the last index vacuum cycle, but dead_items_reset() emptied the dead item store without reporting it. After each cycle the view kept showing the previous cycle's values until the heap scan found the next page with dead items. Before 667e65aac35 the same happened with num_dead_tuples, which was documented the same way. Found with the PROGRESS_DEBUG tracing proposed in the same thread. --- src/backend/access/heap/vacuumlazy.c | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 8e1f660bc2f..fb0a97b56bc 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -3525,10 +3525,22 @@ dead_items_add(LVRelState *vacrel, BlockNumber blkno, OffsetNumber *offsets, static void dead_items_reset(LVRelState *vacrel) { + const int prog_index[2] = { + PROGRESS_VACUUM_NUM_DEAD_ITEM_IDS, + PROGRESS_VACUUM_DEAD_TUPLE_BYTES + }; + const int64 prog_val[2] = {0, 0}; + /* Update statistics for dead items */ vacrel->num_dead_items_resets++; vacrel->total_dead_items_bytes += TidStoreMemoryUsage(vacrel->dead_items); + /* + * Both progress counters are documented as what was collected since the + * last index vacuum cycle, which is nothing yet. + */ + pgstat_progress_update_multi_param(2, prog_index, prog_val); + if (ParallelVacuumIsActive(vacrel)) { parallel_vacuum_reset_dead_items(vacrel->pvs); -- 2.55.0
>From 50da0288025a3900116fe37bd606140cac3df72e Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:59:40 -0300 Subject: [PATCH v2 4/6] Don't count the last key twice in a parallel GIN build's progress When the leader of a parallel GIN index build merges the workers' sorted tuples, it counts each tuple it reads in tuples_done, which so reaches tuples_total. It then counted once more when it flushed the entries buffered for the last key, which are tuples already counted, so the build ended with tuples_done one above tuples_total. Found with the PROGRESS_DEBUG tracing proposed in the same thread. Oversight in 8492feb98f6. --- src/backend/access/gin/gininsert.c | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/src/backend/access/gin/gininsert.c b/src/backend/access/gin/gininsert.c index aaef7020981..0e5ac87fc9a 100644 --- a/src/backend/access/gin/gininsert.c +++ b/src/backend/access/gin/gininsert.c @@ -1777,7 +1777,10 @@ _gin_parallel_merge(GinBuildState *state) ++numtuples); } - /* flush data remaining in the buffer (for the last key) */ + /* + * Flush data remaining in the buffer (for the last key). Its tuples were + * already counted in the progress report when they were read. + */ if (!GinBufferIsEmpty(buffer)) { AssertCheckItemPointers(buffer); @@ -1788,10 +1791,6 @@ _gin_parallel_merge(GinBuildState *state) /* discard the existing data */ GinBufferReset(buffer); - - /* Report progress */ - pgstat_progress_update_param(PROGRESS_CREATEIDX_TUPLES_DONE, - ++numtuples); } /* release all the memory */ -- 2.55.0
>From c82651b1a2560a69857b4d766a86de5d82c00161 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v2 5/6] Add PROGRESS_DEBUG, to test the whole sequence of progress reports Progress reporting is tested, when it is, by looking at the pg_stat_progress_* views at some point in time, which needs concurrency or injection points and only sees what happens to be there at that moment. With PROGRESS_DEBUG defined, every change to a backend's progress state is logged at LOG_SERVER_ONLY: progress start: VACUUM relid=16384 progress update: VACUUM relid=16384 0:1->2 8:0->2 progress end: VACUUM relid=16384 An update line has only the parameters that changed, as index:old->new, and one pgstat_progress_update_multi_param() call is one line. All the writes go through backend_progress.c, so nothing is missed. The line is built on the stack, as progress is reported inside critical sections. Without PROGRESS_DEBUG the code is compiled out. The new test module test_progress reads those lines back. Its ProgressCheck.pm replays each backend's trace and checks rules that hold for every command: values continue from the last one logged, counters do not decrease or only go back to 0, done counters stay within their totals, phases take defined values, a command only writes its own parameters (or those of an index build, whose numbers are reserved for that), and commands do not start inside other commands. The test then runs COPY, CREATE INDEX [CONCURRENTLY], a parallel GIN build, ANALYZE, VACUUM (with truncation, in several index cycles, and parallel), REPACK (sorting, through an index, and CONCURRENTLY) and base backups, and checks the exact succession of phases, the succession of index_rebuild_count, and final values. ProgressCheck.pm also describes every parameter of commands/progress.h, and the test checks that description against the header on any build, so a new or renumbered parameter has to be described before the test passes. The rest of the test is skipped without PROGRESS_DEBUG. --- src/backend/utils/activity/backend_progress.c | 170 +++++ src/include/pg_config_manual.h | 8 + src/test/modules/Makefile | 1 + src/test/modules/meson.build | 1 + src/test/modules/test_progress/Makefile | 20 + .../modules/test_progress/ProgressCheck.pm | 699 ++++++++++++++++++ src/test/modules/test_progress/meson.build | 17 + .../modules/test_progress/t/001_progress.pl | 411 ++++++++++ 8 files changed, 1327 insertions(+) create mode 100644 src/test/modules/test_progress/Makefile create mode 100644 src/test/modules/test_progress/ProgressCheck.pm create mode 100644 src/test/modules/test_progress/meson.build create mode 100644 src/test/modules/test_progress/t/001_progress.pl diff --git a/src/backend/utils/activity/backend_progress.c b/src/backend/utils/activity/backend_progress.c index dee05b1abb1..93c00ac5d0e 100644 --- a/src/backend/utils/activity/backend_progress.c +++ b/src/backend/utils/activity/backend_progress.c @@ -12,11 +12,99 @@ #include "access/parallel.h" #include "libpq/pqformat.h" +#include "miscadmin.h" #include "storage/proc.h" #include "utils/backend_progress.h" #include "utils/backend_status.h" +#ifdef PROGRESS_DEBUG + +/* + * Room for every parameter as " index:old->new". The log line is built on + * the stack: progress can be reported inside a critical section, where + * palloc is not allowed. + */ +#define PROGRESS_DEBUG_BUFSIZE (PGSTAT_NUM_PROGRESS_PARAM * 48) + +static const char * +progress_debug_command_name(ProgressCommandType cmdtype) +{ + switch (cmdtype) + { + case PROGRESS_COMMAND_INVALID: + return "INVALID"; + case PROGRESS_COMMAND_VACUUM: + return "VACUUM"; + case PROGRESS_COMMAND_ANALYZE: + return "ANALYZE"; + case PROGRESS_COMMAND_CREATE_INDEX: + return "CREATE_INDEX"; + case PROGRESS_COMMAND_BASEBACKUP: + return "BASEBACKUP"; + case PROGRESS_COMMAND_COPY: + return "COPY"; + case PROGRESS_COMMAND_REPACK: + return "REPACK"; + case PROGRESS_COMMAND_DATACHECKSUMS: + return "DATACHECKSUMS"; + } + return "UNKNOWN"; +} + +/* + * Log one change of this backend's progress state. + * + * The format is meant to be parsed by tests (see src/test/modules/ + * test_progress), so keep it stable: + * + * progress start: <command> relid=<oid> + * progress update: <command> relid=<oid> <index>:<old>-><new> ... + * progress end: <command> relid=<oid> + * + * An update line lists only the parameters whose value changed, and one + * pgstat_progress_update_multi_param() call produces one line, since + * readers see those values change together. + * + * This must be called after PGSTAT_END_WRITE_ACTIVITY(), outside the + * critical section that protects the write. + * + * Standalone backends, such as those initdb runs, log to their caller's + * stderr, so nothing is logged there: that output should not change with + * this option. + */ +static void +progress_debug_log(const char *event, ProgressCommandType cmdtype, Oid relid, + const char *changes) +{ + if (!IsUnderPostmaster) + return; + + /* LOG_SERVER_ONLY: never sent to the client, so no test output changes */ + ereport(LOG_SERVER_ONLY, + errmsg_internal("progress %s: %s relid=%u%s", + event, + progress_debug_command_name(cmdtype), + relid, + changes ? changes : ""), + errhidestmt(true), + errhidecontext(true)); +} + +static int +progress_debug_append(char *buf, int len, int index, int64 oldval, int64 newval) +{ + int n; + + n = snprintf(buf + len, PROGRESS_DEBUG_BUFSIZE - len, + " %d:%lld->%lld", index, + (long long) oldval, (long long) newval); + Assert(n > 0 && len + n < PROGRESS_DEBUG_BUFSIZE); + return len + n; +} + +#endif /* PROGRESS_DEBUG */ + /*----------- * pgstat_progress_start_command() - * @@ -37,6 +125,10 @@ pgstat_progress_start_command(ProgressCommandType cmdtype, Oid relid) beentry->st_progress_command_target = relid; MemSet(&beentry->st_progress_param, 0, sizeof(beentry->st_progress_param)); PGSTAT_END_WRITE_ACTIVITY(beentry); + +#ifdef PROGRESS_DEBUG + progress_debug_log("start", cmdtype, relid, NULL); +#endif } /*----------- @@ -49,15 +141,33 @@ void pgstat_progress_update_param(int index, int64 val) { volatile PgBackendStatus *beentry = MyBEEntry; +#ifdef PROGRESS_DEBUG + int64 oldval; +#endif Assert(index >= 0 && index < PGSTAT_NUM_PROGRESS_PARAM); if (!beentry || !pgstat_track_activities) return; +#ifdef PROGRESS_DEBUG + oldval = beentry->st_progress_param[index]; +#endif + PGSTAT_BEGIN_WRITE_ACTIVITY(beentry); beentry->st_progress_param[index] = val; PGSTAT_END_WRITE_ACTIVITY(beentry); + +#ifdef PROGRESS_DEBUG + if (oldval != val) + { + char changes[PROGRESS_DEBUG_BUFSIZE]; + + progress_debug_append(changes, 0, index, oldval, val); + progress_debug_log("update", beentry->st_progress_command, + beentry->st_progress_command_target, changes); + } +#endif } /*----------- @@ -70,15 +180,33 @@ void pgstat_progress_incr_param(int index, int64 incr) { volatile PgBackendStatus *beentry = MyBEEntry; +#ifdef PROGRESS_DEBUG + int64 oldval; +#endif Assert(index >= 0 && index < PGSTAT_NUM_PROGRESS_PARAM); if (!beentry || !pgstat_track_activities) return; +#ifdef PROGRESS_DEBUG + oldval = beentry->st_progress_param[index]; +#endif + PGSTAT_BEGIN_WRITE_ACTIVITY(beentry); beentry->st_progress_param[index] += incr; PGSTAT_END_WRITE_ACTIVITY(beentry); + +#ifdef PROGRESS_DEBUG + if (incr != 0) + { + char changes[PROGRESS_DEBUG_BUFSIZE]; + + progress_debug_append(changes, 0, index, oldval, oldval + incr); + progress_debug_log("update", beentry->st_progress_command, + beentry->st_progress_command_target, changes); + } +#endif } /*----------- @@ -122,10 +250,18 @@ pgstat_progress_update_multi_param(int nparam, const int *index, { volatile PgBackendStatus *beentry = MyBEEntry; int i; +#ifdef PROGRESS_DEBUG + int64 oldval[PGSTAT_NUM_PROGRESS_PARAM]; +#endif if (!beentry || !pgstat_track_activities || nparam == 0) return; +#ifdef PROGRESS_DEBUG + for (i = 0; i < PGSTAT_NUM_PROGRESS_PARAM; ++i) + oldval[i] = beentry->st_progress_param[i]; +#endif + PGSTAT_BEGIN_WRITE_ACTIVITY(beentry); for (i = 0; i < nparam; ++i) @@ -136,6 +272,27 @@ pgstat_progress_update_multi_param(int nparam, const int *index, } PGSTAT_END_WRITE_ACTIVITY(beentry); + +#ifdef PROGRESS_DEBUG + { + char changes[PROGRESS_DEBUG_BUFSIZE]; + int len = 0; + + /* + * Report each changed parameter once, with its final value, in index + * order. An index could appear more than once in the call. + */ + for (i = 0; i < PGSTAT_NUM_PROGRESS_PARAM; ++i) + { + if (beentry->st_progress_param[i] != oldval[i]) + len = progress_debug_append(changes, len, i, oldval[i], + beentry->st_progress_param[i]); + } + if (len > 0) + progress_debug_log("update", beentry->st_progress_command, + beentry->st_progress_command_target, changes); + } +#endif } /*----------- @@ -149,6 +306,10 @@ void pgstat_progress_end_command(void) { volatile PgBackendStatus *beentry = MyBEEntry; +#ifdef PROGRESS_DEBUG + ProgressCommandType cmdtype; + Oid relid; +#endif if (!beentry || !pgstat_track_activities) return; @@ -156,8 +317,17 @@ pgstat_progress_end_command(void) if (beentry->st_progress_command == PROGRESS_COMMAND_INVALID) return; +#ifdef PROGRESS_DEBUG + cmdtype = beentry->st_progress_command; + relid = beentry->st_progress_command_target; +#endif + PGSTAT_BEGIN_WRITE_ACTIVITY(beentry); beentry->st_progress_command = PROGRESS_COMMAND_INVALID; beentry->st_progress_command_target = InvalidOid; PGSTAT_END_WRITE_ACTIVITY(beentry); + +#ifdef PROGRESS_DEBUG + progress_debug_log("end", cmdtype, relid, NULL); +#endif } diff --git a/src/include/pg_config_manual.h b/src/include/pg_config_manual.h index 521b49b8888..fc89e10e8c7 100644 --- a/src/include/pg_config_manual.h +++ b/src/include/pg_config_manual.h @@ -362,6 +362,14 @@ */ /* #define WAL_DEBUG */ +/* + * Log every change to a backend's command progress state (the values shown + * in the pg_stat_progress_* views) at LOG level, so that tests can check the + * whole sequence of values a command reports. See backend_progress.c and + * src/test/modules/test_progress. + */ +/* #define PROGRESS_DEBUG */ + /* * Enable tracing of syncscan operations (see also the trace_syncscan GUC var). */ diff --git a/src/test/modules/Makefile b/src/test/modules/Makefile index 71a2e65ad70..3667f5dc3cb 100644 --- a/src/test/modules/Makefile +++ b/src/test/modules/Makefile @@ -44,6 +44,7 @@ SUBDIRS = \ test_pg_dump \ test_plan_advice \ test_predtest \ + test_progress \ test_radixtree \ test_rbtree \ test_regex \ diff --git a/src/test/modules/meson.build b/src/test/modules/meson.build index 77e1a2810e5..f5b4e78ce80 100644 --- a/src/test/modules/meson.build +++ b/src/test/modules/meson.build @@ -45,6 +45,7 @@ subdir('test_parser') subdir('test_pg_dump') subdir('test_plan_advice') subdir('test_predtest') +subdir('test_progress') subdir('test_radixtree') subdir('test_rbtree') subdir('test_regex') diff --git a/src/test/modules/test_progress/Makefile b/src/test/modules/test_progress/Makefile new file mode 100644 index 00000000000..f5dbca84920 --- /dev/null +++ b/src/test/modules/test_progress/Makefile @@ -0,0 +1,20 @@ +# src/test/modules/test_progress/Makefile + +TAP_TESTS = 1 + +# The test reads the server log, which is cluster-wide. +NO_INSTALLCHECK = 1 + +ifdef USE_PGXS +PG_CONFIG = pg_config +PGXS := $(shell $(PG_CONFIG) --pgxs) +include $(PGXS) +else +subdir = src/test/modules/test_progress +top_builddir = ../../../.. +include $(top_builddir)/src/Makefile.global +include $(top_srcdir)/contrib/contrib-global.mk +endif + +# The test checks its description of the progress parameters against this. +export PROGRESS_H := $(abs_top_srcdir)/src/include/commands/progress.h diff --git a/src/test/modules/test_progress/ProgressCheck.pm b/src/test/modules/test_progress/ProgressCheck.pm new file mode 100644 index 00000000000..d336eb20973 --- /dev/null +++ b/src/test/modules/test_progress/ProgressCheck.pm @@ -0,0 +1,699 @@ + +# Copyright (c) 2026, PostgreSQL Global Development Group + +=pod + +=head1 NAME + +ProgressCheck - parse and check the progress trace of a PROGRESS_DEBUG build + +=head1 SYNOPSIS + + use ProgressCheck; + + my $spec = ProgressCheck::load_spec($progress_h); + my @problems = ProgressCheck::check_spec($spec); + my $trace = ProgressCheck::parse_log($log_contents); + my @violations = ProgressCheck::check_trace($spec, $trace); + +=head1 DESCRIPTION + +A server compiled with PROGRESS_DEBUG logs every change to a backend's +progress state (see backend_progress.c): + + [pid] ... LOG: progress start: VACUUM relid=16384 + [pid] ... LOG: progress update: VACUUM relid=16384 0:1->2 8:0->2 + [pid] ... LOG: progress end: VACUUM relid=16384 + +This module turns such a log into a per-backend sequence of events, and +checks it against a description of what each command's parameters mean. +The description names parameters by their macro in commands/progress.h, +and load_spec() reads their numbers from that file, so that a parameter +that is added, removed or renumbered there is noticed by check_spec(). + +=cut + +package ProgressCheck; + +use strict; +use warnings FATAL => 'all'; + +use Carp; + +# The number of parameters in a backend's progress state; see +# PGSTAT_NUM_PROGRESS_PARAM. +our $NUM_PARAMS = 20; + +# The parameters that index AMs write while they build an index. An index +# build does not know which command it runs under, so these are written +# whatever command is active, or when none is (e.g. the TOAST index built +# by CREATE TABLE). Their numbers were chosen so as not to collide with +# those of CLUSTER, now REPACK, which rebuilds indexes; check_spec() makes +# sure that stays true for every command marked 'hosts_index_build'. +our @INDEX_BUILD_PARAMS = qw( + PROGRESS_CREATEIDX_SUBPHASE + PROGRESS_CREATEIDX_TUPLES_TOTAL + PROGRESS_CREATEIDX_TUPLES_DONE + PROGRESS_SCAN_BLOCKS_TOTAL + PROGRESS_SCAN_BLOCKS_DONE +); + +# What each command's parameters mean. +# +# Kinds: +# phase the command's phase; only values of the <macro>_* macros +# (or 0) are valid +# monotonic a counter that never decreases during the command +# resetting a counter that never decreases, except back to 0 when a new +# round starts (a new phase, index, child table, ...) +# free anything else: totals, OIDs, enum values +# +# A counter may name the parameter that bounds it, [kind, bound]: while the +# bound is positive, the counter must not exceed it. +# +# 'values' lists the prefixes of the macros that are values of the +# command's parameters rather than parameters. +our %COMMANDS = ( + VACUUM => { + params => { + PROGRESS_VACUUM_PHASE => 'phase', + PROGRESS_VACUUM_TOTAL_HEAP_BLKS => 'free', + PROGRESS_VACUUM_HEAP_BLKS_SCANNED => + [ 'monotonic', 'PROGRESS_VACUUM_TOTAL_HEAP_BLKS' ], + PROGRESS_VACUUM_HEAP_BLKS_VACUUMED => + [ 'monotonic', 'PROGRESS_VACUUM_TOTAL_HEAP_BLKS' ], + PROGRESS_VACUUM_NUM_INDEX_VACUUMS => 'monotonic', + PROGRESS_VACUUM_MAX_DEAD_TUPLE_BYTES => 'free', + PROGRESS_VACUUM_DEAD_TUPLE_BYTES => 'resetting', + PROGRESS_VACUUM_NUM_DEAD_ITEM_IDS => 'resetting', + PROGRESS_VACUUM_INDEXES_TOTAL => 'free', + PROGRESS_VACUUM_INDEXES_PROCESSED => + [ 'resetting', 'PROGRESS_VACUUM_INDEXES_TOTAL' ], + PROGRESS_VACUUM_DELAY_TIME => 'monotonic', + PROGRESS_VACUUM_MODE => 'free', + PROGRESS_VACUUM_STARTED_BY => 'free', + }, + values => [ + 'PROGRESS_VACUUM_PHASE_', 'PROGRESS_VACUUM_MODE_', + 'PROGRESS_VACUUM_STARTED_BY_' + ], + }, + ANALYZE => { + params => { + PROGRESS_ANALYZE_PHASE => 'phase', + PROGRESS_ANALYZE_BLOCKS_TOTAL => 'free', + PROGRESS_ANALYZE_BLOCKS_DONE => + [ 'resetting', 'PROGRESS_ANALYZE_BLOCKS_TOTAL' ], + PROGRESS_ANALYZE_EXT_STATS_TOTAL => 'free', + PROGRESS_ANALYZE_EXT_STATS_COMPUTED => + [ 'resetting', 'PROGRESS_ANALYZE_EXT_STATS_TOTAL' ], + PROGRESS_ANALYZE_CHILD_TABLES_TOTAL => 'free', + PROGRESS_ANALYZE_CHILD_TABLES_DONE => + [ 'monotonic', 'PROGRESS_ANALYZE_CHILD_TABLES_TOTAL' ], + PROGRESS_ANALYZE_CURRENT_CHILD_TABLE_RELID => 'free', + PROGRESS_ANALYZE_DELAY_TIME => 'monotonic', + PROGRESS_ANALYZE_STARTED_BY => 'free', + }, + values => + [ 'PROGRESS_ANALYZE_PHASE_', 'PROGRESS_ANALYZE_STARTED_BY_' ], + }, + REPACK => { + params => { + PROGRESS_REPACK_COMMAND => 'free', + PROGRESS_REPACK_PHASE => 'phase', + PROGRESS_REPACK_INDEX_RELID => 'free', + PROGRESS_REPACK_HEAP_TUPLES_SCANNED => 'monotonic', + PROGRESS_REPACK_HEAP_TUPLES_INSERTED => 'monotonic', + PROGRESS_REPACK_HEAP_TUPLES_UPDATED => 'monotonic', + PROGRESS_REPACK_HEAP_TUPLES_DELETED => 'monotonic', + PROGRESS_REPACK_TOTAL_HEAP_BLKS => 'free', + PROGRESS_REPACK_HEAP_BLKS_SCANNED => + [ 'monotonic', 'PROGRESS_REPACK_TOTAL_HEAP_BLKS' ], + PROGRESS_REPACK_INDEX_REBUILD_COUNT => 'monotonic', + }, + values => ['PROGRESS_REPACK_PHASE_'], + hosts_index_build => 1, + }, + CREATE_INDEX => { + params => { + PROGRESS_CREATEIDX_COMMAND => 'free', + PROGRESS_CREATEIDX_INDEX_OID => 'free', + PROGRESS_CREATEIDX_ACCESS_METHOD_OID => 'free', + PROGRESS_CREATEIDX_PHASE => 'phase', + # its values are defined by each index AM + PROGRESS_CREATEIDX_SUBPHASE => 'free', + PROGRESS_CREATEIDX_TUPLES_TOTAL => 'free', + PROGRESS_CREATEIDX_TUPLES_DONE => + [ 'resetting', 'PROGRESS_CREATEIDX_TUPLES_TOTAL' ], + PROGRESS_CREATEIDX_PARTITIONS_TOTAL => 'free', + PROGRESS_CREATEIDX_PARTITIONS_DONE => + [ 'monotonic', 'PROGRESS_CREATEIDX_PARTITIONS_TOTAL' ], + PROGRESS_WAITFOR_TOTAL => 'free', + PROGRESS_WAITFOR_DONE => + [ 'resetting', 'PROGRESS_WAITFOR_TOTAL' ], + PROGRESS_WAITFOR_CURRENT_PID => 'free', + PROGRESS_SCAN_BLOCKS_TOTAL => 'free', + PROGRESS_SCAN_BLOCKS_DONE => + [ 'resetting', 'PROGRESS_SCAN_BLOCKS_TOTAL' ], + }, + values => [ + 'PROGRESS_CREATEIDX_PHASE_', 'PROGRESS_CREATEIDX_SUBPHASE_', + 'PROGRESS_CREATEIDX_COMMAND_' + ], + }, + BASEBACKUP => { + params => { + PROGRESS_BASEBACKUP_PHASE => 'phase', + PROGRESS_BASEBACKUP_BACKUP_TOTAL => 'free', + PROGRESS_BASEBACKUP_BACKUP_STREAMED => + [ 'monotonic', 'PROGRESS_BASEBACKUP_BACKUP_TOTAL' ], + PROGRESS_BASEBACKUP_TBLSPC_TOTAL => 'free', + PROGRESS_BASEBACKUP_TBLSPC_STREAMED => + [ 'monotonic', 'PROGRESS_BASEBACKUP_TBLSPC_TOTAL' ], + PROGRESS_BASEBACKUP_BACKUP_TYPE => 'free', + }, + values => [ + 'PROGRESS_BASEBACKUP_PHASE_', 'PROGRESS_BASEBACKUP_BACKUP_TYPE_' + ], + }, + COPY => { + params => { + PROGRESS_COPY_BYTES_PROCESSED => + [ 'monotonic', 'PROGRESS_COPY_BYTES_TOTAL' ], + PROGRESS_COPY_BYTES_TOTAL => 'free', + PROGRESS_COPY_TUPLES_PROCESSED => 'monotonic', + PROGRESS_COPY_TUPLES_EXCLUDED => 'monotonic', + PROGRESS_COPY_COMMAND => 'free', + PROGRESS_COPY_TYPE => 'free', + PROGRESS_COPY_TUPLES_SKIPPED => 'monotonic', + }, + values => [ 'PROGRESS_COPY_COMMAND_', 'PROGRESS_COPY_TYPE_' ], + }, + DATACHECKSUMS => { + params => { + PROGRESS_DATACHECKSUMS_PHASE => 'phase', + PROGRESS_DATACHECKSUMS_DBS_TOTAL => 'free', + PROGRESS_DATACHECKSUMS_DBS_DONE => + [ 'monotonic', 'PROGRESS_DATACHECKSUMS_DBS_TOTAL' ], + PROGRESS_DATACHECKSUMS_RELS_TOTAL => 'free', + PROGRESS_DATACHECKSUMS_RELS_DONE => + [ 'resetting', 'PROGRESS_DATACHECKSUMS_RELS_TOTAL' ], + PROGRESS_DATACHECKSUMS_BLOCKS_TOTAL => 'free', + PROGRESS_DATACHECKSUMS_BLOCKS_DONE => + [ 'resetting', 'PROGRESS_DATACHECKSUMS_BLOCKS_TOTAL' ], + }, + values => ['PROGRESS_DATACHECKSUMS_PHASE_'], + },); + +=pod + +=head1 FUNCTIONS + +=over + +=item load_spec($progress_h) + +Read the macros of commands/progress.h and resolve %COMMANDS against them. +Returns a hash: 'macros' (name => number) and, per command, 'kind', +'bound' and 'name' indexed by parameter number, and 'phase_values'. + +=cut + +sub load_spec +{ + my ($progress_h) = @_; + my %macros; + + open my $fh, '<', $progress_h or croak "could not open $progress_h: $!"; + while (my $line = <$fh>) + { + $macros{$1} = $2 if $line =~ /^#define\s+(PROGRESS_\w+)\s+(\d+)\b/; + } + close $fh; + + my %spec = (macros => \%macros); + foreach my $cmd (keys %COMMANDS) + { + my %c = (kind => {}, bound => {}, name => {}, phase_values => {}); + + while (my ($macro, $def) = each %{ $COMMANDS{$cmd}{params} }) + { + my ($kind, $bound) = ref $def ? @$def : ($def); + next unless defined $macros{$macro}; # reported by check_spec() + my $n = $macros{$macro}; + $c{kind}{$n} = $kind; + $c{name}{$n} = $macro; + $c{bound}{$n} = $macros{$bound} + if defined $bound && defined $macros{$bound}; + if ($kind eq 'phase') + { + $c{phase_param} = $n; + $c{phase_values}{0} = 1; + $c{phase_values}{ $macros{$_} } = 1 + foreach grep { index($_, "${macro}_") == 0 } keys %macros; + } + } + $spec{$cmd} = \%c; + } + + # Index build parameters: checked as CREATE INDEX's in the commands that + # host an index build, and allowed while no command is active. + my %build; + foreach my $macro (@INDEX_BUILD_PARAMS) + { + next unless defined $macros{$macro}; + my $def = $COMMANDS{CREATE_INDEX}{params}{$macro}; + my ($kind, $bound) = ref $def ? @$def : ($def); + $build{ $macros{$macro} } = [ $macro, $kind, $bound ]; + } + $spec{index_build} = { map { $_ => $build{$_}[0] } keys %build }; + foreach my $cmd (grep { $COMMANDS{$_}{hosts_index_build} } keys %COMMANDS) + { + my $c = $spec{$cmd}; + foreach my $n (keys %build) + { + next if defined $c->{kind}{$n}; # collision, see check_spec() + my ($macro, $kind, $bound) = @{ $build{$n} }; + $c->{kind}{$n} = $kind; + $c->{name}{$n} = $macro; + $c->{bound}{$n} = $macros{$bound} + if defined $bound && defined $macros{$bound}; + } + } + return \%spec; +} + +=pod + +=item check_spec($spec) + +Compare %COMMANDS with the macros read from progress.h. Returns a list of +problems: a macro that is not described here, a described parameter that +progress.h does not define, or two parameters of a command that share a +number. + +=cut + +sub check_spec +{ + my ($spec) = @_; + my @problems; + my %claimed; + + foreach my $cmd (sort keys %COMMANDS) + { + my %seen; + foreach my $macro (sort keys %{ $COMMANDS{$cmd}{params} }) + { + my $def = $COMMANDS{$cmd}{params}{$macro}; + my (undef, $bound) = ref $def ? @$def : ($def); + $claimed{$macro} = 1; + if (!defined $spec->{macros}{$macro}) + { + push @problems, "$cmd: $macro is not defined in progress.h"; + next; + } + push @problems, "$cmd: bound $bound of $macro is not defined" + if defined $bound && !defined $spec->{macros}{$bound}; + my $n = $spec->{macros}{$macro}; + push @problems, "$cmd: $macro and $seen{$n} are both parameter $n" + if defined $seen{$n}; + $seen{$n} = $macro; + } + } + + foreach my $cmd ( + sort grep { $COMMANDS{$_}{hosts_index_build} } + keys %COMMANDS) + { + my %own = + map { $spec->{macros}{$_} => $_ } + grep { defined $spec->{macros}{$_} } + keys %{ $COMMANDS{$cmd}{params} }; + foreach my $macro (@INDEX_BUILD_PARAMS) + { + my $n = $spec->{macros}{$macro}; + push @problems, + "$cmd: its parameter $own{$n} is $n, which an index build writes as $macro" + if defined $n && defined $own{$n}; + } + } + + foreach my $macro (sort keys %{ $spec->{macros} }) + { + next if $claimed{$macro}; + next + if grep { + my $cmd = $_; + grep { index($macro, $_) == 0 } @{ $COMMANDS{$cmd}{values} } + } keys %COMMANDS; + push @problems, + "progress.h defines $macro, which is neither a parameter nor a value of any command"; + } + return @problems; +} + +=pod + +=item parse_log($contents) + +Return the progress events found in a server log, as a hash of pid => +array of events. Each event is a hash with 'event' (start, update or end), +'command', 'relid', 'line' (line number in the log), 'text' and, for +updates, 'changes' (a list of [param, old, new]). The log must have the +pid in brackets in log_line_prefix, as the test framework's default does. + +=cut + +sub parse_log +{ + my ($contents) = @_; + my %trace; + my $lineno = 0; + + foreach my $line (split /\n/, $contents) + { + $lineno++; + next + unless $line =~ + /\[(\d+)\].*?LOG:\s+progress (start|update|end): (\w+) relid=(\d+)(.*)$/; + my %ev = ( + pid => $1, + event => $2, + command => $3, + relid => $4, + line => $lineno, + text => $line); + my $rest = $5; + if ($ev{event} eq 'update') + { + my @changes; + while ($rest =~ /\s(\d+):(-?\d+)->(-?\d+)/g) + { + push @changes, [ $1, $2, $3 ]; + } + $ev{changes} = \@changes; + } + push @{ $trace{ $ev{pid} } }, \%ev; + } + return \%trace; +} + +=pod + +=item check_trace($spec, $trace) + +Replay each backend's events and return the violations found, as hashes +with 'rule', 'pid', 'command', 'line', 'text' and 'detail'. The rules: + + mismatch an update names another command or relation than the start + that is active + nested a command started while a different command was active; + starting the same command again is how a command resets + its counters (REINDEX CONCURRENTLY does it for each index, + with the index's table, which may be a TOAST table) + continuity the old value of a change is not the value this backend + had: the state was changed without being logged. Values + are only known from the backend's first start on, since a + backend's parameters are not zeroed until then. + foreign a command wrote a parameter that is not one of its own + phase a phase took a value that is not defined for it + decrease a monotonic counter decreased + reset a resetting counter decreased to a value other than 0 + bound a counter exceeded the parameter that bounds it + +Writes made while no command is active are not violations: nothing reads +the parameters then (see pgstat_bestart_initial()), and index builds make +such writes routinely. stray_writes() counts them. + +=cut + +sub check_trace +{ + my ($spec, $trace) = @_; + my @violations; + + foreach my $pid (sort { $a <=> $b } keys %$trace) + { + my $active; # command name, or undef + my $relid; + my @vals = (undef) x $NUM_PARAMS; # unknown before the first start + + foreach my $ev (@{ $trace->{$pid} }) + { + my $cmd = $ev->{command}; + my $flag = sub { + my ($rule, $detail) = @_; + push @violations, + { + rule => $rule, + pid => $pid, + command => $cmd, + line => $ev->{line}, + text => $ev->{text}, + detail => $detail + }; + }; + + if ($ev->{event} eq 'start') + { + $flag->( + 'nested', + "$cmd relid=$ev->{relid} started while $active relid=$relid was active" + ) if defined $active && $cmd ne $active; + $active = $cmd; + $relid = $ev->{relid}; + @vals = (0) x $NUM_PARAMS; + next; + } + + if (!defined $active || $cmd eq 'INVALID') + { + # not a violation, see above; only keep the values known + $flag->('mismatch', "end of $cmd with no command active") + if $ev->{event} eq 'end'; + } + elsif ($cmd ne $active || $ev->{relid} != $relid) + { + $flag->( + 'mismatch', + "$ev->{event} of $cmd relid=$ev->{relid} while $active relid=$relid is active" + ); + } + + if ($ev->{event} eq 'end') + { + undef $active; + undef $relid; + next; + } + + my $c = $spec->{$cmd}; + foreach my $ch (@{ $ev->{changes} }) + { + my ($n, $old, $new) = @$ch; + my $name = $c && $c->{name}{$n} ? $c->{name}{$n} : "param $n"; + + $flag->( + 'continuity', + "$name changed from $old, but it was $vals[$n]" + ) if defined $vals[$n] && $old != $vals[$n]; + $vals[$n] = $new; + + next unless $c && defined $active; + my $kind = $c->{kind}{$n}; + if (!defined $kind) + { + $flag->( + 'foreign', "$cmd wrote parameter $n ($old -> $new)"); + next; + } + $flag->('phase', "$name took undefined value $new") + if $kind eq 'phase' && !$c->{phase_values}{$new}; + $flag->('decrease', "$name decreased from $old to $new") + if $kind eq 'monotonic' && $new < $old; + $flag->('reset', "$name went from $old to $new, not to 0") + if $kind eq 'resetting' && $new < $old && $new != 0; + } + + # Bounds are checked once the whole update is applied, since an + # update can move a counter and its bound together. + next unless $c && defined $active; + foreach my $n (sort { $a <=> $b } keys %{ $c->{bound} }) + { + my $b = $c->{bound}{$n}; + next + unless grep { $_->[0] == $n || $_->[0] == $b } + @{ $ev->{changes} }; + # A total of 0 is not known yet, and -1 means it is not + # known at all (backup_total without a size estimate). + $flag->( + 'bound', + "$c->{name}{$n} is $vals[$n], above $spec->{$cmd}{name}{$b} = $vals[$b]" + ) if $vals[$b] > 0 && $vals[$n] > $vals[$b]; + } + } + } + return @violations; +} + +=pod + +=item commands_run($trace) + +Return a hash of command name => number of times it started. + +=cut + +sub commands_run +{ + my ($trace) = @_; + my %count; + foreach my $events (values %$trace) + { + $count{ $_->{command} }++ + foreach grep { $_->{event} eq 'start' } @$events; + } + return %count; +} + +=pod + +=item stray_writes($trace) + +Return a hash of parameter number => number of changes made to it while no +command was active. + +=cut + +sub stray_writes +{ + my ($trace) = @_; + my %count; + foreach my $events (values %$trace) + { + my $active = 0; + foreach my $ev (@$events) + { + $active = 1 if $ev->{event} eq 'start'; + $active = 0 if $ev->{event} eq 'end'; + next if $active || $ev->{event} ne 'update'; + $count{ $_->[0] }++ foreach @{ $ev->{changes} }; + } + } + return %count; +} + +=pod + +=item phases_of($trace, $spec, $command, $relid) + +Return, for each run of $command on $relid (in log order), the list of +phase values it went through, e.g. ([1, 2, 3, 4, 6]). + +=cut + +sub phases_of +{ + my ($trace, $spec, $command, $relid) = @_; + my $phase = $spec->{$command}{phase_param}; + croak "$command has no phase parameter" unless defined $phase; + + my @runs; + foreach my $pid (sort { $a <=> $b } keys %$trace) + { + my $current; + foreach my $ev (@{ $trace->{$pid} }) + { + next + unless $ev->{command} eq $command + && (!defined $relid || $ev->{relid} == $relid); + if ($ev->{event} eq 'start') + { + $current = []; + push @runs, [ $ev->{line}, $current ]; + } + elsif ($ev->{event} eq 'update' && $current) + { + push @$current, map { $_->[2] } + grep { $_->[0] == $phase } @{ $ev->{changes} }; + } + } + } + return map { $_->[1] } sort { $a->[0] <=> $b->[0] } @runs; +} + +=pod + +=item values_of($trace, $command, $relid, $param) + +Return, for each run of $command on $relid, the list of values that +parameter number $param took, in order. This checks a whole succession, +which a final value can hide: a count that jumps ahead and comes back can +still end at the right number. + +=cut + +sub values_of +{ + my ($trace, $command, $relid, $param) = @_; + my @runs; + foreach my $pid (sort { $a <=> $b } keys %$trace) + { + my $current; + foreach my $ev (@{ $trace->{$pid} }) + { + next + unless $ev->{command} eq $command + && (!defined $relid || $ev->{relid} == $relid); + if ($ev->{event} eq 'start') + { + $current = []; + push @runs, [ $ev->{line}, $current ]; + } + elsif ($ev->{event} eq 'update' && $current) + { + push @$current, map { $_->[2] } + grep { $_->[0] == $param } @{ $ev->{changes} }; + } + } + } + return map { $_->[1] } sort { $a->[0] <=> $b->[0] } @runs; +} + +=pod + +=item final_values($trace, $command, $relid) + +Return, for each run of $command on $relid, a hash of parameter number => +the value it had when the command ended. + +=cut + +sub final_values +{ + my ($trace, $command, $relid) = @_; + my @runs; + foreach my $pid (sort { $a <=> $b } keys %$trace) + { + my %vals; + foreach my $ev (@{ $trace->{$pid} }) + { + next + unless $ev->{command} eq $command + && (!defined $relid || $ev->{relid} == $relid); + %vals = () if $ev->{event} eq 'start'; + $vals{ $_->[0] } = $_->[2] foreach @{ $ev->{changes} || [] }; + push @runs, [ $ev->{line}, {%vals} ] if $ev->{event} eq 'end'; + } + } + return map { $_->[1] } sort { $a->[0] <=> $b->[0] } @runs; +} + +=pod + +=back + +=cut + +1; diff --git a/src/test/modules/test_progress/meson.build b/src/test/modules/test_progress/meson.build new file mode 100644 index 00000000000..0f8a6d86dba --- /dev/null +++ b/src/test/modules/test_progress/meson.build @@ -0,0 +1,17 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +tests += { + 'name': 'test_progress', + 'sd': meson.current_source_dir(), + 'bd': meson.current_build_dir(), + 'tap': { + 'env': { + 'PROGRESS_H': meson.project_source_root() / 'src/include/commands/progress.h', + }, + 'tests': [ + 't/001_progress.pl', + ], + # The test reads the server log, which is cluster-wide. + 'runningcheck': false, + }, +} diff --git a/src/test/modules/test_progress/t/001_progress.pl b/src/test/modules/test_progress/t/001_progress.pl new file mode 100644 index 00000000000..33e6fa3794b --- /dev/null +++ b/src/test/modules/test_progress/t/001_progress.pl @@ -0,0 +1,411 @@ + +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Check the whole sequence of values that commands report through the +# pg_stat_progress_* views. +# +# A server compiled with PROGRESS_DEBUG logs every change to a backend's +# progress state. This test runs a series of commands, reads those lines +# back from the server log and checks them: first against rules that hold +# for every command (see ProgressCheck.pm), then against the exact +# succession of phases and the final values expected for each command. +# +# The first check, that ProgressCheck.pm describes every macro in +# commands/progress.h, runs on any build. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +use ProgressCheck; + +my $progress_h = $ENV{PROGRESS_H}; +die "PROGRESS_H is not set" unless defined $progress_h; + +my $spec = ProgressCheck::load_spec($progress_h); +my @problems = ProgressCheck::check_spec($spec); +is_deeply(\@problems, [], + 'ProgressCheck.pm describes every macro of commands/progress.h') + or diag(join("\n", @problems)); + +# Is the server compiled with PROGRESS_DEBUG? It is set in the compiler +# flags, as a buildfarm animal would (CPPFLAGS or CFLAGS with configure, +# c_args with meson), or in pg_config_manual.h. Find out without starting +# a server, so that the test costs nothing in other builds. +my ($cppflags) = run_command([ 'pg_config', '--cppflags' ]); +my ($cflags) = run_command([ 'pg_config', '--cflags' ]); +(my $manual_h = $progress_h) =~ s{commands/progress\.h$}{pg_config_manual.h}; +if ("$cppflags $cflags" !~ /-DPROGRESS_DEBUG\b/ + && slurp_file($manual_h) !~ /^\s*#\s*define\s+PROGRESS_DEBUG\b/m) +{ + note 'not compiled with PROGRESS_DEBUG, skipping the traces'; + done_testing(); + exit; +} + +my $node = PostgreSQL::Test::Cluster->new('main'); +$node->init(allows_streaming => 1); +$node->append_conf( + 'postgresql.conf', qq( +autovacuum = off +max_parallel_maintenance_workers = 2 +min_parallel_index_scan_size = 0 +min_parallel_table_scan_size = 0 +)); +$node->start; + +# Run $sql and return the progress trace it left in the server log, after +# checking it against the rules that hold for every command. +sub traced +{ + my ($name, $code) = @_; + my $offset = -s $node->logfile; + $code->(); + my $trace = ProgressCheck::parse_log(slurp_file($node->logfile, $offset)); + my @violations = ProgressCheck::check_trace($spec, $trace); + is(scalar(@violations), 0, "$name: trace follows the rules") + or diag( + join("\n", + map { "$_->{rule}: $_->{detail}\n $_->{text}" } + @violations[ 0 .. ($#violations < 9 ? $#violations : 9) ])); + return $trace; +} + +sub traced_sql +{ + my ($name, $sql) = @_; + return traced($name, sub { $node->safe_psql('postgres', $sql) }); +} + +# Parameter number of a macro of progress.h. +sub p +{ + my ($macro) = @_; + my $n = $spec->{macros}{$macro}; + die "unknown macro $macro" unless defined $n; + return $n; +} + +my $trace = traced_sql('probe', 'CREATE TABLE probe (a int); VACUUM probe'); +my %runs = ProgressCheck::commands_run($trace); +is($runs{VACUUM}, 1, 'the server log has the trace of a VACUUM'); + +my $tempdir = PostgreSQL::Test::Utils::tempdir; +my $nrows = 3000; + +$node->safe_psql( + 'postgres', qq( +CREATE TABLE prog (a int, b text); +INSERT INTO prog SELECT g, repeat('x', 100) FROM generate_series(1, $nrows) g; +COPY prog TO '$tempdir/prog.data'; +TRUNCATE prog; +)); +my $relid = $node->safe_psql('postgres', "SELECT 'prog'::regclass::oid"); +my $file_size = -s "$tempdir/prog.data"; + +# COPY FROM a file: every row and every byte of the file is counted. +$trace = traced_sql('COPY FROM', "COPY prog FROM '$tempdir/prog.data'"); +my ($copy) = ProgressCheck::final_values($trace, 'COPY', $relid); +is($copy->{ p('PROGRESS_COPY_TUPLES_PROCESSED') }, + $nrows, 'COPY FROM: tuples_processed'); +is($copy->{ p('PROGRESS_COPY_BYTES_TOTAL') }, + $file_size, 'COPY FROM: bytes_total is the file size'); +is($copy->{ p('PROGRESS_COPY_BYTES_PROCESSED') }, + $file_size, 'COPY FROM: bytes_processed reaches the file size'); +is( $copy->{ p('PROGRESS_COPY_COMMAND') }, + p('PROGRESS_COPY_COMMAND_FROM'), + 'COPY FROM: command'); +is( $copy->{ p('PROGRESS_COPY_TYPE') }, + p('PROGRESS_COPY_TYPE_FILE'), + 'COPY FROM: type'); + +# COPY TO a file. +$trace = traced_sql('COPY TO', "COPY prog TO '$tempdir/prog.out'"); +($copy) = ProgressCheck::final_values($trace, 'COPY', $relid); +is($copy->{ p('PROGRESS_COPY_TUPLES_PROCESSED') }, + $nrows, 'COPY TO: tuples_processed'); +is( $copy->{ p('PROGRESS_COPY_BYTES_PROCESSED') }, + -s "$tempdir/prog.out", + 'COPY TO: bytes_processed is the size of what was written'); +is( $copy->{ p('PROGRESS_COPY_COMMAND') }, + p('PROGRESS_COPY_COMMAND_TO'), + 'COPY TO: command'); + +# CREATE INDEX goes through a single phase, building. +$trace = traced_sql('CREATE INDEX', 'CREATE INDEX prog_a ON prog (a)'); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'CREATE_INDEX', $relid) ], + [ [ p('PROGRESS_CREATEIDX_PHASE_BUILD') ] ], + 'CREATE INDEX: phases'); +my ($idx) = ProgressCheck::final_values($trace, 'CREATE_INDEX', $relid); +is($idx->{ p('PROGRESS_CREATEIDX_TUPLES_DONE') }, + $nrows, 'CREATE INDEX: tuples_done'); + +# A parallel GIN build: the leader merges what the workers sorted, and +# counts each merged tuple once. +$node->safe_psql( + 'postgres', q( +CREATE TABLE prog_gin (a int[]); +INSERT INTO prog_gin SELECT ARRAY[g % 100, g % 7] FROM generate_series(1, 3000) g; +)); +my $gin_relid = + $node->safe_psql('postgres', "SELECT 'prog_gin'::regclass::oid"); +$trace = traced_sql('parallel GIN build', + 'CREATE INDEX prog_gin_a ON prog_gin USING gin (a)'); +my ($gin) = ProgressCheck::final_values($trace, 'CREATE_INDEX', $gin_relid); +cmp_ok($gin->{ p('PROGRESS_CREATEIDX_TUPLES_TOTAL') }, + '>', 0, 'parallel GIN build: tuples_total was reported'); +is( $gin->{ p('PROGRESS_CREATEIDX_TUPLES_DONE') }, + $gin->{ p('PROGRESS_CREATEIDX_TUPLES_TOTAL') }, + 'parallel GIN build: tuples_done ends at tuples_total'); + +# CREATE INDEX CONCURRENTLY goes through every phase, in order. +$trace = traced_sql('CREATE INDEX CONCURRENTLY', + 'CREATE INDEX CONCURRENTLY prog_b ON prog (b)'); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'CREATE_INDEX', $relid) ], + [ + [ + map { p("PROGRESS_CREATEIDX_PHASE_$_") } + qw(WAIT_1 BUILD WAIT_2 VALIDATE_IDXSCAN VALIDATE_SORT + VALIDATE_TABLESCAN WAIT_3) + ] + ], + 'CREATE INDEX CONCURRENTLY: phases'); + +# ANALYZE samples every block of a small table. +$trace = traced_sql('ANALYZE', 'ANALYZE prog'); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'ANALYZE', $relid) ], + [ + [ + map { p("PROGRESS_ANALYZE_PHASE_$_") } + qw(ACQUIRE_SAMPLE_ROWS COMPUTE_STATS FINALIZE_ANALYZE) + ] + ], + 'ANALYZE: phases'); +my ($an) = ProgressCheck::final_values($trace, 'ANALYZE', $relid); +is( $an->{ p('PROGRESS_ANALYZE_BLOCKS_DONE') }, + $an->{ p('PROGRESS_ANALYZE_BLOCKS_TOTAL') }, + 'ANALYZE: every block sampled'); + +# VACUUM with dead tuples and two indexes, then with an empty tail, which +# adds the truncate phase. +$node->safe_psql('postgres', 'DELETE FROM prog WHERE a % 3 = 0'); +$trace = traced_sql('VACUUM', 'VACUUM prog'); +my @vacuum = ProgressCheck::phases_of($trace, $spec, 'VACUUM', $relid); +is_deeply( + \@vacuum, + [ + [ + map { p("PROGRESS_VACUUM_PHASE_$_") } + qw(SCAN_HEAP VACUUM_INDEX VACUUM_HEAP INDEX_CLEANUP FINAL_CLEANUP) + ] + ], + 'VACUUM: phases'); +my ($vac) = ProgressCheck::final_values($trace, 'VACUUM', $relid); +is( $vac->{ p('PROGRESS_VACUUM_HEAP_BLKS_SCANNED') }, + $vac->{ p('PROGRESS_VACUUM_TOTAL_HEAP_BLKS') }, + 'VACUUM: every block scanned'); +is($vac->{ p('PROGRESS_VACUUM_NUM_INDEX_VACUUMS') }, + 1, 'VACUUM: one round of index vacuuming'); + +$node->safe_psql('postgres', "DELETE FROM prog WHERE a > $nrows / 2"); +$trace = traced_sql('VACUUM with truncation', 'VACUUM prog'); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'VACUUM', $relid) ], + [ + [ + map { p("PROGRESS_VACUUM_PHASE_$_") } + qw(SCAN_HEAP VACUUM_INDEX VACUUM_HEAP INDEX_CLEANUP TRUNCATE + FINAL_CLEANUP) + ] + ], + 'VACUUM with truncation: phases'); + +# VACUUM with too little memory for all the dead items goes through several +# index vacuum cycles. The dead item counters are documented as what was +# collected since the last cycle, so each new heap scan starts from 0. +$node->safe_psql( + 'postgres', q( +CREATE TABLE prog_cycles (a int PRIMARY KEY); +INSERT INTO prog_cycles SELECT g FROM generate_series(1, 100000) g; +DELETE FROM prog_cycles WHERE a % 2 = 0; +)); +my $cycles_relid = + $node->safe_psql('postgres', "SELECT 'prog_cycles'::regclass::oid"); +$trace = traced_sql('VACUUM in several cycles', + "SET maintenance_work_mem = '64kB'; VACUUM prog_cycles"); +my ($cyc) = ProgressCheck::final_values($trace, 'VACUUM', $cycles_relid); +cmp_ok($cyc->{ p('PROGRESS_VACUUM_NUM_INDEX_VACUUMS') }, + '>', 1, 'VACUUM in several cycles: more than one index vacuum cycle'); +my @stale; +foreach my $events (values %$trace) +{ + my %v; + foreach my $ev (grep { $_->{command} eq 'VACUUM' } @$events) + { + foreach my $ch (@{ $ev->{changes} || [] }) + { + my ($n, $old, $new) = @$ch; + push @stale, + "$ev->{text}: $v{ p('PROGRESS_VACUUM_NUM_DEAD_ITEM_IDS') } dead item ids left" + if $n == p('PROGRESS_VACUUM_PHASE') + && $new == p('PROGRESS_VACUUM_PHASE_SCAN_HEAP') + && $old == p('PROGRESS_VACUUM_PHASE_VACUUM_HEAP') + && $v{ p('PROGRESS_VACUUM_NUM_DEAD_ITEM_IDS') }; + $v{$n} = $new; + } + } +} +is_deeply(\@stale, [], + 'VACUUM in several cycles: each heap scan after the first starts with no dead items' +); + +# Parallel index vacuuming: the workers' progress reaches the leader, so +# every index is counted before each index phase ends. +$node->safe_psql( + 'postgres', qq( +CREATE INDEX prog_ab ON prog (a, b); +DELETE FROM prog WHERE a % 5 = 0; +)); +$trace = traced_sql('parallel VACUUM', 'VACUUM (PARALLEL 2) prog'); + +# A round of index processing ends when the phase changes or when the +# counters go back to 0; at that point every index must have been counted. +my (@rounds, %v); +my ($total, $processed, $phase) = ( + p('PROGRESS_VACUUM_INDEXES_TOTAL'), + p('PROGRESS_VACUUM_INDEXES_PROCESSED'), + p('PROGRESS_VACUUM_PHASE')); +foreach my $events (values %$trace) +{ + foreach my $ev (grep { $_->{command} eq 'VACUUM' } @$events) + { + %v = () if $ev->{event} eq 'start'; + my %changed = map { $_->[0] => $_->[2] } @{ $ev->{changes} || [] }; + if (($v{$total} // 0) > 0 + && ( defined $changed{$phase} + || (defined $changed{$total} && $changed{$total} == 0) + || $ev->{event} eq 'end')) + { + push @rounds, [ $v{$processed} // 0, $v{$total} ]; + } + $v{$_} = $changed{$_} foreach keys %changed; + } +} +ok(@rounds > 0, 'parallel VACUUM: index rounds were reported'); +is_deeply([ grep { $_->[0] != $_->[1] } @rounds ], + [], 'parallel VACUUM: every round counts every index'); + +# REPACK rebuilds each index once, and says so: index_rebuild_count goes +# through 1, 2, ... n, one step per index. Checking only the final value +# would miss a count that jumps ahead and comes back. REPACK USING INDEX +# either sorts the heap or reads it through the index, depending on their +# costs; disabling index scans forces the sort. +my $nindexes = $node->safe_psql('postgres', + "SELECT count(*) FROM pg_index WHERE indrelid = $relid"); + +sub rebuild_counts +{ + my ($trace, $relid) = @_; + return [ + ProgressCheck::values_of( + $trace, 'REPACK', + $relid, p('PROGRESS_REPACK_INDEX_REBUILD_COUNT')) + ]; +} +my @repack_sort = map { p("PROGRESS_REPACK_PHASE_$_") } + qw(SEQ_SCAN_HEAP SORT_TUPLES WRITE_NEW_HEAP SWAP_REL_FILES REBUILD_INDEX + FINAL_CLEANUP); +my @repack_index = map { p("PROGRESS_REPACK_PHASE_$_") } + qw(INDEX_SCAN_HEAP SWAP_REL_FILES REBUILD_INDEX FINAL_CLEANUP); + +$trace = traced_sql('REPACK USING INDEX with a sort', + 'SET enable_indexscan = off; REPACK prog USING INDEX prog_a'); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'REPACK', $relid) ], + [ \@repack_sort ], + 'REPACK USING INDEX with a sort: phases'); +is_deeply( + rebuild_counts($trace, $relid), + [ [ 1 .. $nindexes ] ], + 'REPACK USING INDEX with a sort: index_rebuild_count'); + +$trace = traced_sql('REPACK USING INDEX', 'REPACK prog USING INDEX prog_a'); +my ($phases) = ProgressCheck::phases_of($trace, $spec, 'REPACK', $relid); +ok( "@$phases" eq "@repack_sort" || "@$phases" eq "@repack_index", + 'REPACK USING INDEX: phases of either way of ordering the heap' +) or diag("got phases @$phases"); +is_deeply( + rebuild_counts($trace, $relid), + [ [ 1 .. $nindexes ] ], + 'REPACK USING INDEX: index_rebuild_count'); + +$trace = traced_sql('REPACK', 'REPACK prog'); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'REPACK', $relid) ], + [ + [ + map { p("PROGRESS_REPACK_PHASE_$_") } + qw(SEQ_SCAN_HEAP SWAP_REL_FILES REBUILD_INDEX FINAL_CLEANUP) + ] + ], + 'REPACK: phases'); +is_deeply( + rebuild_counts($trace, $relid), + [ [ 1 .. $nindexes ] ], + 'REPACK: index_rebuild_count'); +my ($rp) = ProgressCheck::final_values($trace, 'REPACK', $relid); +is( $rp->{ p('PROGRESS_REPACK_HEAP_BLKS_SCANNED') }, + $rp->{ p('PROGRESS_REPACK_TOTAL_HEAP_BLKS') }, + 'REPACK: every block scanned'); + +# REPACK (CONCURRENTLY) rebuilds the indexes on the new heap itself, and +# counts them there. +$node->safe_psql( + 'postgres', qq( +CREATE TABLE prog_conc (a int PRIMARY KEY, b text); +INSERT INTO prog_conc SELECT g, repeat('x', 100) FROM generate_series(1, $nrows) g; +CREATE INDEX prog_conc_b ON prog_conc (b); +)); +my $conc_relid = + $node->safe_psql('postgres', "SELECT 'prog_conc'::regclass::oid"); +$trace = + traced_sql('REPACK (CONCURRENTLY)', 'REPACK (CONCURRENTLY) prog_conc'); +is_deeply( + rebuild_counts($trace, $conc_relid), + [ [ 1, 2 ] ], + 'REPACK (CONCURRENTLY): index_rebuild_count'); +($phases) = ProgressCheck::phases_of($trace, $spec, 'REPACK', $conc_relid); +ok( (grep { $_ == p('PROGRESS_REPACK_PHASE_CATCH_UP') } @$phases), + 'REPACK (CONCURRENTLY): goes through the catch-up phase' +) or diag("got phases @$phases"); + +# Base backups, reported by the walsender. WAL is only transferred at the +# end when it is not streamed. +my @backup_phases = map { p("PROGRESS_BASEBACKUP_PHASE_$_") } + qw(WAIT_CHECKPOINT ESTIMATE_BACKUP_SIZE STREAM_BACKUP WAIT_WAL_ARCHIVE); +$trace = traced( + 'BASEBACKUP', + sub { $node->backup('backup', backup_options => ['--wal-method=stream']) } +); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'BASEBACKUP', undef) ], + [ \@backup_phases ], + 'BASEBACKUP: phases'); +$trace = traced( + 'BASEBACKUP fetching WAL', + sub { $node->backup('backup2', backup_options => ['--wal-method=fetch']) } +); +is_deeply( + [ ProgressCheck::phases_of($trace, $spec, 'BASEBACKUP', undef) ], + [ [ @backup_phases, p('PROGRESS_BASEBACKUP_PHASE_TRANSFER_WAL') ] ], + 'BASEBACKUP fetching WAL: phases'); + +$node->stop; + +done_testing(); -- 2.55.0
>From 72a2963e80e472178f8e66715dc29a585419c427 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Tue, 22 Sep 2026 21:33:44 -0300 Subject: [PATCH v2 6/6] Check the documented progress phases against the reported ones --- src/test/modules/test_progress/DocPhases.pm | 265 ++++++++++++++++++ src/test/modules/test_progress/Makefile | 5 + src/test/modules/test_progress/meson.build | 3 + .../modules/test_progress/t/002_doc_phases.pl | 110 ++++++++ 4 files changed, 383 insertions(+) create mode 100644 src/test/modules/test_progress/DocPhases.pm create mode 100644 src/test/modules/test_progress/t/002_doc_phases.pl diff --git a/src/test/modules/test_progress/DocPhases.pm b/src/test/modules/test_progress/DocPhases.pm new file mode 100644 index 00000000000..7485c5f07ca --- /dev/null +++ b/src/test/modules/test_progress/DocPhases.pm @@ -0,0 +1,265 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +=pod + +=head1 NAME + +DocPhases - cross-check the documented phases against the ones a command +really reports + +=head1 SYNOPSIS + + use DocPhases; + + my $doc = DocPhases::load($share_dir); + my @problems = DocPhases::check_against_trace($doc, 'VACUUM', \@phases_seen); + +=head1 DESCRIPTION + +A progress phase exists in three places in the tree, and nothing checks +that the three agree: + +=over + +=item * F<src/include/commands/progress.h> defines the value +(C<PROGRESS_VACUUM_PHASE_SCAN_HEAP> is 1). + +=item * F<src/backend/catalog/system_views.sql> turns the value into the +text the user sees (C<WHEN 1 THEN 'scanning heap'>). + +=item * F<doc/src/sgml/monitoring.sgml> lists the phases, in a table whose +row order is what a reader takes as the order the phases happen in. + +=back + +This module reads the last two and compares them with what a command +actually reported, so that a phase that is documented but never reached, a +phase reported but not documented, and a documented order that does not +match the real one, all become visible. + +Nothing here is hardcoded: adding a phase in the three places keeps the +check quiet, adding it in two of them does not. + +=cut + +package DocPhases; + +use strict; +use warnings FATAL => 'all'; + +use Carp; + +# view name -> the phase table in monitoring.sgml +our %PHASE_TABLE = ( + pg_stat_progress_vacuum => 'vacuum-phases', + pg_stat_progress_analyze => 'analyze-phases', + pg_stat_progress_cluster => 'cluster-phases', + pg_stat_progress_repack => 'repack-phases', + pg_stat_progress_create_index => 'create-index-phases', + pg_stat_progress_basebackup => 'basebackup-phases', +); + +# command name as PROGRESS_DEBUG logs it -> view name +our %COMMAND_VIEW = ( + VACUUM => 'pg_stat_progress_vacuum', + ANALYZE => 'pg_stat_progress_analyze', + CLUSTER => 'pg_stat_progress_cluster', + REPACK => 'pg_stat_progress_repack', + # progress.h calls it CREATE_INDEX, which is how PROGRESS_DEBUG logs it + CREATE_INDEX => 'pg_stat_progress_create_index', + BASEBACKUP => 'pg_stat_progress_basebackup', +); + +=pod + +=head2 load($system_views_sql, $monitoring_sgml) + +Read the phase texts from system_views.sql and their documented order from +monitoring.sgml. Returns a hashref keyed by view name, each holding + + value_to_text { 0 => 'initializing', 1 => 'scanning heap', ... } + doc_order [ 'initializing', 'scanning heap', ... ] + +The two paths come from the Makefile, the same way the module that reads +progress.h gets its own. + +=cut + +sub load +{ + my ($system_views_sql, $monitoring_sgml) = @_; + my %out; + + my $views = _slurp($system_views_sql); + my $sgml = _slurp($monitoring_sgml); + + for my $view (keys %PHASE_TABLE) + { + # the CASE that maps the phase parameter to its text + next unless $views =~ /CREATE VIEW \Q$view\E AS(.*?);\n/s; + my $body = $1; + # The phase CASE, and only it: some views have another CASE just + # before it (create_index maps param1 to a command name), so the + # match must not run from one CASE into the next one's END. The + # keyword case varies too ("END as phase"). + next + unless $body =~ + /CASE \s+ S\.param\d+ ((?: (?! \bEND\s+AS\b ) . )*?) \s+ END \s+ AS \s+ phase/isx; + my $case = $1; + + my %v2t; + while ($case =~ /WHEN\s+(\d+)\s+THEN\s+'([^']*)'/g) + { + $v2t{$1} = $2; + } + next unless %v2t; + + # the documented order is the row order of the phase table + my $id = $PHASE_TABLE{$view}; + my @doc; + if ($sgml =~ /<table id="\Q$id\E">(.*?)<\/table>/s) + { + my $table = $1; + while ($table =~ /<entry><literal>([^<]*)<\/literal><\/entry>/g) + { + push @doc, $1; + } + } + + $out{$view} = { value_to_text => \%v2t, doc_order => \@doc }; + } + + return \%out; +} + +=pod + +=head2 check_against_trace($doc, $command, $phases) + +$phases is the sequence of phase values a single command run reported, as +ProgressCheck::phases_of() returns it. Returns a list of problems, each a +hashref with 'kind' and 'detail'. + +Three kinds are reported: + + undocumented a value was reported that system_views.sql or the + documentation does not know about + out_of_order a phase was reported after one that the documentation + lists later, which means the table's row order is not the + order of execution + never_reached reported only by unreached_phases(), see below + +A phase repeating, or the sequence going back to an earlier phase, is +normal for commands that loop (VACUUM revisits the heap), so a backwards +step is only reported the first time a pair is seen, and the caller +decides whether that pair is a real loop or a documentation bug. + +=cut + +sub check_against_trace +{ + my ($doc, $command, $phases) = @_; + my @problems; + + my $view = $COMMAND_VIEW{$command} or return (); + my $d = $doc->{$view} or return (); + + my %rank; + my $i = 0; + $rank{$_} = $i++ for @{ $d->{doc_order} }; + + my $prev; + my %seen_pair; + my %already; + for my $val (@$phases) + { + my $text = $d->{value_to_text}{$val}; + + if (!defined $text) + { + push @problems, + { + kind => 'undocumented', + detail => "$command reported phase value $val, which " + . "system_views.sql does not map to any text" + }; + next; + } + + if (!exists $rank{$text}) + { + push @problems, + { + kind => 'undocumented', + detail => "$command reported phase \"$text\", which is not " + . "listed in the documentation table" + }; + } + elsif (defined $prev + && exists $rank{$prev} + && $rank{$text} < $rank{$prev} + && !$already{$text} + && !$seen_pair{"$prev|$text"}++) + { + # Going back to a phase that already happened is a loop, and + # several commands loop on purpose: VACUUM returns to "scanning + # heap" for each round of index vacuuming, and the documentation + # says so. What is reported here is the other case: a phase + # reached for the FIRST time although the table lists it earlier, + # which means the row order is not the order of execution. + push @problems, + { + kind => 'out_of_order', + detail => "$command went from \"$prev\" to \"$text\", but the " + . "documentation lists \"$text\" before \"$prev\"" + }; + } + + if (defined $text) + { + $already{$text} = 1; + $prev = $text; + } + } + + return @problems; +} + +=pod + +=head2 unreached_phases($doc, $command, $phases) + +The documented phases that the run never reported. A phase can be +legitimately unreachable in a given run (an index-less table never +vacuums indexes), so this is information for the caller, not a failure. + +=cut + +sub unreached_phases +{ + my ($doc, $command, $phases) = @_; + + my $view = $COMMAND_VIEW{$command} or return (); + my $d = $doc->{$view} or return (); + + my %seen; + for my $val (@$phases) + { + my $t = $d->{value_to_text}{$val}; + $seen{$t} = 1 if defined $t; + } + + return grep { !$seen{$_} } @{ $d->{doc_order} }; +} + +sub _slurp +{ + my ($path) = @_; + open my $fh, '<', $path or croak "could not open $path: $!"; + local $/; + my $c = <$fh>; + close $fh; + return $c; +} + +1; diff --git a/src/test/modules/test_progress/Makefile b/src/test/modules/test_progress/Makefile index f5dbca84920..835acc0ae0f 100644 --- a/src/test/modules/test_progress/Makefile +++ b/src/test/modules/test_progress/Makefile @@ -18,3 +18,8 @@ endif # The test checks its description of the progress parameters against this. export PROGRESS_H := $(abs_top_srcdir)/src/include/commands/progress.h + +# ... and the phases a command reports against the text the view gives them +# and the order the documentation lists them in. +export SYSTEM_VIEWS_SQL := $(abs_top_srcdir)/src/backend/catalog/system_views.sql +export MONITORING_SGML := $(abs_top_srcdir)/doc/src/sgml/monitoring.sgml diff --git a/src/test/modules/test_progress/meson.build b/src/test/modules/test_progress/meson.build index 0f8a6d86dba..0743267d106 100644 --- a/src/test/modules/test_progress/meson.build +++ b/src/test/modules/test_progress/meson.build @@ -7,9 +7,12 @@ tests += { 'tap': { 'env': { 'PROGRESS_H': meson.project_source_root() / 'src/include/commands/progress.h', + 'SYSTEM_VIEWS_SQL': meson.project_source_root() / 'src/backend/catalog/system_views.sql', + 'MONITORING_SGML': meson.project_source_root() / 'doc/src/sgml/monitoring.sgml', }, 'tests': [ 't/001_progress.pl', + 't/002_doc_phases.pl', ], # The test reads the server log, which is cluster-wide. 'runningcheck': false, diff --git a/src/test/modules/test_progress/t/002_doc_phases.pl b/src/test/modules/test_progress/t/002_doc_phases.pl new file mode 100644 index 00000000000..23d6085cad9 --- /dev/null +++ b/src/test/modules/test_progress/t/002_doc_phases.pl @@ -0,0 +1,110 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Check the progress phases a command really reports against the phases the +# documentation lists for it. +# +# A phase lives in three places that nothing keeps in sync: its value in +# progress.h, its text in system_views.sql, and its row in the table in +# monitoring.sgml. This test runs the commands and compares. + +use strict; +use warnings FATAL => 'all'; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +use FindBin; +use lib $FindBin::RealBin . '/..'; + +use ProgressCheck; +use DocPhases; + +if (!$ENV{PROGRESS_DEBUG_BUILD}) +{ + plan skip_all => + 'test requires a build with PROGRESS_DEBUG (set PROGRESS_DEBUG_BUILD=1)'; +} + +my $system_views = $ENV{SYSTEM_VIEWS_SQL} + or plan skip_all => 'SYSTEM_VIEWS_SQL is not set'; +my $monitoring = $ENV{MONITORING_SGML} + or plan skip_all => 'MONITORING_SGML is not set'; + +my $node = PostgreSQL::Test::Cluster->new('doc_phases'); +$node->init; +# one round of index vacuuming per small batch of dead tuples, so that VACUUM +# really goes back to "scanning heap" and the check has a loop to not trip on +$node->append_conf('postgresql.conf', 'maintenance_work_mem = 1024'); +# REPACK (CONCURRENTLY) refuses to run below "replica" +$node->append_conf('postgresql.conf', 'wal_level = replica'); +$node->start; + +$node->safe_psql('postgres', + q{CREATE TABLE phases_tab (a int primary key, b text)}); +$node->safe_psql('postgres', + q{INSERT INTO phases_tab SELECT g, repeat('y', 40) FROM generate_series(1, 200000) g}); +$node->safe_psql('postgres', q{CREATE INDEX phases_b ON phases_tab (b)}); +$node->safe_psql('postgres', q{DELETE FROM phases_tab}); + +my $doc = DocPhases::load($system_views, $monitoring); +ok(keys %$doc, 'found phase tables in the documentation'); + +my $spec = ProgressCheck::load_spec($ENV{PROGRESS_H}); + +my @commands = ( + [ 'VACUUM' => 'VACUUM phases_tab' ], + [ 'ANALYZE' => 'ANALYZE phases_tab' ], + [ 'CLUSTER' => 'CLUSTER phases_tab USING phases_tab_pkey' ], + [ 'CREATE INDEX CONCURRENTLY' => + 'CREATE INDEX CONCURRENTLY phases_c ON phases_tab (a)' ], + [ 'REPACK (CONCURRENTLY)' => 'REPACK (CONCURRENTLY) phases_tab' ], +); + +my @out_of_order; + +for my $c (@commands) +{ + my ($name, $sql) = @$c; + + my $offset = -s $node->logfile; + $node->safe_psql('postgres', $sql); + + my $contents = slurp_file($node->logfile, $offset); + my $trace = ProgressCheck::parse_log($contents); + + my %ran = ProgressCheck::commands_run($trace); + for my $command (sort keys %ran) + { + next unless defined $spec->{$command}{phase_param}; + + for my $phases (ProgressCheck::phases_of($trace, $spec, $command, undef)) + { + next unless @$phases; + + my @problems = + DocPhases::check_against_trace($doc, $command, $phases); + + # A value the view or the documentation does not know about is a + # plain bug: the three places have drifted apart. + my @undocumented = grep { $_->{kind} eq 'undocumented' } @problems; + is(scalar @undocumented, 0, + "$name: every phase $command reports is documented") + or diag($_->{detail}) for @undocumented; + + # A phase first reached out of the documented order means the + # table's row order is not the order of execution. That is a + # documentation bug, not a server one, so it is reported rather + # than failed, until the table is fixed. + push @out_of_order, $_->{detail} + for grep { $_->{kind} eq 'out_of_order' } @problems; + } + } +} + +my %seen; +my @unique = grep { !$seen{$_}++ } @out_of_order; +diag("documented order does not match execution order:\n " . join("\n ", @unique)) + if @unique; + +done_testing(); -- 2.55.0
