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_test
VALUES (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_test
VALUES (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 of table
"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 of table
"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;
