From 64629b672e79d4f34706e7d8314b1d96362f8c6b Mon Sep 17 00:00:00 2001 From: Manu 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: relid= + * progress update: relid= :-> ... + * progress end: relid= + * + * 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 _* 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