Re: pgsql: Test replay of regression tests, attempt II. - Mailing list pgsql-committers

Hi,

On 2022-01-20 17:23:30 +1300, Thomas Munro wrote:
> Having failed to reproduce this locally, I clicked on "re-run tests"
> all afternoon on CI until eventually I captured a failure log[1]
> there, with the smoking gun:

Phew, finally.


> Since this page doesn't require wraparound vacuuming, if we fail to
> conditionally acquire the cleanup lock, this block skips the page.

The most likely source for such a pin is bgwriter, I think?

It's not actually *immediately* obviously why the page doesn't require
wraparound, as VACUUM FREEZE should use a very aggressive one. The reason is
presumably that there are concurrent backends holding back the horizon. Note
that the oldest xmin in the log below (15356 for both vacuums) is older than
the xids from the intentionally failed insert (15465).

I wonder if the easiest way to make this test reliable would be to make the
table a temporary one? That now uses very aggressive horizons, there's no
bgwriter that could pin the page, etc.

Regards,

Andres


2022-01-20 03:58:31.966 UTC [32584][client backend] [pg_regress/reloptions][4/5416:0] LOG:  statement: INSERT INTO
reloptions_testVALUES (1, NULL), (NULL, NULL);
 
2022-01-20 03:58:31.967 UTC [32584][client backend] [pg_regress/reloptions][4/5416:15465] ERROR:  null value in column
"i"of relation "reloptions_test" violates not-null constraint
 
2022-01-20 03:58:31.967 UTC [32584][client backend] [pg_regress/reloptions][4/5416:15465] DETAIL:  Failing row contains
(null,null).
 
2022-01-20 03:58:31.967 UTC [32584][client backend] [pg_regress/reloptions][4/5416:15465] STATEMENT:  INSERT INTO
reloptions_testVALUES (1, NULL), (NULL, NULL);
 

2022-01-20 03:58:31.970 UTC [32584][client backend] [pg_regress/reloptions][4/5417:0] LOG:  statement: VACUUM (FREEZE,
DISABLE_PAGE_SKIPPING)reloptions_test;
 
2022-01-20 03:58:31.973 UTC [32584][client backend] [pg_regress/reloptions][4/5418:0] LOG:  automatic aggressive vacuum
oftable "regression.public.reloptions_test": index scans: 0
 
    pages: 0 removed, 1 remain, 1 skipped due to pins, 0 skipped frozen
    tuples: 0 removed, 0 remain, 0 are dead but not yet removable, oldest xmin: 15356
    index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed
    avg read rate: 372.024 MB/s, avg write rate: 0.000 MB/s
    buffer usage: 3 hits, 6 misses, 0 dirtied
    WAL usage: 1 records, 0 full page images, 237 bytes
    system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2022-01-20 03:58:31.973 UTC [32584][client backend] [pg_regress/reloptions][4/5418:0] STATEMENT:  VACUUM (FREEZE,
DISABLE_PAGE_SKIPPING)reloptions_test;
 
2022-01-20 03:58:31.973 UTC [32584][client backend] [pg_regress/reloptions][4/5419:0] LOG:  automatic aggressive vacuum
oftable "regression.pg_toast.pg_toast_35786": index scans: 0
 
    pages: 0 removed, 0 remain, 0 skipped due to pins, 0 skipped frozen
    tuples: 0 removed, 0 remain, 0 are dead but not yet removable, oldest xmin: 15356
    avg read rate: 790.028 MB/s, avg write rate: 0.000 MB/s
    buffer usage: 13 hits, 9 misses, 0 dirtied
    WAL usage: 0 records, 0 full page images, 0 bytes
    system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2022-01-20 03:58:31.973 UTC [32584][client backend] [pg_regress/reloptions][4/5419:0] STATEMENT:  VACUUM (FREEZE,
DISABLE_PAGE_SKIPPING)reloptions_test;