Hi Álvaro, Michael, Álvaro Herrera <[email protected]> wrote: > Maybe a good frame would be a TAP test that runs > REPACK/COPY/etc and then reads the debug output to see if the order of > phase switching is from A to B to C, and that block numbers in column > such-and-such are monotonically increasing within one phase, and that > they get back to 0 when changing to phase X, etc.
Michael Paquier <[email protected]> wrote: > To me, progress coverage should not just check one point in > time of the progress, but a succession of expected numbers. And this > does not have to involve concurrent activity. Here is a first version. 0005 is the framework; 0001-0004 fix four bugs it found the first time it ran over the regression suite. 0005 adds PROGRESS_DEBUG, a compile-time option in pg_config_manual.h. With it, backend_progress.c logs every change to a backend's progress state at LOG_SERVER_ONLY, and only changes: progress start: VACUUM relid=16384 progress update: VACUUM relid=16384 0:1->2 8:0->2 progress end: VACUUM relid=16384 One pgstat_progress_update_multi_param() call is one line, since readers see those values change together. Without the option the code is compiled out: backend_progress.c compiles to the same machine code as on master (compared with __LINE__ and __FILE__ fixed, 265 instructions). A new module, src/test/modules/test_progress, reads those lines back. Its ProgressCheck.pm replays each backend's trace and checks rules that hold for every command: each change starts from the last value logged, counters don't decrease or only go back to 0, done counters stay within their totals, phases take defined values, and a command only writes its own parameters. 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 succession of phases and of index_rebuild_count, and some final values. ProgressCheck.pm also describes every macro of commands/progress.h, and the test checks that against the header on every build, so a new parameter can't be added without saying what it is. Without PROGRESS_DEBUG that is all the test does: it doesn't start a server, so it costs nothing in other builds. Running make check with PROGRESS_DEBUG and ProgressCheck over the postmaster log (1.34 million changes from about 3,600 commands) found: 0001 blocks_done of an index build's heap scan was reported as blocks_total on the first block, then went back to 1. heapam_scan_get_blocks_done() took the wrap-around branch when the current block is the start block. Since ab0dfc961b6. 0002 When one command builds several indexes without progress for each (REPACK, CREATE INDEX on a partitioned table), each build started from the previous build's tuples_done, which could be above the new tuples_total. index_build() only reset the AM counters when reporting progress, since caec9d9fadf, while the AMs report them anyway. It now resets them in every build, but still sets the phase only when asked, so it keeps what 4b445479f9e fixed. 0003 num_dead_item_ids and dead_tuple_bytes are documented as collected since the last index vacuum cycle, but dead_items_reset() didn't report the reset, so the view kept the previous cycle's values until the next page with dead items. num_dead_tuples behaved the same way before 667e65aac35. 0004 A parallel GIN build ended with tuples_done one above tuples_total: the leader counted the last key's tuples again when flushing them. Since 8492feb98f6. With the four fixes, the same run has no violations. Removing any one of them from the series makes the test fail, only in the checks for that fix. I also checked the framework against the two bugs that 4b445479f9e and 0765b48874a fixed last week, by reverting each of them on top of the series. Without 4b445479f9e the test fails in every REPACK case, because index_rebuild_count starts at 2 and then goes back to 1. Without 0765b48874a, REPACK (CONCURRENTLY) fails because index_rebuild_count is never reported. With both reverted, each is still caught: the final count happens to be right in that case, which is why the test checks the succession rather than the last value. Some things the trace shows that I did not treat as bugs, and on which I'd like your opinion: - Parameters written while no command is active. Index AMs report their subphase and counts whether or not anyone asked. reindex_relation() sets REPACK's index_rebuild_count for its other callers too (TRUNCATE, REINDEX TABLE, and through finish_heap_swap() ALTER TABLE and REFRESH MATERIALIZED VIEW, for which finish_heap_swap() also sets REPACK's phase). And CREATE TABLE ... PARTITION OF and ATTACH PARTITION report a whole CREATE INDEX for the partition's index, phase and partitions_done included, without a command. Nothing reads the parameters then, so ProgressCheck only counts these writes. Should those callers stop writing, instead? - REINDEX CONCURRENTLY starts CREATE INDEX again for each index, with that index's table, which may be the TOAST table. ProgressCheck accepts a command restarting itself, and flags only a different command starting inside another one (which never happened). Open questions: 1. The option is a plain #define (CPPFLAGS=-DPROGRESS_DEBUG with configure, -Dc_args=-DPROGRESS_DEBUG with meson), and the test finds it in pg_config --cppflags or --cflags, or in pg_config_manual.h. Would you rather have a configure/meson option, like injection points? 2. The trace is large: make check writes a 182 MB log with the option against 3 MB without, and the tests took 2.6% longer in one run. 91% of the lines are tuples_done in index builds, which is updated once per tuple. That seems acceptable for an opt-in build, but runs of +1 of the same counter could be folded into one line if you think the size matters for a buildfarm animal. 3. ProgressCheck.pm lives in the module for now. If it's useful elsewhere, it could go in src/test/perl. With PROGRESS_DEBUG, check-world passes. The trace doesn't reach clients (LOG_SERVER_ONLY), and standalone backends don't emit it, since they log to their caller's stderr: initdb's test checks that it prints nothing there. Without the option, check-world passes as on master. The bugs fixed by 0001 and 0003 are in all supported branches, the one fixed by 0004 in 18 and later, and the one fixed by 0002 only in 19. I can post the fixes separately if that is easier. Regards, Manu
From f850779c908b8ef9afc4cbb41402e3c91853c845 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:59:40 -0300 Subject: [PATCH v1 4/5] 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 64629b672e79d4f34706e7d8314b1d96362f8c6b Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v1 5/5] 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 ff5827d48fb1ec0fc3909afa4bc98cf6f3fe1357 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v1 2/5] 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 c2f6239a34908bd7fc7ef59e3d46aa0458d4fc7a Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v1 3/5] 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 3462ca980c47d7bb6c93573e05f740eb3c89ded9 Mon Sep 17 00:00:00 2001 From: Manu <[email protected]> Date: Mon, 21 Sep 2026 20:53:25 -0300 Subject: [PATCH v1 1/5] 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
