019_replslot_limit.pl might fail due to checkpoint skipped - Mailing list pgsql-hackers

Hello hackers,

Investigating a recent buildfarm failure [1] with the following
diagnostics:
[12:27:41.437](0.024s) ok 18 - have walreceiver pid 637143
[12:30:42.564](181.127s) not ok 19 - walsender termination logged
[12:30:42.564](0.000s)
[12:30:42.564](0.000s) #   Failed test 'walsender termination logged'
#   at t/019_replslot_limit.pl line 382.

019_replslot_limit_primary3.log:
2024-12-13 12:27:40.912 ACDT [637093:7] LOG:  checkpoint starting: wal
...
2024-12-13 12:27:41.461 ACDT [637182:4] 019_replslot_limit.pl LOG: statement: SELECT pg_logical_emit_message(false, '',

'foo');
2024-12-13 12:27:41.462 ACDT [637182:5] 019_replslot_limit.pl LOG: statement: SELECT pg_switch_wal();
2024-12-13 12:27:41.463 ACDT [637182:6] 019_replslot_limit.pl LOG: disconnection: session time: 0:00:00.003 
user=postgres database=postgres host=[local]
2024-12-13 12:27:41.668 ACDT [637093:8] LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 1 
removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.756 s; sync files=0, longest=0.000 s, average=0.000 s; 
distance=1024 kB, estimate=1024 kB; lsn=0/900060, redo lsn=0/700028
2024-12-13 12:27:41.668 ACDT [637093:9] LOG:  checkpoints are occurring too frequently (1 second apart)
2024-12-13 12:27:41.668 ACDT [637093:10] HINT:  Consider increasing the configuration parameter "max_wal_size".
2024-12-13 12:30:42.565 ACDT [637144:10] standby_3 LOG:  terminating walsender process due to replication timeout
### waiting for walsender termination logged timed out after 3 minuts
2024-12-13 12:30:42.565 ACDT [637144:11] standby_3 STATEMENT: START_REPLICATION SLOT "rep3" 0/700000 TIMELINE 1
(note that checkpoint was started at 40.912 and completed at 41.668, i.e.,
it took 0.7 seconds)

I've found that such a failure can occur when the checkpoint, which should
invalidate replication slot (through the call chain: CreateCheckPoint() ->
InvalidateObsoleteReplicationSlots() -> InvalidatePossiblyObsoleteSlot()),
is skipped.

I've managed to reproduce this with the following sleep() added inside
src/backend/access/transam/xlog.c:
@@ -7126,6 +7126,11 @@ CreateCheckPoint(int flags)
          * panic. Accordingly, exit critical section while doing it.
          */
         END_CRIT_SECTION();
+if (rand() % 2 == 0)
+{
+elog(LOG, "!!!CreateCheckPoint| sleeping...");
+pg_usleep(1000000);
+}

When running just
make -s check -C src/test/recovery/ PROVE_TESTS="t/019*"
in a loop. I got failures on iterations 3, 4, 13, so with debug logging
enabled, I can see the following:
[12:57:41.899](0,009s) ok 18 - have walreceiver pid 509480
[13:00:44.862](182,963s) not ok 19 - walsender termination logged
[13:00:44.862](0,000s)
[13:00:44.862](0,000s) #   Failed test 'walsender termination logged'
#   at t/019_replslot_limit.pl line 382.

019_replslot_limit_primary3.log:
2024-12-17 12:57:41.695 UTC [][509460:11][checkpointer] LOG: checkpoints are occurring too frequently (0 seconds
apart)
2024-12-17 12:57:41.695 UTC [][509460:12][checkpointer] HINT: Consider increasing the configuration parameter 
"max_wal_size".
2024-12-17 12:57:41.695 UTC [][509460:13][checkpointer] LOG: checkpoint starting: wal
2024-12-17 12:57:41.695 UTC [][509460:14][checkpointer] LOG: !!!CreateCheckPoint| sleeping...
...
2024-12-17 12:57:41.903 UTC [][509460:15][checkpointer] DEBUG: performing replication slot checkpoint
...
2024-12-17 12:57:41.907 UTC [postgres][509495:5][client backend] [019_replslot_limit.pl] LOG:  statement: SELECT 
pg_logical_emit_message(false, '', 'foo');
2024-12-17 12:57:41.908 UTC [postgres][509495:6][client backend] [019_replslot_limit.pl] LOG:  statement: SELECT 
pg_switch_wal();
...
2024-12-17 12:57:41.947 UTC [][509460:16][checkpointer] DEBUG: snapshot of 0+0 running transaction ids (lsn 0/C00060 
oldest xid 742 latest complete 741 next xid 742)
2024-12-17 12:57:41.947 UTC [][509460:17][checkpointer] DEBUG: attempting to remove WAL segments older than log file 
000000000000000000000009
2024-12-17 12:57:41.947 UTC [][509460:18][checkpointer] DEBUG: removing write-ahead log file
"000000010000000000000009"
2024-12-17 12:57:41.948 UTC [][509460:19][checkpointer] DEBUG: SlruScanDirectory invoking callback on pg_subtrans/0000
2024-12-17 12:57:41.948 UTC [][509460:20][checkpointer] LOG: checkpoint complete: wrote 0 buffers (0.0%), wrote 0 SLRU

buffers; 0 WAL file(s) added, 1 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.253 s; sync files=0, 
longest=0.000 s, average=0.000 s; distance=1024 kB, estimate=1024 kB; lsn=0/C00060, redo lsn=0/A00028
     ### the checkpoint, that started before pg_switch_wal(), is completed
2024-12-17 12:57:41.948 UTC [][509460:21][checkpointer] LOG: checkpoints are occurring too frequently (0 seconds
apart)
2024-12-17 12:57:41.948 UTC [][509460:22][checkpointer] HINT: Consider increasing the configuration parameter 
"max_wal_size".
2024-12-17 12:57:41.948 UTC [][509460:23][checkpointer] DEBUG: checkpoint skipped because system is idle
     ### the checkpoint, which expected to invalidate the replication slot after pg_switch_wal, is skipped

Reproduced starting from commit 24043c27b (dated 2021-07-23), which added
this test case.

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=alligator&dt=2024-12-13%2001%3A24%3A58

Best regards,
Alexander