Re: Add a test for index_rebuild_count of REPACK (CONCURRENTLY)

Hi Álvaro, Michael,

Álvaro Herrera <alvherre(at)kurilemu(dot)de> 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 <michael(at)paquier(dot)xyz> 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