Date: Wed, 26 Feb 2025 09:48:50 +0000
From: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
To: Michael Paquier <michael@paquier.xyz>
Cc: pgsql-hackers@lists.postgresql.org
Subject: Re: [BUG]: the walsender does not update its IO statistics until it
 exits
Message-ID: <Z77jgvhwOu9S0a5r@ip-10-97-1-34.eu-west-3.compute.internal>
References: <Z73IsKBceoVd4t55@ip-10-97-1-34.eu-west-3.compute.internal>
 <Z762lusJXp_wNF_z@paquier.xyz>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="AOn2IxnzNvFdITAb"
Content-Disposition: inline
In-Reply-To: <Z762lusJXp_wNF_z@paquier.xyz>
Archived-At: <https://www.postgresql.org/message-id/Z77jgvhwOu9S0a5r%40ip-10-97-1-34.eu-west-3.compute.internal>
Precedence: bulk


--AOn2IxnzNvFdITAb
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

Hi,

On Wed, Feb 26, 2025 at 03:37:10PM +0900, Michael Paquier wrote:
> On Tue, Feb 25, 2025 at 01:42:08PM +0000, Bertrand Drouvot wrote:
> > Now we can see that the numbers increased for the relation object and that we
> > get non zeros numbers for the wal object too (which makes fully sense).
> > 
> > With the attached patch applied, we would get the same numbers already in
> > step 4. (means the stats are flushed without the need to wait for the walsender
> > to exit).
> 
> @@ -2793,6 +2794,12 @@ WalSndLoop(WalSndSendDataCallback send_data)
>          if (pq_flush_if_writable() != 0)
>              WalSndShutdown();
>  
> +        /*
> +         * Report IO statistics
> +         */
> +        pgstat_flush_io(false);
> +        (void) pgstat_flush_backend(false, PGSTAT_BACKEND_FLUSH_IO);
> +
>          /* If nothing remains to be sent right now ... */
>          if (WalSndCaughtUp && !pq_is_send_pending())
>          {
> 
> That's bad, worse for a logical WAL sender, because it means that we
> have no idea what kind of I/O happens in this process until it exits,
> and logical WAL senders could loop forever, since v16 where we've
> begun tracking I/O.

Yeah... And while the example shared up-thread is related to logical walsender,
the same issue exists for a physical walsender.

OTOH, It's also great to see that the new stats that have been added (the WAL
ones) helped to spot the issue.

> A non-forced periodic flush like you are proposing here sounds OK to
> me,

Thanks for looking at it!

> but the position of the flush could be positioned better in the
> loop.  If there is a SIGUSR2 (aka got_SIGUSR2 is true), WAL senders
> would shut down,

That's true for a physical walsender but I'm not sure it is for a logical
walsender (due to the "sentPtr == replicatedPtr" check in WalSndDone()).

> so it seems rather pointless to do a flush just
> before exiting the process in WalSndDone(), no?  I'd suggest to move
> the flush attempt closer to where we wait for some activity, just
> after WalSndKeepaliveIfNecessary().

Yeah I think that makes sense, done that way in the attached.

Speaking about physical walsender, I moved the test to 001_stream_rep.pl instead
(would also fail without the fix).

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

--AOn2IxnzNvFdITAb
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="v2-0001-Flush-the-IO-statistics-of-active-walsenders.patch"

From 0b610eaea0f71c3f61e1cded137dc59db596322e Mon Sep 17 00:00:00 2001
From: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Date: Tue, 25 Feb 2025 10:18:05 +0000
Subject: [PATCH v2] Flush the IO statistics of active walsenders

The walsender does not flush its IO statistics until it exits.
The issue is there since pg_stat_io has been introduced in a9c70b46dbe.
This commits:

1. ensures it does not wait to exit to flush its IO statistics
2. adds a test for a physical walsender (a logical walsender had the same issue
but the fix is in the same code path)
---
 src/backend/replication/walsender.c   |  7 +++++++
 src/test/recovery/t/001_stream_rep.pl | 14 ++++++++++++++
 2 files changed, 21 insertions(+)
  26.8% src/backend/replication/
  73.1% src/test/recovery/t/

diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 446d10c1a7d..9ddf111af25 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -90,6 +90,7 @@
 #include "utils/guc.h"
 #include "utils/memutils.h"
 #include "utils/pg_lsn.h"
+#include "utils/pgstat_internal.h"
 #include "utils/ps_status.h"
 #include "utils/timeout.h"
 #include "utils/timestamp.h"
@@ -2829,6 +2830,12 @@ WalSndLoop(WalSndSendDataCallback send_data)
 		/* Send keepalive if the time has come */
 		WalSndKeepaliveIfNecessary();
 
+		/*
+		 * Report IO statistics
+		 */
+		pgstat_flush_io(false);
+		(void) pgstat_flush_backend(false, PGSTAT_BACKEND_FLUSH_IO);
+
 		/*
 		 * Block if we have unsent data.  XXX For logical replication, let
 		 * WalSndWaitForWal() handle any other blocking; idle receivers need
diff --git a/src/test/recovery/t/001_stream_rep.pl b/src/test/recovery/t/001_stream_rep.pl
index ee57d234c86..aea32f68b79 100644
--- a/src/test/recovery/t/001_stream_rep.pl
+++ b/src/test/recovery/t/001_stream_rep.pl
@@ -42,6 +42,9 @@ $node_standby_2->init_from_backup($node_standby_1, $backup_name,
 	has_streaming => 1);
 $node_standby_2->start;
 
+# To check that an active walsender updates its IO statistics below.
+$node_primary->safe_psql('postgres', "SELECT pg_stat_reset_shared('io')");
+
 # Create some content on primary and check its presence in standby nodes
 $node_primary->safe_psql('postgres',
 	"CREATE TABLE tab_int AS SELECT generate_series(1,1002) AS a");
@@ -69,6 +72,17 @@ ALTER EVENT TRIGGER on_login_trigger ENABLE ALWAYS;
 $node_primary->wait_for_replay_catchup($node_standby_1);
 $node_standby_1->wait_for_replay_catchup($node_standby_2, $node_primary);
 
+# Ensure an active walsender updates its IO statistics.
+is( $node_primary->safe_psql(
+		'postgres',
+		qq(SELECT sum(reads) > 0
+       FROM pg_catalog.pg_stat_io
+       WHERE backend_type = 'walsender'
+       AND object = 'wal')
+	),
+	qq(t),
+	"Check that the walsender updates its IO statistics");
+
 my $result =
   $node_standby_1->safe_psql('postgres', "SELECT count(*) FROM tab_int");
 print "standby 1: $result\n";
-- 
2.34.1


--AOn2IxnzNvFdITAb--