Thread

Unusually long checkpoint time on version 16, and 17beta1 running in a docker container

Dave Cramer <davecramer@gmail.com> — 2024-06-24T19:44:25Z

Greetings,

While testing pgjdbc I noticed the following

pgdb-1  | Will execute command on database postgres:
pgdb-1  |         SELECT pg_drop_replication_slot(slot_name) FROM
pg_replication_slots WHERE slot_name = 'replica_one';
pgdb-1  |         DROP USER IF EXISTS replica_one;
pgdb-1  |         CREATE USER replica_one WITH REPLICATION PASSWORD 'test';
pgdb-1  |         SELECT * FROM
pg_create_physical_replication_slot('replica_one');
pgdb-1  |
pgdb-1  | NOTICE:  role "replica_one" does not exist, skipping
pgdb-1  |  pg_drop_replication_slot
pgdb-1  | --------------------------
pgdb-1  | (0 rows)
pgdb-1  |
pgdb-1  | DROP ROLE
pgdb-1  | CREATE ROLE
pgdb-1  |   slot_name  | lsn
pgdb-1  | -------------+-----
pgdb-1  |  replica_one |
pgdb-1  | (1 row)
pgdb-1  |
pgdb-1  | waiting for checkpoint
pgdb-1  | 2024-06-24 19:07:18.569 UTC [66] LOG:  checkpoint starting: force
wait
pgdb-1  | 2024-06-24 19:11:48.008 UTC [66] LOG:  checkpoint complete: wrote
6431 buffers (39.3%); 0 WAL file(s) added, 0 removed, 3 recycled;
write=269.438 s, sync=0.001 s, total=269.439 s; sync files=0, longest=0.000
s, average=0.000 s; distance=44140 kB, estimate=44140 kB; lsn=0/40000B8,
redo lsn=0/4000028


Note that it takes 4 minutes 48 seconds to do the checkpoint. This seems
ridiculously long ?

If I add a checkpoint before doing anything there is no delay

 Will execute command on database postgres:
pgdb-1  |         checkpoint;
pgdb-1  |         SELECT pg_drop_replication_slot(slot_name) FROM
pg_replication_slots WHERE slot_name = 'replica_one';
pgdb-1  |         DROP USER IF EXISTS replica_one;
pgdb-1  |         CREATE USER replica_one WITH REPLICATION PASSWORD 'test';
pgdb-1  |         SELECT * FROM
pg_create_physical_replication_slot('replica_one');
pgdb-1  |
pgdb-1  | 2024-06-24 19:19:57.498 UTC [66] LOG:  checkpoint starting:
immediate force wait
pgdb-1  | 2024-06-24 19:19:57.558 UTC [66] LOG:  checkpoint complete: wrote
6431 buffers (39.3%); 0 WAL file(s) added, 0 removed, 2 recycled;
write=0.060 s, sync=0.001 s, total=0.061 s; sync files=0, longest=0.000 s,
average=0.000 s; distance=29947 kB, estimate=29947 kB; lsn=0/3223BA0, redo
lsn=0/3223B48
===> pgdb-1  | CHECKPOINT
pgdb-1  |  pg_drop_replication_slot
pgdb-1  | --------------------------
pgdb-1  | (0 rows)
pgdb-1  |
pgdb-1  | DROP ROLE
pgdb-1  | NOTICE:  role "replica_one" does not exist, skipping
pgdb-1  | CREATE ROLE
pgdb-1  |   slot_name  | lsn
pgdb-1  | -------------+-----
pgdb-1  |  replica_one |
pgdb-1  | (1 row)
pgdb-1  |
pgdb-1  | waiting for checkpoint
pgdb-1  | 2024-06-24 19:19:57.614 UTC [66] LOG:  checkpoint starting: force
wait
pgdb-1  | 2024-06-24 19:19:57.915 UTC [66] LOG:  checkpoint complete: wrote
4 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.301
s, sync=0.001 s, total=0.302 s; sync files=0, longest=0.000 s,
average=0.000 s; distance=14193 kB, estimate=28372 kB; lsn=0/4000080, redo
lsn=0/4000028

This starts in version 16, versions up to and including 15 do not impose
the wait.


Dave Cramer