From: Noah Misch <noah@leadboat.com>
To: pgsql-hackers@postgresql.org
Subject: wal_sender_timeout should ignore server-side latency
Date: Sat, 25 Aug 2018 20:46:00 -0700
Message-ID: <20180826034600.GA1105084@rfd.leadboat.com> (raw)
WalSndLoop() does this, simplifying considerably:
for (;;)
{
/* does: last_reply_timestamp = GetCurrentTimestamp() */
ProcessRepliesIfAny();
send_data(); /* e.g. XLogSendPhysical(), which calls XLogRead() */
WalSndCheckTimeOut(GetCurrentTimestamp());
}
A consequence is that any time spent in the send_data() callback counts
against the timeout. In particular, if a single send_data() takes longer than
wal_sender_timeout, the client is powerless to prevent a timeout. This
disagrees with the wal_sender_timeout documentation ("Terminate replication
connections that are inactive longer than the specified number of
milliseconds. This is useful for the sending server to detect a standby crash
or network outage"). I find it undesirable.
The fix, attached, is to interpret the timeout relative to a timestamp taken
before ProcessRepliesIfAny() polls the socket. If that timestamp is
wal_sender_timeout later than the last reply, we can terminate with
confidence. This adds one gettimeofday() per ProcessRepliesIfAny() finding no
replies, which feels cheap enough.
We've seen a number of wal_sender_timeout buildfarm failures on systems with
I/O performance trouble:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tern&dt=2018-08-16%2020:55:57https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tern&dt=2018-06-30%2020:38:10https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hornet&dt=2018-04-12%2018:12:36https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=mandrill&dt=2018-01-13%2005:01:17https://postgr.es/m/flat/20170604211229.GA1528911@rfd.leadboat.com
Fixing $SUBJECT won't necessarily cure that, because an I/O stall on the
client side can still cause a failure. We'd need something like threads or
async I/O to avoid that. I mention a less-important corner case in the
WalSndCheckTimeOut() header comment. You can simulate slow XLogSendPhysical()
to explore these problems on any system:
inline patch 1: src/backend/replication/walsender.c (+4/-0 lines) download inline-1.patch--- a/src/backend/replication/walsender.c+++ b/src/backend/replication/walsender.c@@ -65,2 +65,3 @@
#include "libpq/pqformat.h"
+#include "libpq/pqsignal.h"
#include "miscadmin.h"
@@ -2731,2 +2732,5 @@ XLogSendPhysical(void)
enlargeStringInfo(&output_message, nbytes);
+ PG_SETMASK(&BlockSig);+ pg_usleep(65 * 1000 * 1000);+ PG_SETMASK(&UnBlockSig);
XLogRead(&output_message.data[output_message.len], startptr, nbytes);
Patches and attachments:download all (2 files, .tar.gz)wal_sender_timeout-server-independent-v1.patch (text/plain, 6.3K) downloaddiff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.cindex c83ff3b..3e51cf3 100644--- a/src/backend/replication/walsender.c+++ b/src/backend/replication/walsender.c@@ -161,9 +161,12 @@ static StringInfoData output_message;
static StringInfoData reply_message;
static StringInfoData tmpbuf;
+/* Timestamp of last ProcessRepliesIfAny(). */+static TimestampTz last_processing = 0;+
/*
- * Timestamp of the last receipt of the reply from the standby. Set to 0 if- * wal_sender_timeout doesn't need to be active.+ * Timestamp of last ProcessRepliesIfAny() that saw a reply from the+ * standby. Set to 0 if wal_sender_timeout doesn't need to be active.
*/
static TimestampTz last_reply_timestamp = 0;
@@ -240,8 +243,8 @@ static void ProcessStandbyReplyMessage(void);
static void ProcessStandbyHSFeedbackMessage(void);
static void ProcessRepliesIfAny(void);
static void WalSndKeepalive(bool requestReply);
-static void WalSndKeepaliveIfNecessary(TimestampTz now);-static void WalSndCheckTimeOut(TimestampTz now);+static void WalSndKeepaliveIfNecessary(void);+static void WalSndCheckTimeOut(void);
static long WalSndComputeSleeptime(TimestampTz now);
static void WalSndPrepareWrite(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid, bool last_write);
static void WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid, bool last_write);
@@ -1202,18 +1205,16 @@ WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid,
/* Check for input from the client */
ProcessRepliesIfAny();
- now = GetCurrentTimestamp();-
/* die if timeout was reached */
- WalSndCheckTimeOut(now);+ WalSndCheckTimeOut();
/* Send keepalive if the time has come */
- WalSndKeepaliveIfNecessary(now);+ WalSndKeepaliveIfNecessary();
if (!pq_is_send_pending())
break;
- sleeptime = WalSndComputeSleeptime(now);+ sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
wakeEvents = WL_LATCH_SET | WL_POSTMASTER_DEATH |
WL_SOCKET_WRITEABLE | WL_SOCKET_READABLE | WL_TIMEOUT;
@@ -1308,7 +1309,6 @@ WalSndWaitForWal(XLogRecPtr loc)
for (;;)
{
long sleeptime;
- TimestampTz now;
/*
* Emergency bailout if postmaster has died. This is to avoid the
@@ -1393,13 +1393,11 @@ WalSndWaitForWal(XLogRecPtr loc)
!pq_is_send_pending())
break;
- now = GetCurrentTimestamp();-
/* die if timeout was reached */
- WalSndCheckTimeOut(now);+ WalSndCheckTimeOut();
/* Send keepalive if the time has come */
- WalSndKeepaliveIfNecessary(now);+ WalSndKeepaliveIfNecessary();
/*
* Sleep until something happens or we time out. Also wait for the
@@ -1408,7 +1406,7 @@ WalSndWaitForWal(XLogRecPtr loc)
* new WAL to be generated. (But if we have nothing to send, we don't
* want to wake on socket-writable.)
*/
- sleeptime = WalSndComputeSleeptime(now);+ sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
wakeEvents = WL_LATCH_SET | WL_POSTMASTER_DEATH |
WL_SOCKET_READABLE | WL_TIMEOUT;
@@ -1605,6 +1603,8 @@ ProcessRepliesIfAny(void)
int r;
bool received = false;
+ last_processing = GetCurrentTimestamp();+
for (;;)
{
pq_startmsgread();
@@ -1692,7 +1692,7 @@ ProcessRepliesIfAny(void)
*/
if (received)
{
- last_reply_timestamp = GetCurrentTimestamp();+ last_reply_timestamp = last_processing;
waiting_for_ping_response = false;
}
}
@@ -2071,10 +2071,18 @@ WalSndComputeSleeptime(TimestampTz now)
/*
* Check whether there have been responses by the client within
- * wal_sender_timeout and shutdown if not.+ * wal_sender_timeout and shutdown if not. Using last_processing as the+ * reference point avoids counting server-side stalls against the client.+ * However, a long server-side stall can make WalSndKeepaliveIfNecessary()+ * postdate last_processing by more than wal_sender_timeout. If that happens,+ * the client must reply almost immediately to avoid a timeout. This rarely+ * affects the default configuration, under which clients spontaneously send a+ * message every standby_message_timeout = wal_sender_timeout/6 = 10s. We+ * could eliminate that problem by recognizing timeout expiration at+ * wal_sender_timeout/2 after the keepalive.
*/
static void
-WalSndCheckTimeOut(TimestampTz now)+WalSndCheckTimeOut(void)
{
TimestampTz timeout;
@@ -2085,7 +2093,7 @@ WalSndCheckTimeOut(TimestampTz now)
timeout = TimestampTzPlusMilliseconds(last_reply_timestamp,
wal_sender_timeout);
- if (wal_sender_timeout > 0 && now >= timeout)+ if (wal_sender_timeout > 0 && last_processing >= timeout)
{
/*
* Since typically expiration of replication timeout means
@@ -2116,8 +2124,6 @@ WalSndLoop(WalSndSendDataCallback send_data)
*/
for (;;)
{
- TimestampTz now;-
/*
* Emergency bailout if postmaster has died. This is to avoid the
* necessity for manual cleanup of all postmaster children.
@@ -2195,13 +2201,11 @@ WalSndLoop(WalSndSendDataCallback send_data)
WalSndDone(send_data);
}
- now = GetCurrentTimestamp();-
/* Check for replication timeout. */
- WalSndCheckTimeOut(now);+ WalSndCheckTimeOut();
/* Send keepalive if the time has come */
- WalSndKeepaliveIfNecessary(now);+ WalSndKeepaliveIfNecessary();
/*
* We don't block if not caught up, unless there is unsent data
@@ -2219,7 +2223,11 @@ WalSndLoop(WalSndSendDataCallback send_data)
wakeEvents = WL_LATCH_SET | WL_POSTMASTER_DEATH | WL_TIMEOUT |
WL_SOCKET_READABLE;
- sleeptime = WalSndComputeSleeptime(now);+ /*+ * Use fresh timestamp, not last_processed, to reduce the chance+ * of reaching wal_sender_timeout before sending a keepalive.+ */+ sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
if (pq_is_send_pending())
wakeEvents |= WL_SOCKET_WRITEABLE;
@@ -3379,7 +3387,7 @@ WalSndKeepalive(bool requestReply)
* Send keepalive message if too much time has elapsed.
*/
static void
-WalSndKeepaliveIfNecessary(TimestampTz now)+WalSndKeepaliveIfNecessary(void)
{
TimestampTz ping_time;
@@ -3400,7 +3408,7 @@ WalSndKeepaliveIfNecessary(TimestampTz now)
*/
ping_time = TimestampTzPlusMilliseconds(last_reply_timestamp,
wal_sender_timeout / 2);
- if (now >= ping_time)+ if (last_processing >= ping_time)
{
WalSndKeepalive(true);
waiting_for_ping_response = true;
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: pgsql-hackers@postgresql.org
Cc: noah@leadboat.com
Subject: Re: wal_sender_timeout should ignore server-side latency
In-Reply-To: <20180826034600.GA1105084@rfd.leadboat.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox