walsender waiting_for_ping spuriously set

Started by Alvaro Herreraover 5 years ago6 messages
#1Alvaro Herrera
alvherre@2ndquadrant.com
1 attachment(s)

Ashutosh Bapat noticed that WalSndWaitForWal() is setting
waiting_for_ping_response after sending a keepalive that does *not*
request a reply. The bad consequence is that other callers that do
require a reply end up in not sending a keepalive, because they think it
was already sent previously. So the whole thing gets stuck.

He found that commit 41d5f8ad734 failed to remove the setting of
waiting_for_ping_response after changing the "request" parameter
WalSndKeepalive from true to false; that seems to have been an omission
and it breaks the algorithm. Thread at [1]/messages/by-id/flat/BLU436-SMTP25712B7EF9FC2ADEB87C522DC040@phx.gbl.

The simplest fix is just to remove the line that sets
waiting_for_ping_response, but I think it is less error-prone to have
WalSndKeepalive set the flag itself, instead of expecting its callers to
do it (and know when to). Patch attached. Also rewords some related
commentary.

[1]: /messages/by-id/flat/BLU436-SMTP25712B7EF9FC2ADEB87C522DC040@phx.gbl

--
�lvaro Herrera Valdivia, Chile

Attachments:

0001-Fix-waiting_for_ping-in-walsender.patchtext/x-diff; charset=us-asciiDownload
From bf5ca106817744c1ba300ecb8c86d230789988e0 Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvherre@alvh.no-ip.org>
Date: Thu, 6 Aug 2020 14:57:09 -0400
Subject: [PATCH] Fix waiting_for_ping in walsender

---
 src/backend/replication/walsender.c | 29 ++++++++++++++---------------
 1 file changed, 14 insertions(+), 15 deletions(-)

diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 5e2210dd7b..c239902e0e 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -151,7 +151,7 @@ static XLogRecPtr sendTimeLineValidUpto = InvalidXLogRecPtr;
  * How far have we sent WAL already? This is also advertised in
  * MyWalSnd->sentPtr.  (Actually, this is the next WAL location to send.)
  */
-static XLogRecPtr sentPtr = 0;
+static XLogRecPtr sentPtr = InvalidXLogRecPtr;
 
 /* Buffers for constructing outgoing messages and processing reply messages. */
 static StringInfoData output_message;
@@ -1444,17 +1444,13 @@ WalSndWaitForWal(XLogRecPtr loc)
 		 * We only send regular messages to the client for full decoded
 		 * transactions, but a synchronous replication and walsender shutdown
 		 * possibly are waiting for a later location. So, before sleeping, we
-		 * send a ping containing the flush location. If the receiver is
-		 * otherwise idle, this keepalive will trigger a reply. Processing the
-		 * reply will update these MyWalSnd locations.
+		 * send a ping containing the flush location. A reply from standby is
+		 * not needed and would be wasteful.
 		 */
 		if (MyWalSnd->flush < sentPtr &&
 			MyWalSnd->write < sentPtr &&
 			!waiting_for_ping_response)
-		{
 			WalSndKeepalive(false);
-			waiting_for_ping_response = true;
-		}
 
 		/* check whether we're done */
 		if (loc <= RecentFlushPtr)
@@ -2932,10 +2928,7 @@ WalSndDone(WalSndSendDataCallback send_data)
 		proc_exit(0);
 	}
 	if (!waiting_for_ping_response)
-	{
 		WalSndKeepalive(true);
-		waiting_for_ping_response = true;
-	}
 }
 
 /*
@@ -3432,10 +3425,13 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 }
 
 /*
-  * This function is used to send a keepalive message to standby.
-  * If requestReply is set, sets a flag in the message requesting the standby
-  * to send a message back to us, for heartbeat purposes.
-  */
+ * Send a keepalive message to standby.
+ *
+ * If requestReply is set, the message requests the other party to send
+ * a message back to us, for heartbeat purposes.  We also set a flag to
+ * let nearby code that we're waiting for that response, to avoid
+ * repeated requests.
+ */
 static void
 WalSndKeepalive(bool requestReply)
 {
@@ -3450,6 +3446,10 @@ WalSndKeepalive(bool requestReply)
 
 	/* ... and send it wrapped in CopyData */
 	pq_putmessage_noblock('d', output_message.data, output_message.len);
+
+	/* Set local flag */
+	if (requestReply)
+		waiting_for_ping_response = true;
 }
 
 /*
@@ -3480,7 +3480,6 @@ WalSndKeepaliveIfNecessary(void)
 	if (last_processing >= ping_time)
 	{
 		WalSndKeepalive(true);
-		waiting_for_ping_response = true;
 
 		/* Try to flush pending output to the client */
 		if (pq_flush_if_writable() != 0)
-- 
2.20.1

#2Ashutosh Bapat
ashutosh.bapat@2ndquadrant.com
In reply to: Alvaro Herrera (#1)
Re: walsender waiting_for_ping spuriously set

The patch looks good to me. Thanks for improving comments around that code.
I like the change to set waiting_for_ping_response in WalSndKeepalive.
Thanks.

On Fri, 7 Aug 2020 at 04:26, Alvaro Herrera <alvherre@2ndquadrant.com>
wrote:

Ashutosh Bapat noticed that WalSndWaitForWal() is setting
waiting_for_ping_response after sending a keepalive that does *not*
request a reply. The bad consequence is that other callers that do
require a reply end up in not sending a keepalive, because they think it
was already sent previously. So the whole thing gets stuck.

He found that commit 41d5f8ad734 failed to remove the setting of
waiting_for_ping_response after changing the "request" parameter
WalSndKeepalive from true to false; that seems to have been an omission
and it breaks the algorithm. Thread at [1].

The simplest fix is just to remove the line that sets
waiting_for_ping_response, but I think it is less error-prone to have
WalSndKeepalive set the flag itself, instead of expecting its callers to
do it (and know when to). Patch attached. Also rewords some related
commentary.

[1]
/messages/by-id/flat/BLU436-SMTP25712B7EF9FC2ADEB87C522DC040@phx.gbl

--
Álvaro Herrera Valdivia, Chile

--
Best Wishes,
Ashutosh

#3Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Alvaro Herrera (#1)
Re: walsender waiting_for_ping spuriously set

I just noticed that part of this comment I'm modifying:

@@ -1444,17 +1444,13 @@ WalSndWaitForWal(XLogRecPtr loc)
* We only send regular messages to the client for full decoded
* transactions, but a synchronous replication and walsender shutdown
* possibly are waiting for a later location. So, before sleeping, we
-		 * send a ping containing the flush location. If the receiver is
-		 * otherwise idle, this keepalive will trigger a reply. Processing the
-		 * reply will update these MyWalSnd locations.
+		 * send a ping containing the flush location. A reply from standby is
+		 * not needed and would be wasteful.

was added very recently, in f246ea3b2a5e ("In caught-up logical
walsender, sleep only in WalSndWaitForWal()."). Added Noah to CC.

I think the walreceiver will only send a reply if
wal_receiver_status_interval is set to a nonzero value. I don't
understand what reason could there possibly be for setting this
parameter to zero, but it seems better to be explicit about it, as this
code is confusing enough.

I'm thinking in keeping the sentences that were added in that commit,
maybe like so:

* We only send regular messages to the client for full decoded
* transactions, but a synchronous replication and walsender shutdown
* possibly are waiting for a later location. So, before sleeping, we
+		 * send a ping containing the flush location. A reply from standby is
+		 * not needed and would be wasteful most of the time,
+		 * but if the receiver is otherwise idle and walreceiver status messages
+		 * are enabled, this keepalive will trigger a reply.  Processing the
+		 * reply will update these MyWalSnd locations.

(Also, the comment would be updated all the way back to 9.5, even if
f246ea3b2a5e itself was not.)

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#4Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Alvaro Herrera (#3)
Re: walsender waiting_for_ping spuriously set

On 2020-Aug-07, Alvaro Herrera wrote:

I'm thinking in keeping the sentences that were added in that commit,
maybe like so:

* We only send regular messages to the client for full decoded
* transactions, but a synchronous replication and walsender shutdown
* possibly are waiting for a later location. So, before sleeping, we
+		 * send a ping containing the flush location. A reply from standby is
+		 * not needed and would be wasteful most of the time,
+		 * but if the receiver is otherwise idle and walreceiver status messages
+		 * are enabled, this keepalive will trigger a reply.  Processing the
+		 * reply will update these MyWalSnd locations.

After rereading this a few more times, I think it's OK as Noah had it,
so I'll just use his wording.

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#5Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Alvaro Herrera (#4)
Re: walsender waiting_for_ping spuriously set

Pushed.

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#6Andres Freund
andres@anarazel.de
In reply to: Alvaro Herrera (#1)
Re: walsender waiting_for_ping spuriously set

On 2020-08-06 18:55:58 -0400, Alvaro Herrera wrote:

Ashutosh Bapat noticed that WalSndWaitForWal() is setting
waiting_for_ping_response after sending a keepalive that does *not*
request a reply. The bad consequence is that other callers that do
require a reply end up in not sending a keepalive, because they think it
was already sent previously. So the whole thing gets stuck.

He found that commit 41d5f8ad734 failed to remove the setting of
waiting_for_ping_response after changing the "request" parameter
WalSndKeepalive from true to false; that seems to have been an omission
and it breaks the algorithm. Thread at [1].

The simplest fix is just to remove the line that sets
waiting_for_ping_response, but I think it is less error-prone to have
WalSndKeepalive set the flag itself, instead of expecting its callers to
do it (and know when to). Patch attached. Also rewords some related
commentary.

Thanks for diagnosis and fix!

- Andres