public inbox for [email protected]
help / color / mirror / Atom feedFrom: RECHTÉ Marc <[email protected]>
To: [email protected]
Subject: Logical replication timeout
Date: Wed, 6 Nov 2024 07:36:51 +0000 (GMT)
Message-ID: <[email protected]> (raw)
Hello,
For some unknown reason (probably a very big transaction at the source), we experienced a logical decoding breakdown,
due to a timeout from the subscriber side (either wal_receiver_timeout or connexion drop by network equipment due to inactivity).
The problem is, that due to that failure, the wal_receiver process stops. When the wal_sender is ready to send some data, it finds the connexion broken and exits.
A new wal_sender process is created that restarts from the beginning (restart LSN). This is an endless loop.
Checking the network connexion between wal_sender and wal_receiver, we found that no traffic occurs for hours.
We first increased wal_receiver_timeout up to 12h and still got a disconnection on the receiver party:
2024-10-17 16:31:58.645 GMT [1356203:2] user=,db=,app=,client= ERROR: terminating logical replication worker due to timeout
2024-10-17 16:31:58.648 GMT [849296:212] user=,db=,app=,client= LOG: background worker "logical replication worker" (PID 1356203) exited with exit code 1
Then put this parameter to 0, but got then disconnected by the network (note the slight difference in message):
2024-10-21 11:45:42.867 GMT [1697787:2] user=,db=,app=,client= ERROR: could not receive data from WAL stream: could not receive data from server: Connection timed out
2024-10-21 11:45:42.869 GMT [849296:40860] user=,db=,app=,client= LOG: background worker "logical replication worker" (PID 1697787) exited with exit code 1
The message is generated in libpqrcv_receive function (replication/libpqwalreceiver/libpqwalreceiver.c) which calls pqsecure_raw_read (interfaces/libpq/fe-secure.c)
The last message "Connection timed out" is the errno translation from the recv system function:
ETIMEDOUT Connection timed out (POSIX.1-2001)
When those timeout occurred, the sender was still busy deleting files from data/pg_replslot/bdcpb21_sene, accumulating more than 6 millions small ".spill" files.
It seems this very long pause is at cleanup stage were PG is blindly trying to delete those files.
strace on wal sender show tons of calls like:
unlink("pg_replslot/bdcpb21_sene/xid-2 721 821 917-lsn-439C-0.spill") = -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-1000000.spill") = -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-2000000.spill") = -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-3000000.spill") = -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-4000000.spill") = -1 ENOENT (Aucun fichier ou dossier de ce type)
unlink("pg_replslot/bdcpb21_sene/xid-2721821917-lsn-439C-5000000.spill") = -1 ENOENT (Aucun fichier ou dossier de ce type)
This occurs in ReorderBufferRestoreCleanup (backend/replication/logical/reorderbuffer.c).
The call stack presumes this may probably occur in DecodeCommit or DecodeAbort (backend/replication/logical/decode.c):
unlink("pg_replslot/bdcpb21_sene/xid-2730444214-lsn-43A6-88000000.spill") = -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) [0x769e3d]
> /usr/pgsql-15/bin/postgres(ReorderBufferCleanupTXN+0x166) [0x76aec6] <=== replication/logical/reorderbuff.c:1480 (mais cette fonction (static) n'est utiliée qu'au sein de ce module ...)
> /usr/pgsql-15/bin/postgres(xact_decode+0x1e7) [0x75f217] <=== replication/logical/decode.c:175
> /usr/pgsql-15/bin/postgres(LogicalDecodingProcessRecord+0x73) [0x75eee3] <=== replication/logical/decode.c:90, appelle la fonction rmgr.rm_decode(ctx, &buf) = 1 des 6 méthodes 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]
We did not find any other option than deleting the subscription to stop that loop and start a new one (thus loosing transactions).
The publisher is PostgreSQL 15.6
The subscriber is PostgreSQL 14.5
Thanks
view thread (5+ messages) latest in thread
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected]
Subject: Re: Logical replication timeout
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox