Date: Wed, 13 Nov 2024 08:00:46 +0000 (GMT)
From: =?utf-8?Q?RECHT=C3=89?= Marc <marc.rechte@meteo.fr>
To: pgsql-bugs@lists.postgresql.org
Message-ID: <1430556325.185731745.1731484846410.JavaMail.zimbra@meteo.fr>
Subject: Very long loop breaking logical replication walsender / walreceiver
 connection
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
Thread-Index: jPJaTQPJoigmFXkhL07k7/bCbTU7jA==
Thread-Topic: Very long loop breaking logical replication walsender /
 walreceiver connection
Archived-At: 
 <https://www.postgresql.org/message-id/1430556325.185731745.1731484846410.JavaMail.zimbra%40meteo.fr>
Precedence: bulk

For some unknown reason (probably a very big transaction at the source), we=
 experienced a logical decoding breakdown,=20
due to a timeout from the subscriber side (either wal_receiver_timeout or c=
onnexion drop by network equipment due to inactivity).

When those timeout occurred (more than 12 hours), the sender was still busy=
 deleting files from data/pg_replslot/bdcpb21_sene,
accumulating more than *6 millions* small ".spill" files.

strace on wal sender showed tons of calls like:

unlink("pg_replslot/bdcpb21_sene/xid-2 721 821 917-lsn-439C-0.spill") =3D -=
1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-1000000.spill") =
=3D -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-2000000.spill") =
=3D -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-3000000.spill") =
=3D -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-4000000.spill") =
=3D -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-5000000.spill") =
=3D -1 ENOENT (Aucun fichier ou dossier de ce type)

This occurs in ReorderBufferRestoreCleanup (backend/replication/logical/reo=
rderbuffer.c).=20
The call stack presumes this may probably occur in DecodeCommit or DecodeAb=
ort (backend/replication/logical/decode.c):

unlink("pg_replslot/bdcpb21_sene/xid-2730444214-lsn-43A6-88000000.spill") =
=3D -1 ENOENT (Aucun fichier ou dossier de ce type)
 > /usr/lib64/libc-2.17.so(unlink+0x7) [0xf12e7]
 > /usr/pgsql-15/bin/postgres(ReorderBufferRestoreCleanup.isra.17+0x5d) [0x=
769e3d]
 > /usr/pgsql-15/bin/postgres(ReorderBufferCleanupTXN+0x166) [0x76aec6] <=
=3D=3D=3D replication/logical/reorderbuff.c:1480 (mais cette fonction (stat=
ic) n'est utili=C3=A9e qu'au sein de ce module ...)
 > /usr/pgsql-15/bin/postgres(xact_decode+0x1e7) [0x75f217] <=3D=3D=3D repl=
ication/logical/decode.c:175=20
 > /usr/pgsql-15/bin/postgres(LogicalDecodingProcessRecord+0x73) [0x75eee3]=
 <=3D=3D=3D replication/logical/decode.c:90, appelle la fonction rmgr.rm_de=
code(ctx, &buf) =3D 1 des 6 m=C3=A9thodes du resource manager
 > /usr/pgsql-15/bin/postgres(XLogSendLogical+0x4e) [0x78294e]
 > /usr/pgsql-15/bin/postgres(WalSndLoop+0x151) [0x785121]
 > /usr/pgsql-15/bin/postgres(exec_replication_command+0xcba) [0x785f4a]
 > /usr/pgsql-15/bin/postgres(PostgresMain+0xfa8) [0x7d0588]
 > /usr/pgsql-15/bin/postgres(ServerLoop+0xa8a) [0x493b97]
 > /usr/pgsql-15/bin/postgres(PostmasterMain+0xe6c) [0x74d66c]
 > /usr/pgsql-15/bin/postgres(main+0x1c5) [0x494a05]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf4) [0x22554]
 > /usr/pgsql-15/bin/postgres(_start+0x28) [0x494fb8]

There are 2 problems in ReorderBufferRestoreCleanup (backend/replication/lo=
gical/reorderbuffer.c:4562):

1) rb->update_progress_txn may be called periodically to avoid the connecti=
on to break
2) find a more effiiecent way to delete files blindly (using scandir with a=
 filter on the TXID base name)

See also https://www.postgresql.org/message-id/638764862.181008636.17308786=
11279.JavaMail.zimbra%40meteo.fr