Re: Progress reporting: a debug trace and a test framework

Hi,

Using v5 I found two problems with it: with PROGRESS_DEBUG compiled
in, a check-world wrote 1.8 GB of server logs (master: 70 MB), and,
reverting each progress fix committed this year, it caught only four
of the ten. v6, attached and rebased on master, fixes both: 135 MB,
the extra 65 MB being test_progress's own trace, and nine of the ten.

Changes since v5: a trace_progress developer option; a check that a
command has ended when its process goes idle; each parameter checked
by value or listed with the reason; commands failing part of the way;
and the whole succession of each counter and phase checked, in more
scenarios: parallel builds, CREATE INDEX CONCURRENTLY waiting for
writers and snapshots, REPACK (CONCURRENTLY) applying changes, VACUUM
in failsafe mode, autovacuum.

The trace is written only where it is read: trace_progress turns it
on, as trace_syncscan does for TRACE_SYNCSCAN, and test_progress sets
it for its nodes. Álvaro, you thought a compile option was enough; it
still is what puts the code in, and trace_progress only keeps the
trace out of every other test's log. Without PROGRESS_DEBUG the
object code has the same instructions as master's, and meson test
takes as long: 84.9 s against 84.2 s, median of five paired rounds, a
difference within the noise. With the option it takes 7 s more,
test_progress's scenarios (10 s alone).

The checks new since v5 catch 99ea4a55270, 4dd037286e0, cedd2cec7d5,
422e54e3092 and 55f0a13e96b. I wrote them knowing those fixes, so
they show the fixes would hold, not that they would have been found.
To see what it finds beyond those, I mutated every progress call of
the backend blindly: 572 mutants. Of a sample of 150 fixed
beforehand, today's tests catch 10. test_progress now catches 548 of
the 572, but the new checks were written against them; the number
that counts is a reserve of 301 more mutants, of other kinds, sealed
before and not looked at until the end: it catches 285 (94.7%). Of
the 16 left, 4 are gaps a check could close; they and the rest are
listed with the reason in nocfbot-mutation-benchmark.txt, and the
numbers are in measurements.txt.

The sweep of check-world with the trace on also found one that is
still on master: WaitForOlderSnapshots() leaves the PROGRESS_WAITFOR_*
values set when it returns, which WaitForLockersMultiple() resets, so
REINDEX CONCURRENTLY's wait for readers shows lockers_done 2 with
lockers_total 1 (repro-waitfor.sh.txt, on any build). It also flags
ANALYZE of a file_fdw table, whose COPY report takes over ANALYZE's;
Antonin's sub-command patch (CF 6958) is about that.

One detail the benchmark showed: PROGRESS_DATACHECKSUMS_PHASE_ENABLING
is 0, the value every parameter starts with, so neither the trace nor
the view can tell when that phase is set.

Regards,
Manu