Re: Add a perl function in Cluster.pm to generate WAL

Hello Bertrand,

08.01.2024 10:34, Bertrand Drouvot wrote:
> If one is able to reproduce, would it be possible to change the test and launch
> the vacuum in verbose mode? That way, we could see if this is somehow due to [1]
> (means something holding global xmin).

Yes, I've added (VERBOSE) and also cut down the test to catch the failure faster.
The difference between a successful and a failed run:
2024-01-08 11:58:30.679 UTC [668363] 035_standby_logical_decoding.pl INFO:  vacuuming "testdb.pg_catalog.pg_authid"
2024-01-08 11:58:30.679 UTC [668363] 035_standby_logical_decoding.pl INFO:  finished vacuuming 
"testdb.pg_catalog.pg_authid": index scans: 1
         pages: 0 removed, 1 remain, 1 scanned (100.00% of total)
         tuples: 1 removed, 15 remain, 0 are dead but not yet removable
         removable cutoff: 767, which was 0 XIDs old when operation ended
         new relfrozenxid: 767, which is 39 XIDs ahead of previous value
         frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
         index scan needed: 1 pages from table (100.00% of total) had 1 dead item identifiers removed
---
2024-01-08 12:00:59.903 UTC [669119] 035_standby_logical_decoding.pl LOG:  statement: VACUUM (VERBOSE) pg_authid;
2024-01-08 12:00:59.904 UTC [669119] 035_standby_logical_decoding.pl INFO:  vacuuming "testdb.pg_catalog.pg_authid"
2024-01-08 12:00:59.904 UTC [669119] 035_standby_logical_decoding.pl INFO:  finished vacuuming 
"testdb.pg_catalog.pg_authid": index scans: 0
         pages: 0 removed, 1 remain, 1 scanned (100.00% of total)
         tuples: 0 removed, 16 remain, 1 are dead but not yet removable
         removable cutoff: 766, which was 1 XIDs old when operation ended
         new relfrozenxid: 765, which is 37 XIDs ahead of previous value
         frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
         index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed

The difference in WAL is essentially the same as I observed before [1].
rmgr: Transaction len (rec/tot):     82/    82, tx:        766, lsn: 0/0403D418, prev 0/0403D3D8, desc: COMMIT 
2024-01-08 11:58:30.679035 UTC; inval msgs: catcache 11 catcache 10
rmgr: Heap2       len (rec/tot):     57/    57, tx:          0, lsn: 0/0403D470, prev 0/0403D418, desc: PRUNE 
snapshotConflictHorizon: 766, nredirected: 0, ndead: 1, isCatalogRel: T, nunused: 0, redirected: [], dead: [16],
unused:
 
[], blkref #0: rel 1664/0/1260 blk 0
rmgr: Btree       len (rec/tot):     52/    52, tx:          0, lsn: 0/0403D4B0, prev 0/0403D470, desc: VACUUM
ndeleted:
 
1, nupdated: 0, deleted: [1], updated: [], blkref #0: rel 1664/0/2676 blk 1
rmgr: Btree       len (rec/tot):     52/    52, tx:          0, lsn: 0/0403D4E8, prev 0/0403D4B0, desc: VACUUM
ndeleted:
 
1, nupdated: 0, deleted: [16], updated: [], blkref #0: rel 1664/0/2677 blk 1
rmgr: Heap2       len (rec/tot):     50/    50, tx:          0, lsn: 0/0403D520, prev 0/0403D4E8, desc: VACUUM nunused:

1, unused: [16], blkref #0: rel 1664/0/1260 blk 0
rmgr: Heap2       len (rec/tot):     64/  8256, tx:          0, lsn: 0/0403D558, prev 0/0403D520, desc: VISIBLE 
snapshotConflictHorizon: 0, flags: 0x07, blkref #0: rel 1664/0/1260 fork vm blk 0 FPW, blkref #1: rel 1664/0/1260 blk
0
rmgr: Heap        len (rec/tot):    225/   225, tx:          0, lsn: 0/0403F5B0, prev 0/0403D558, desc: INPLACE off:
26,
 
blkref #0: rel 1663/16384/16410 blk 4
vs
rmgr: Transaction len (rec/tot):     82/    82, tx:        766, lsn: 0/0403F480, prev 0/0403F440, desc: COMMIT 
2024-01-08 12:00:59.901582 UTC; inval msgs: catcache 11 catcache 10
rmgr: XLOG        len (rec/tot):     49/  8241, tx:          0, lsn: 0/0403F4D8, prev 0/0403F480, desc: FPI_FOR_HINT ,

blkref #0: rel 1664/0/1260 fork fsm blk 2 FPW
rmgr: XLOG        len (rec/tot):     49/  8241, tx:          0, lsn: 0/04041528, prev 0/0403F4D8, desc: FPI_FOR_HINT ,

blkref #0: rel 1664/0/1260 fork fsm blk 1 FPW
rmgr: XLOG        len (rec/tot):     49/  8241, tx:          0, lsn: 0/04043578, prev 0/04041528, desc: FPI_FOR_HINT ,

blkref #0: rel 1664/0/1260 fork fsm blk 0 FPW
rmgr: Heap        len (rec/tot):    225/   225, tx:          0, lsn: 0/040455C8, prev 0/04043578, desc: INPLACE off:
26,
 
blkref #0: rel 1663/16384/16410 blk 4

(Complete logs and the modified test are attached.)

With FREEZE, 10 iterations with 20 tests in parallel succeeded for me
(while without it, I get failures on iterations 1,2).

[1] https://www.postgresql.org/message-id/b2a1f7d0-7629-72c0-2da7-e9c4e336b010%40gmail.com

Best regards,
Alexander