Received: from malur.postgresql.org ([217.196.149.56])
	by arkaria.postgresql.org with esmtps  (TLS1.3) tls
 TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
	(Exim 4.94.2)
	(envelope-from <pgsql-committers-owner+archive@lists.postgresql.org>)
	id 1uSlCK-00CjFu-Bn
	for pgsql-committers@arkaria.postgresql.org; Fri, 20 Jun 2025 23:31:04 +0000
Received: from localhost ([127.0.0.1] helo=malur.postgresql.org)
	by malur.postgresql.org with esmtp (Exim 4.94.2)
	(envelope-from <pgsql-committers-owner+archive@lists.postgresql.org>)
	id 1uSlCI-004siI-BO
	for pgsql-committers@arkaria.postgresql.org; Fri, 20 Jun 2025 23:31:02 +0000
Received: from makus.postgresql.org ([2001:4800:3e1:1::229])
	by malur.postgresql.org with esmtps  (TLS1.3) tls
 TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
	(Exim 4.94.2)
	(envelope-from <tgl@sss.pgh.pa.us>)
	id 1uSlCI-004si9-48
	for pgsql-committers@lists.postgresql.org; Fri, 20 Jun 2025 23:31:02 +0000
Received: from sss.pgh.pa.us ([68.162.161.243])
	by makus.postgresql.org with esmtps  (TLS1.3) tls
 TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
	(Exim 4.96)
	(envelope-from <tgl@sss.pgh.pa.us>)
	id 1uSlCG-0038Mm-1t
	for pgsql-committers@lists.postgresql.org;
	Fri, 20 Jun 2025 23:31:01 +0000
Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1])
	by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 55KNUwjj2593442;
	Fri, 20 Jun 2025 19:30:58 -0400
From: Tom Lane <tgl@sss.pgh.pa.us>
To: Alexander Korotkov <aekorotkov@gmail.com>
cc: Melanie Plageman <melanieplageman@gmail.com>,
        pgsql-committers@lists.postgresql.org
Subject: Re: pgsql: Improve runtime and output of tests for replication slots
 checkp
In-reply-to: 
 <CAPpHfdsedYNmKDnDuueJor2k8kA+hgEJKFJRf4PhDowdP_A4Bg@mail.gmail.com>
References: <E1uSOip-002TUa-0p@gemulon.postgresql.org>
 <CAAKRu_ZCOzQpEumLFgG_+iw3FTa+hJ4SRpxzaQBYxxM_ZAzWcA@mail.gmail.com>
 <2542023.1750456985@sss.pgh.pa.us> <2585993.1750458298@sss.pgh.pa.us>
 <CAPpHfdsedYNmKDnDuueJor2k8kA+hgEJKFJRf4PhDowdP_A4Bg@mail.gmail.com>
Comments: In-reply-to Alexander Korotkov <aekorotkov@gmail.com>
	message dated "Sat, 21 Jun 2025 01:40:46 +0300"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <2593440.1750462258.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Fri, 20 Jun 2025 19:30:58 -0400
Message-ID: <2593441.1750462258@sss.pgh.pa.us>
List-Id: <pgsql-committers.lists.postgresql.org>
List-Help: <https://lists.postgresql.org/manage/>
List-Subscribe: <https://lists.postgresql.org/manage/>
List-Post: <mailto:pgsql-committers@lists.postgresql.org>
List-Owner: <mailto:pgsql-committers-owner@lists.postgresql.org>
List-Archive: <https://www.postgresql.org/list/pgsql-committers>
Archived-At: 
 <https://www.postgresql.org/message-id/2593441.1750462258%40sss.pgh.pa.us>
Precedence: bulk

Alexander Korotkov <aekorotkov@gmail.com> writes:
> I think this indicates unfinished intention to wait for checkpoint
> completion.  But I think both cases (checkpoint finished and
> unfinished) should work correctly.  So, I believe there is a backend
> problem.  I'm trying to reproduce this locally.  Sorry for the
> confusion.

I've found it not hugely difficult to reproduce: on two different
Mac M4 machines, repeated runs of 046_checkpoint_logical_slot.pl
hung up after 30 or so tries.  Backtrace of the stuck query
looks like

 (lldb) bt
* thread #1, queue =3D 'com.apple.main-thread', stop reason =3D signal SIG=
STOP
  * frame #0: 0x00000001836b01c8 libsystem_kernel.dylib`__semwait_signal +=
 8
    frame #1: 0x000000018358c6f4 libsystem_c.dylib`nanosleep + 220
    frame #2: 0x000000010070d358 postgres`pg_usleep(microsec=3D1000) at pg=
sleep.c:50:10 [opt]
    frame #3: 0x00000001002a0508 postgres`read_local_xlog_page_guts(state=3D=
0x0000000126057298, targetPagePtr=3D687882240, reqLen=3D277, targetRecPtr=3D=
<unavailable>, cur_page=3D"\U00000018\xd1\U00000005", wait_for_wal=3Dtrue)=
 at xlogutils.c:950:4 [opt]
    frame #4: 0x0000000100298f0c postgres`ReadPageInternal(state=3D0x00000=
00126057298, pageptr=3D687882240, reqLen=3D277) at xlogreader.c:1061:12 [o=
pt]
    frame #5: 0x0000000100298300 postgres`XLogReadAhead [inlined] XLogDeco=
deNextRecord(state=3D0x0000000126057298, nonblocking=3D<unavailable>) at x=
logreader.c:727:14 [opt]
    frame #6: 0x00000001002980b4 postgres`XLogReadAhead(state=3D0x00000001=
26057298, nonblocking=3Dfalse) at xlogreader.c:974:11 [opt]
    frame #7: 0x0000000100297fd4 postgres`XLogReadRecord(state=3D0x0000000=
126057298, errormsg=3D0x000000016fc24d08) at xlogreader.c:405:3 [opt]
    frame #8: 0x00000001004ee514 postgres`pg_logical_slot_get_changes_guts=
(fcinfo=3D<unavailable>, confirm=3Dtrue, binary=3D<unavailable>) at logica=
lfuncs.c:257:13 [opt]
    frame #9: 0x00000001004ee1e8 postgres`pg_logical_slot_get_changes(fcin=
fo=3D<unavailable>) at logicalfuncs.c:333:9 [opt]
    frame #10: 0x00000001003a77ec postgres`ExecMakeTableFunctionResult(set=
expr=3D0x000000012603da40, econtext=3D<unavailable>, argContext=3D<unavail=
able>, expectedDesc=3D0x00000001260472b0, randomAccess=3Dfalse) at execSRF=
.c:234:13 [opt]
    frame #11: 0x00000001003ba02c postgres`FunctionNext(node=3D0x000000012=
603d6d0) at nodeFunctionscan.c:94:5 [opt]
    frame #12: 0x00000001003b4894 postgres`fetch_input_tuple [inlined] Exe=
cProcNode(node=3D0x000000012603d6d0) at executor.h:313:9 [opt]
    frame #13: 0x00000001003b4878 postgres`fetch_input_tuple(aggstate=3D0x=
000000012603cf28) at nodeAgg.c:563:10 [opt]
    frame #14: 0x00000001003b2eb4 postgres`ExecAgg [inlined] agg_retrieve_=
direct(aggstate=3D0x000000012603cf28) at nodeAgg.c:2450:17 [opt]
    frame #15: 0x00000001003b2ab8 postgres`ExecAgg(pstate=3D0x000000012603=
cf28) at nodeAgg.c:2265:14 [opt]

so apparently it's waiting patiently for WAL that will never appear.
(I do see the 'checkpoint complete' log message before the shutdown
in this particular run.)  I still have this debugger session open
if there's any particular data you'd like me to look at.

			regards, tom lane