Skip to content

Commit 20cd888

Browse files
nmischnmisch
committed
Ignore server-side delays when enforcing wal_sender_timeout.
Healthy clients of servers having poor I/O performance, such as buildfarm members hamster and tern, saw unexpected timeouts. That disagreed with documentation. This fix adds one gettimeofday() call whenever ProcessRepliesIfAny() finds no client reply messages. Back-patch to 9.4; the bug's symptom is rare and mild, and the code all moved between 9.3 and 9.4. Discussion: https://postgr.es/m/20180826034600.GA1105084@rfd.leadboat.com
1 parent d9638a3 commit 20cd888

File tree

1 file changed

+36
-28
lines changed

1 file changed

+36
-28
lines changed

‎src/backend/replication/walsender.c

Lines changed: 36 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -152,9 +152,12 @@ static StringInfoData output_message;
152152
static StringInfoData reply_message;
153153
static StringInfoData tmpbuf;
154154

155+
/* Timestamp of last ProcessRepliesIfAny(). */
156+
static TimestampTz last_processing = 0;
157+
155158
/*
156-
* Timestamp of the last receipt of the reply from the standby. Set to 0 if
157-
* wal_sender_timeout doesn't need to be active.
159+
* Timestamp of last ProcessRepliesIfAny() that saw a reply from the
160+
* standby. Set to 0 if wal_sender_timeout doesn't need to be active.
158161
*/
159162
static TimestampTz last_reply_timestamp = 0;
160163

@@ -211,8 +214,8 @@ static void ProcessStandbyReplyMessage(void);
211214
static void ProcessStandbyHSFeedbackMessage(void);
212215
static void ProcessRepliesIfAny(void);
213216
static void WalSndKeepalive(bool requestReply);
214-
static void WalSndKeepaliveIfNecessary(TimestampTz now);
215-
static void WalSndCheckTimeOut(TimestampTz now);
217+
static void WalSndKeepaliveIfNecessary(void);
218+
static void WalSndCheckTimeOut(void);
216219
static long WalSndComputeSleeptime(TimestampTz now);
217220
static void WalSndPrepareWrite(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid, bool last_write);
218221
static void WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid, bool last_write);
@@ -1107,18 +1110,16 @@ WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid,
11071110
/* Check for input from the client */
11081111
ProcessRepliesIfAny();
11091112

1110-
now = GetCurrentTimestamp();
1111-
11121113
/* die if timeout was reached */
1113-
WalSndCheckTimeOut(now);
1114+
WalSndCheckTimeOut();
11141115

11151116
/* Send keepalive if the time has come */
1116-
WalSndKeepaliveIfNecessary(now);
1117+
WalSndKeepaliveIfNecessary();
11171118

11181119
if (!pq_is_send_pending())
11191120
break;
11201121

1121-
sleeptime = WalSndComputeSleeptime(now);
1122+
sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
11221123

11231124
wakeEvents = WL_LATCH_SET | WL_POSTMASTER_DEATH |
11241125
WL_SOCKET_WRITEABLE | WL_SOCKET_READABLE | WL_TIMEOUT;
@@ -1186,7 +1187,6 @@ WalSndWaitForWal(XLogRecPtr loc)
11861187
for (;;)
11871188
{
11881189
long sleeptime;
1189-
TimestampTz now;
11901190

11911191
/*
11921192
* Emergency bailout if postmaster has died. This is to avoid the
@@ -1269,13 +1269,11 @@ WalSndWaitForWal(XLogRecPtr loc)
12691269
!pq_is_send_pending())
12701270
break;
12711271

1272-
now = GetCurrentTimestamp();
1273-
12741272
/* die if timeout was reached */
1275-
WalSndCheckTimeOut(now);
1273+
WalSndCheckTimeOut();
12761274

12771275
/* Send keepalive if the time has come */
1278-
WalSndKeepaliveIfNecessary(now);
1276+
WalSndKeepaliveIfNecessary();
12791277

12801278
/*
12811279
* Sleep until something happens or we time out. Also wait for the
@@ -1284,7 +1282,7 @@ WalSndWaitForWal(XLogRecPtr loc)
12841282
* new WAL to be generated. (But if we have nothing to send, we don't
12851283
* want to wake on socket-writable.)
12861284
*/
1287-
sleeptime = WalSndComputeSleeptime(now);
1285+
sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
12881286

12891287
wakeEvents = WL_LATCH_SET | WL_POSTMASTER_DEATH |
12901288
WL_SOCKET_READABLE | WL_TIMEOUT;
@@ -1423,6 +1421,8 @@ ProcessRepliesIfAny(void)
14231421
int r;
14241422
bool received = false;
14251423

1424+
last_processing = GetCurrentTimestamp();
1425+
14261426
for (;;)
14271427
{
14281428
pq_startmsgread();
@@ -1510,7 +1510,7 @@ ProcessRepliesIfAny(void)
15101510
*/
15111511
if (received)
15121512
{
1513-
last_reply_timestamp = GetCurrentTimestamp();
1513+
last_reply_timestamp = last_processing;
15141514
waiting_for_ping_response = false;
15151515
}
15161516
}
@@ -1806,10 +1806,18 @@ WalSndComputeSleeptime(TimestampTz now)
18061806

18071807
/*
18081808
* Check whether there have been responses by the client within
1809-
* wal_sender_timeout and shutdown if not.
1809+
* wal_sender_timeout and shutdown if not. Using last_processing as the
1810+
* reference point avoids counting server-side stalls against the client.
1811+
* However, a long server-side stall can make WalSndKeepaliveIfNecessary()
1812+
* postdate last_processing by more than wal_sender_timeout. If that happens,
1813+
* the client must reply almost immediately to avoid a timeout. This rarely
1814+
* affects the default configuration, under which clients spontaneously send a
1815+
* message every standby_message_timeout = wal_sender_timeout/6 = 10s. We
1816+
* could eliminate that problem by recognizing timeout expiration at
1817+
* wal_sender_timeout/2 after the keepalive.
18101818
*/
18111819
static void
1812-
WalSndCheckTimeOut(TimestampTz now)
1820+
WalSndCheckTimeOut(void)
18131821
{
18141822
TimestampTz timeout;
18151823

@@ -1820,7 +1828,7 @@ WalSndCheckTimeOut(TimestampTz now)
18201828
timeout = TimestampTzPlusMilliseconds(last_reply_timestamp,
18211829
wal_sender_timeout);
18221830

1823-
if (wal_sender_timeout > 0 && now >= timeout)
1831+
if (wal_sender_timeout > 0 && last_processing >= timeout)
18241832
{
18251833
/*
18261834
* Since typically expiration of replication timeout means
@@ -1851,8 +1859,6 @@ WalSndLoop(WalSndSendDataCallback send_data)
18511859
*/
18521860
for (;;)
18531861
{
1854-
TimestampTz now;
1855-
18561862
/*
18571863
* Emergency bailout if postmaster has died. This is to avoid the
18581864
* necessity for manual cleanup of all postmaster children.
@@ -1930,13 +1936,11 @@ WalSndLoop(WalSndSendDataCallback send_data)
19301936
WalSndDone(send_data);
19311937
}
19321938

1933-
now = GetCurrentTimestamp();
1934-
19351939
/* Check for replication timeout. */
1936-
WalSndCheckTimeOut(now);
1940+
WalSndCheckTimeOut();
19371941

19381942
/* Send keepalive if the time has come */
1939-
WalSndKeepaliveIfNecessary(now);
1943+
WalSndKeepaliveIfNecessary();
19401944

19411945
/*
19421946
* We don't block if not caught up, unless there is unsent data
@@ -1954,7 +1958,11 @@ WalSndLoop(WalSndSendDataCallback send_data)
19541958
wakeEvents = WL_LATCH_SET | WL_POSTMASTER_DEATH | WL_TIMEOUT |
19551959
WL_SOCKET_READABLE;
19561960

1957-
sleeptime = WalSndComputeSleeptime(now);
1961+
/*
1962+
* Use fresh timestamp, not last_processed, to reduce the chance
1963+
* of reaching wal_sender_timeout before sending a keepalive.
1964+
*/
1965+
sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
19581966

19591967
if (pq_is_send_pending())
19601968
wakeEvents |= WL_SOCKET_WRITEABLE;
@@ -3051,7 +3059,7 @@ WalSndKeepalive(bool requestReply)
30513059
* Send keepalive message if too much time has elapsed.
30523060
*/
30533061
static void
3054-
WalSndKeepaliveIfNecessary(TimestampTz now)
3062+
WalSndKeepaliveIfNecessary(void)
30553063
{
30563064
TimestampTz ping_time;
30573065

@@ -3072,7 +3080,7 @@ WalSndKeepaliveIfNecessary(TimestampTz now)
30723080
*/
30733081
ping_time = TimestampTzPlusMilliseconds(last_reply_timestamp,
30743082
wal_sender_timeout / 2);
3075-
if (now >= ping_time)
3083+
if (last_processing >= ping_time)
30763084
{
30773085
WalSndKeepalive(true);
30783086
waiting_for_ping_response = true;

0 commit comments

Comments
 (0)