From: Tom Lane <tgl@sss.pgh.pa.us>
To: Melanie Plageman <melanieplageman@gmail.com>
cc: Alexander Korotkov <akorotkov@postgresql.org>,
        pgsql-committers@lists.postgresql.org
Subject: Re: pgsql: Improve runtime and output of tests for replication slots
 checkp
In-reply-to: 
 <CAAKRu_ZCOzQpEumLFgG_+iw3FTa+hJ4SRpxzaQBYxxM_ZAzWcA@mail.gmail.com>
References: <E1uSOip-002TUa-0p@gemulon.postgresql.org>
 <CAAKRu_ZCOzQpEumLFgG_+iw3FTa+hJ4SRpxzaQBYxxM_ZAzWcA@mail.gmail.com>
Comments: In-reply-to Melanie Plageman <melanieplageman@gmail.com>
	message dated "Fri, 20 Jun 2025 12:10:07 -0400"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <2542022.1750456985.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Fri, 20 Jun 2025 18:03:05 -0400
Message-ID: <2542023.1750456985@sss.pgh.pa.us>
Archived-At: 
 <https://www.postgresql.org/message-id/2542023.1750456985%40sss.pgh.pa.us>
Precedence: bulk

Melanie Plageman <melanieplageman@gmail.com> writes:
> Quite a few animals have started failing since this commit (for example
> [1]) . I haven't looked into why, but I suspect something is wrong.

It looks to me like it's being triggered by this questionable bit in =

046_checkpoint_logical_slot.pl:

# Continue the checkpoint.
$node->safe_psql('postgres',
	q{select injection_points_wakeup('checkpoint-before-old-wal-removal')});

# Abruptly stop the server (1 second should be enough for the checkpoint
# to finish; it would be better).
$node->stop('immediate');

That second comment is pretty unintelligible, but I think it's
expecting that we'd give the checkpoint 1 second to complete,
which the code is *not* doing.  On my own machine it looks like the
checkpoint does manage to complete within about 1ms, just barely
before the shutdown arrives:

2025-06-20 17:52:25.599 EDT [2538690] 046_checkpoint_logical_slot.pl LOG: =
 statement: select pg_replication_slot_advance('slot_physical', pg_current=
_wal_lsn())
2025-06-20 17:52:25.602 EDT [2538692] 046_checkpoint_logical_slot.pl LOG: =
 statement: select injection_points_wakeup('checkpoint-before-old-wal-remo=
val')
2025-06-20 17:52:25.603 EDT [2538557] LOG:  checkpoint complete: wrote 1 b=
uffers (0.0%), wrote 0 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 rec=
ycled; write=3D0.003 s, sync=3D0.001 s, total=3D1.074 s; sync files=3D0, l=
ongest=3D0.000 s, average=3D0.000 s; distance=3D327688 kB, estimate=3D3276=
88 kB; lsn=3D0/290020C0, redo lsn=3D0/29002068
2025-06-20 17:52:25.604 EDT [2538553] LOG:  received immediate shutdown re=
quest

But in the buildfarm failures I don't see any 'checkpoint complete'
before the shutdown.

If this is an accurate diagnosis then it indicates both a test bug
(it should delay here, or else the comment needs fixed to explain
what we're actually testing) and a backend bug, because an immediate
stop a/k/a crash before completing the checkpoint should not lead to
failure to function after the next restart.

			regards, tom lane