The two patches attached add a debug trace and a test framework for progress reporting. They were first posted in [1]; they get their own thread now, as Michael suggested.
0001 adds PROGRESS_DEBUG. With it defined, every change to a backend's progress state is logged at LOG_SERVER_ONLY, so a test can read back the exact sequence of reports a command makes, without needing concurrency or injection points. It is compiled out by default: with it undefined the object code of backend_progress.c is unchanged (the same instruction stream, only the line numbers baked into existing elog calls shift), and the test below skips, so "make check" and "meson test" are not any slower. 0002 adds the test module test_progress. It replays each backend's trace and checks the 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, and a command writes only its own parameters -- and then the exact succession of phases for each command. It also checks every parameter of commands/progress.h against a description, on any build, so a new or renumbered parameter has to be described before the test passes. These checks have already been useful: the trace is what found the three blips fixed in 3be29d9346d, and the description check flagged, while rebasing, that 1378aa13430 had added PROGRESS_VACUUM_CURRENT_INDEX_RELID without describing it. Run on master, the framework also flags two harmless blips that no view exposes: when one command builds or vacuums several indexes in a row (REPACK, VACUUM FULL, VACUUM in several cycles), the index-build tuple counter and the dead-item counters step straight to the next round's value instead of first going back to 0. The test sets these aside as known-accepted (listed in @ACCEPTED, the dead-item one under a TODO) so the suite is green; they are harmless and I have left the behavior as it is. Resetting the counters in every build and cycle removes them and makes the dead-item counters match their documented "collected since the last cycle" meaning; I can post that as a small optional follow-up if it is wanted. [1] https://postgr.es/m/[email protected]
From 1b0f6d3fc9f00f6485ff7adb4e9c926b544f597c Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v5 1/2] 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. A counter may also go to and come back from the value its view shows as NULL, which data checksums use. The test then runs every command that reports progress: COPY (with rows excluded by WHERE and skipped by ON_ERROR), CREATE INDEX [CONCURRENTLY] (also on a partitioned table), REINDEX [CONCURRENTLY], a parallel GIN build, ANALYZE (also of a partitioned table with extended statistics), VACUUM (with truncation, in several index cycles, and parallel), VACUUM FULL, REPACK (sorting, through an index, and CONCURRENTLY), base backups, and the online disabling and enabling of data checksums. It 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 | 171 +++++ 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 | 712 ++++++++++++++++++ src/test/modules/test_progress/meson.build | 17 + .../modules/test_progress/t/001_progress.pl | 581 ++++++++++++++ 8 files changed, 1511 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..02209a653dd 100644 --- a/src/backend/utils/activity/backend_progress.c +++ b/src/backend/utils/activity/backend_progress.c @@ -17,6 +17,95 @@ #include "utils/backend_status.h" +#ifdef PROGRESS_DEBUG + +#include "miscadmin.h" + +/* + * 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 +126,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 +142,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 +181,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 +251,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 +273,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 +307,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 +318,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..4a1daf910a7 --- /dev/null +++ b/src/test/modules/test_progress/ProgressCheck.pm @@ -0,0 +1,712 @@ + +# 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. +# +# 'null', if set, is the value that the command's view shows as NULL. A +# counter may go to it and come back from it at any time. +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_'], + # the view shows -1 as NULL: not known yet + null => -1, + },); + +=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 => {}, + null => $COMMANDS{$cmd}{null}); + + 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}; + next + if defined $c->{null} + && ($old == $c->{null} || $new == $c->{null}); + $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..b665b76e80b --- /dev/null +++ b/src/test/modules/test_progress/t/001_progress.pl @@ -0,0 +1,581 @@ + +# 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'); + +# REINDEX reports each index as its own CREATE INDEX command, with the +# command set to REINDEX; REINDEX CONCURRENTLY goes through the phases of +# CREATE INDEX CONCURRENTLY. +$trace = traced_sql('REINDEX TABLE', 'REINDEX TABLE prog'); +my @reindex = ProgressCheck::final_values($trace, 'CREATE_INDEX', $relid); +is(scalar(@reindex), $nindexes, 'REINDEX TABLE: one run per index'); +is_deeply( + [ map { $_->{ p('PROGRESS_CREATEIDX_COMMAND') } } @reindex ], + [ (p('PROGRESS_CREATEIDX_COMMAND_REINDEX')) x $nindexes ], + 'REINDEX TABLE: command'); + +$trace = traced_sql('REINDEX INDEX CONCURRENTLY', + 'REINDEX INDEX CONCURRENTLY prog_a'); +my ($reindex_conc) = + ProgressCheck::final_values($trace, 'CREATE_INDEX', $relid); +is( $reindex_conc->{ p('PROGRESS_CREATEIDX_COMMAND') }, + p('PROGRESS_CREATEIDX_COMMAND_REINDEX_CONCURRENTLY'), + 'REINDEX INDEX CONCURRENTLY: command'); + +# An index on a partitioned table counts the partitions it is built on. +$node->safe_psql( + 'postgres', q( +CREATE TABLE prog_part (a int, b int) PARTITION BY RANGE (a); +CREATE TABLE prog_part_1 PARTITION OF prog_part FOR VALUES FROM (0) TO (1000); +CREATE TABLE prog_part_2 PARTITION OF prog_part FOR VALUES FROM (1000) TO (2000); +CREATE TABLE prog_part_3 PARTITION OF prog_part FOR VALUES FROM (2000) TO (3000); +INSERT INTO prog_part SELECT g, g % 10 FROM generate_series(0, 2999) g; +CREATE STATISTICS prog_part_stats ON a, b FROM prog_part; +)); +my $part_relid = + $node->safe_psql('postgres', "SELECT 'prog_part'::regclass::oid"); +$trace = traced_sql('CREATE INDEX on a partitioned table', + 'CREATE INDEX prog_part_a ON prog_part (a)'); +my ($part) = ProgressCheck::final_values($trace, 'CREATE_INDEX', $part_relid); +is($part->{ p('PROGRESS_CREATEIDX_PARTITIONS_TOTAL') }, + 3, 'CREATE INDEX on a partitioned table: partitions_total'); +is($part->{ p('PROGRESS_CREATEIDX_PARTITIONS_DONE') }, + 3, 'CREATE INDEX on a partitioned table: partitions_done'); + +# ANALYZE of a partitioned table samples the whole tree, then computes the +# extended statistics defined on it. +$trace = traced_sql('ANALYZE of a partitioned table', 'ANALYZE prog_part'); +my @part_phases = + ProgressCheck::phases_of($trace, $spec, 'ANALYZE', $part_relid); +ok( (grep { $_ == p('PROGRESS_ANALYZE_PHASE_ACQUIRE_SAMPLE_ROWS_INH') } + map { @$_ } @part_phases), + 'ANALYZE of a partitioned table: samples the inheritance tree' +) or diag(explain \@part_phases); +ok( (grep { $_ == p('PROGRESS_ANALYZE_PHASE_COMPUTE_EXT_STATS') } + map { @$_ } @part_phases), + 'ANALYZE of a partitioned table: computes the extended statistics' +) or diag(explain \@part_phases); +foreach my $an (ProgressCheck::final_values($trace, 'ANALYZE', $part_relid)) +{ + is( $an->{ p('PROGRESS_ANALYZE_CHILD_TABLES_DONE') }, + $an->{ p('PROGRESS_ANALYZE_CHILD_TABLES_TOTAL') }, + 'ANALYZE of a partitioned table: every child table done'); + is( $an->{ p('PROGRESS_ANALYZE_EXT_STATS_COMPUTED') }, + $an->{ p('PROGRESS_ANALYZE_EXT_STATS_TOTAL') }, + 'ANALYZE of a partitioned table: every extended statistic computed' + ); +} + +# COPY FROM counts the rows that WHERE excludes and the rows that +# ON_ERROR ignore skips, apart from the rows it loads. +$node->safe_psql('postgres', 'CREATE TABLE prog_copy (a int)'); +my $copy_relid = + $node->safe_psql('postgres', "SELECT 'prog_copy'::regclass::oid"); +PostgreSQL::Test::Utils::append_to_file("$tempdir/copy.data", + join('', map { $_ % 10 == 0 ? "bad\n" : "$_\n" } 1 .. 100)); +$trace = traced_sql('COPY FROM with WHERE and ON_ERROR', + "COPY prog_copy FROM '$tempdir/copy.data' WITH (ON_ERROR ignore) WHERE a > 50" +); +($copy) = ProgressCheck::final_values($trace, 'COPY', $copy_relid); +is($copy->{ p('PROGRESS_COPY_TUPLES_SKIPPED') }, + 10, 'COPY FROM with ON_ERROR ignore: tuples_skipped'); +is($copy->{ p('PROGRESS_COPY_TUPLES_EXCLUDED') }, + 45, 'COPY FROM with WHERE: tuples_excluded'); +is($copy->{ p('PROGRESS_COPY_TUPLES_PROCESSED') }, + 45, 'COPY FROM with WHERE and ON_ERROR: tuples_processed'); + +# VACUUM FULL is reported as REPACK, and rebuilds every index. +$trace = traced_sql('VACUUM FULL', 'VACUUM FULL prog'); +is_deeply( + rebuild_counts($trace, $relid), + [ [ 1 .. $nindexes ] ], + 'VACUUM FULL: index_rebuild_count'); + +# Online changes of data checksums: a launcher that goes over the +# databases, and for enabling, one worker per database that goes over its +# relations. The counters start at -1, shown as NULL. +sub checksums_trace +{ + my ($name, $sql, $state) = @_; + return traced( + $name, + sub { + $node->safe_psql('postgres', $sql); + $node->poll_query_until('postgres', + "SELECT setting = '$state' FROM pg_settings WHERE name = 'data_checksums'" + ) or die "data_checksums did not become $state"; + $node->poll_query_until('postgres', + "SELECT count(*) = 0 FROM pg_stat_activity WHERE backend_type = 'datachecksums launcher'" + ) or die 'the datachecksums launcher did not exit'; + }); +} + +# The final values of each run of DATACHECKSUMS by a process whose log +# lines name $type. +sub checksums_runs +{ + my ($trace, $type) = @_; + my %by_type = map { $_ => $trace->{$_} } + grep { grep { $_->{text} =~ /\Q$type\E\[/ } @{ $trace->{$_} } } + keys %$trace; + return ProgressCheck::final_values(\%by_type, 'DATACHECKSUMS', 0); +} + +sub checksums_phases +{ + my ($trace, $type) = @_; + my %by_type = map { $_ => $trace->{$_} } + grep { grep { $_->{text} =~ /\Q$type\E\[/ } @{ $trace->{$_} } } + keys %$trace; + return ProgressCheck::phases_of(\%by_type, $spec, 'DATACHECKSUMS', 0); +} + +$trace = checksums_trace('DATACHECKSUMS disable', + 'SELECT pg_disable_data_checksums()', 'off'); +is_deeply( + [ checksums_phases($trace, 'datachecksums launcher') ], + [ + [ + map { p("PROGRESS_DATACHECKSUMS_PHASE_$_") } + qw(DISABLING DONE) + ] + ], + 'DATACHECKSUMS disable: phases of the launcher'); + +$trace = checksums_trace('DATACHECKSUMS enable', + 'SELECT pg_enable_data_checksums(0, 100)', 'on'); +is_deeply( + [ checksums_phases($trace, 'datachecksums launcher') ], + [ + [ + map { p("PROGRESS_DATACHECKSUMS_PHASE_$_") } + qw(WAITING_BARRIER DONE) + ] + ], + 'DATACHECKSUMS enable: phases of the launcher'); +my ($launcher) = checksums_runs($trace, 'datachecksums launcher'); +cmp_ok($launcher->{ p('PROGRESS_DATACHECKSUMS_DBS_TOTAL') }, + '>', 0, 'DATACHECKSUMS enable: databases_total'); +is( $launcher->{ p('PROGRESS_DATACHECKSUMS_DBS_DONE') }, + $launcher->{ p('PROGRESS_DATACHECKSUMS_DBS_TOTAL') }, + 'DATACHECKSUMS enable: every database done'); +my @workers = checksums_runs($trace, 'datachecksums worker'); +is( scalar(@workers), + $launcher->{ p('PROGRESS_DATACHECKSUMS_DBS_TOTAL') }, + 'DATACHECKSUMS enable: one worker per database'); +is_deeply( + [ + grep { + $_->{ p('PROGRESS_DATACHECKSUMS_RELS_DONE') } != + $_->{ p('PROGRESS_DATACHECKSUMS_RELS_TOTAL') } + } @workers + ], + [], + 'DATACHECKSUMS enable: each worker does every relation'); + +$node->stop; + +done_testing(); -- 2.55.0
From 0e0919ff3b730130b535e348cc427c720794b948 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Tue, 22 Sep 2026 21:33:44 -0300 Subject: [PATCH v5 2/2] Check the documented progress phases against the reported ones A progress phase lives in three places that nothing keeps in sync: its value in commands/progress.h, the text the view gives it in system_views.sql, and its row in the phase table of monitoring.sgml. Adding a phase in two of them compiles and passes every test. The new test 002_doc_phases.pl runs VACUUM, ANALYZE, CLUSTER, CREATE INDEX CONCURRENTLY and REPACK (CONCURRENTLY) on a PROGRESS_DEBUG build, and checks that each phase they report is mapped to a text by the view and listed in the documentation. The row order of the tables is not checked, as it is not meant as a guarantee of the order of execution; 001_progress.pl checks the actual succession of phases. The check for a PROGRESS_DEBUG build moves into ProgressCheck.pm as compiled_with_progress_debug(), so that both tests detect it the same way. --- src/test/modules/test_progress/DocPhases.pm | 193 ++++++++++++++++++ src/test/modules/test_progress/Makefile | 5 + .../modules/test_progress/ProgressCheck.pm | 31 +++ src/test/modules/test_progress/meson.build | 3 + .../modules/test_progress/t/001_progress.pl | 59 ++++-- .../modules/test_progress/t/002_doc_phases.pl | 93 +++++++++ 6 files changed, 370 insertions(+), 14 deletions(-) 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..535b742a9be --- /dev/null +++ b/src/test/modules/test_progress/DocPhases.pm @@ -0,0 +1,193 @@ +# 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. + +=back + +This module reads the last two and compares them with what a command +actually reported, so that a phase the view does not name, or the +documentation does not list, becomes visible. The row order of the table +is not checked: it is not meant as a guarantee of the order of execution. + +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 the phases documented in +monitoring.sgml. Returns a hashref keyed by view name, each holding + + value_to_text { 0 => 'initializing', 1 => 'scanning heap', ... } + documented { 'initializing' => 1, 'scanning heap' => 1, ... } + +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; + + my $id = $PHASE_TABLE{$view}; + my %documented; + if ($sgml =~ /<table id="\Q$id\E">(.*?)<\/table>/s) + { + my $table = $1; + while ($table =~ /<entry><literal>([^<]*)<\/literal><\/entry>/g) + { + $documented{$1} = 1; + } + } + + $out{$view} = + { value_to_text => \%v2t, documented => \%documented }; + } + + 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'. The only kind is 'undocumented': a value +was reported that system_views.sql does not map to a text, or whose text +the documentation table does not list. Each such value is reported once. + +=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 %reported; + for my $val (@$phases) + { + next if $reported{$val}++; + + 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" + }; + } + elsif (!$d->{documented}{$text}) + { + push @problems, + { + kind => 'undocumented', + detail => "$command reported phase \"$text\", which is not " + . "listed in the documentation table" + }; + } + } + + return @problems; +} + +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..38afb1198b2 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 table 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/ProgressCheck.pm b/src/test/modules/test_progress/ProgressCheck.pm index 4a1daf910a7..ec76f81e1cd 100644 --- a/src/test/modules/test_progress/ProgressCheck.pm +++ b/src/test/modules/test_progress/ProgressCheck.pm @@ -39,6 +39,7 @@ use strict; use warnings FATAL => 'all'; use Carp; +use PostgreSQL::Test::Utils qw(run_command slurp_file); # The number of parameters in a backend's progress state; see # PGSTAT_NUM_PROGRESS_PARAM. @@ -95,6 +96,13 @@ our %COMMANDS = ( PROGRESS_VACUUM_DELAY_TIME => 'monotonic', PROGRESS_VACUUM_MODE => 'free', PROGRESS_VACUUM_STARTED_BY => 'free', + PROGRESS_VACUUM_CURRENT_INDEX_RELID => 'free', + # While vacuuming or cleaning up an index, vacuum reports the + # scan of that index through the generic block counters, resetting + # them for each index (see 1378aa13430). + PROGRESS_SCAN_BLOCKS_TOTAL => 'free', + PROGRESS_SCAN_BLOCKS_DONE => + [ 'resetting', 'PROGRESS_SCAN_BLOCKS_TOTAL' ], }, values => [ 'PROGRESS_VACUUM_PHASE_', 'PROGRESS_VACUUM_MODE_', @@ -216,6 +224,29 @@ our %COMMANDS = ( =over +=item compiled_with_progress_debug($progress_h) + +Return true if the server is 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, which is found +next to $progress_h. This does not start a server, so that a test costs +nothing in other builds. + +=cut + +sub compiled_with_progress_debug +{ + my ($progress_h) = @_; + 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}; + return "$cppflags $cflags" =~ /-DPROGRESS_DEBUG\b/ + || slurp_file($manual_h) =~ /^\s*#\s*define\s+PROGRESS_DEBUG\b/m; +} + +=pod + =item load_spec($progress_h) Read the macros of commands/progress.h and resolve %COMMANDS against them. 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/001_progress.pl b/src/test/modules/test_progress/t/001_progress.pl index b665b76e80b..8b5f8f899a2 100644 --- a/src/test/modules/test_progress/t/001_progress.pl +++ b/src/test/modules/test_progress/t/001_progress.pl @@ -31,15 +31,7 @@ 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) +if (!ProgressCheck::compiled_with_progress_debug($progress_h)) { note 'not compiled with PROGRESS_DEBUG, skipping the traces'; done_testing(); @@ -59,6 +51,33 @@ $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. +# Blips that the trace exposes but that are harmless, so they do not fail +# the suite. They come from a counter that an index build or an index +# vacuum cycle leaves set when one command builds or vacuums several +# indexes in a row: the counter steps straight to the next round's value +# instead of first returning to 0. No user sees it, because the parameter +# is not one that the running command's view shows. Resetting these in +# every build and cycle is proposed as an optional follow-up in the same +# thread; with that applied, these go away and the TODO blocks below pass. +my @ACCEPTED = ( + { rule => 'reset', command => 'REPACK', param => 'PROGRESS_CREATEIDX_TUPLES_DONE' }, + { rule => 'reset', command => 'VACUUM', param => 'PROGRESS_VACUUM_DEAD_TUPLE_BYTES' }, + { rule => 'reset', command => 'VACUUM', param => 'PROGRESS_VACUUM_NUM_DEAD_ITEM_IDS' }, +); + +sub is_accepted +{ + my ($v) = @_; + foreach my $a (@ACCEPTED) + { + return 1 + if $v->{rule} eq $a->{rule} + && $v->{command} eq $a->{command} + && index($v->{detail}, $a->{param}) == 0; + } + return 0; +} + sub traced { my ($name, $code) = @_; @@ -66,6 +85,12 @@ sub traced $code->(); my $trace = ProgressCheck::parse_log(slurp_file($node->logfile, $offset)); my @violations = ProgressCheck::check_trace($spec, $trace); + my @accepted = grep { is_accepted($_) } @violations; + @violations = grep { !is_accepted($_) } @violations; + diag("$name: " + . scalar(@accepted) + . " known harmless blip(s) set aside (see \@ACCEPTED)") + if @accepted; is(scalar(@violations), 0, "$name: trace follows the rules") or diag( join("\n", @@ -195,7 +220,7 @@ is( $an->{ p('PROGRESS_ANALYZE_BLOCKS_DONE') }, # 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'); +$trace = traced_sql('VACUUM', 'VACUUM (PARALLEL 0) prog'); my @vacuum = ProgressCheck::phases_of($trace, $spec, 'VACUUM', $relid); is_deeply( \@vacuum, @@ -214,7 +239,7 @@ 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'); +$trace = traced_sql('VACUUM with truncation', 'VACUUM (PARALLEL 0) prog'); is_deeply( [ ProgressCheck::phases_of($trace, $spec, 'VACUUM', $relid) ], [ @@ -261,9 +286,15 @@ foreach my $events (values %$trace) } } } -is_deeply(\@stale, [], - 'VACUUM in several cycles: each heap scan after the first starts with no dead items' -); +TODO: { + local $TODO = + "the dead-item counters are not reset after the last index cycle, " + . "a harmless blip no view exposes; a reset is proposed as an optional " + . "follow-up in the same thread"; + 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. 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..67a9d096dc4 --- /dev/null +++ b/src/test/modules/test_progress/t/002_doc_phases.pl @@ -0,0 +1,93 @@ +# 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; + +my $progress_h = $ENV{PROGRESS_H} + or plan skip_all => 'PROGRESS_H is not set'; +plan skip_all => 'not compiled with PROGRESS_DEBUG' + unless ProgressCheck::compiled_with_progress_debug($progress_h); + +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; +# several rounds of index vacuuming, so that VACUUM reports each of its +# phases more than once +$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($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' ], +); + +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; + + # A value the view or the documentation does not know about is a + # plain bug: the three places have drifted apart. + my @undocumented = + DocPhases::check_against_trace($doc, $command, $phases); + is(scalar @undocumented, 0, + "$name: every phase $command reports is documented") + or diag(join("\n", map { $_->{detail} } @undocumented)); + } + } +} + +done_testing(); -- 2.55.0
