Flush the IO statistics of active WAL senders more frequently

WAL senders do not flush their statistics until they exit, limiting the
monitoring possible for live processes.  This is penalizing when WAL
senders are running for a long time, like in streaming or logical
replication setups, because it is not possible to know the amount of IO
they generate while running.

This commit makes WAL senders more aggressive with their statistics
flush, using an internal of 1 second, with the flush timing calculated
based on the existing GetCurrentTimestamp() done before the sleeps done
to wait for some activity.  Note that the sleep done for logical and
physical WAL senders happens in two different code paths, so the stats
flushes need to happen in these two places.

One test is added for the physical WAL sender case, and one for the
logical WAL sender case.  This can be done in a stable fashion by
relying on the WAL generated by the TAP tests in combination with a
stats reset while a server is running, but only on HEAD as WAL data has
been added to pg_stat_io in a051e71e28a1.

This issue exists since a9c70b46dbe and the introduction of pg_stat_io,
so backpatch down to v16.

Author: Bertrand Drouvot <[email protected]>
Reviewed-by: vignesh C <[email protected]>
Reviewed-by: Xuneng Zhou <[email protected]>
Discussion: https://postgr.es/m/[email protected]
Backpatch-through: 16

diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index c3181e3295ea32cd81f72aaf3e0dbd51a9d1bc90..45adf1936e8a56427bec63d95855640542b30201 100644 (file)
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -90,10 +90,14 @@
 #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"
 
+/* Minimum interval used by walsender for stats flushes, in ms */
+#define WALSENDER_STATS_FLUSH_INTERVAL         1000
+
 /*
  * Maximum data payload in a WAL data message.  Must be >= XLOG_BLCKSZ.
  *
@@ -1820,6 +1824,7 @@ WalSndWaitForWal(XLogRecPtr loc)
    int         wakeEvents;
    uint32      wait_event = 0;
    static XLogRecPtr RecentFlushPtr = InvalidXLogRecPtr;
+   TimestampTz last_flush = 0;
 
    /*
     * Fast path to avoid acquiring the spinlock in case we already know we
@@ -1840,6 +1845,7 @@ WalSndWaitForWal(XLogRecPtr loc)
    {
        bool        wait_for_standby_at_stop = false;
        long        sleeptime;
+       TimestampTz now;
 
        /* Clear any already-pending wakeups */
        ResetLatch(MyLatch);
@@ -1950,7 +1956,8 @@ 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(GetCurrentTimestamp());
+       now = GetCurrentTimestamp();
+       sleeptime = WalSndComputeSleeptime(now);
 
        wakeEvents = WL_SOCKET_READABLE;
 
@@ -1959,6 +1966,14 @@ WalSndWaitForWal(XLogRecPtr loc)
 
        Assert(wait_event != 0);
 
+       /* Report IO statistics, if needed */
+       if (TimestampDifferenceExceeds(last_flush, now,
+                                      WALSENDER_STATS_FLUSH_INTERVAL))
+       {
+           pgstat_flush_io(false);
+           last_flush = now;
+       }
+
        WalSndWait(wakeEvents, sleeptime, wait_event);
    }
 
@@ -2766,6 +2781,8 @@ WalSndCheckTimeOut(void)
 static void
 WalSndLoop(WalSndSendDataCallback send_data)
 {
+   TimestampTz last_flush = 0;
+
    /*
     * Initialize the last reply timestamp. That enables timeout processing
     * from hereon.
@@ -2860,6 +2877,9 @@ WalSndLoop(WalSndSendDataCallback send_data)
         * WalSndWaitForWal() handle any other blocking; idle receivers need
         * its additional actions.  For physical replication, also block if
         * caught up; its send_data does not block.
+        *
+        * The IO statistics are reported in WalSndWaitForWal() for the
+        * logical WAL senders.
         */
        if ((WalSndCaughtUp && send_data != XLogSendLogical &&
             !streamingDoneSending) ||
@@ -2867,6 +2887,7 @@ WalSndLoop(WalSndSendDataCallback send_data)
        {
            long        sleeptime;
            int         wakeEvents;
+           TimestampTz now;
 
            if (!streamingDoneReceiving)
                wakeEvents = WL_SOCKET_READABLE;
@@ -2877,11 +2898,20 @@ WalSndLoop(WalSndSendDataCallback send_data)
             * Use fresh timestamp, not last_processing, to reduce the chance
             * of reaching wal_sender_timeout before sending a keepalive.
             */
-           sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
+           now = GetCurrentTimestamp();
+           sleeptime = WalSndComputeSleeptime(now);
 
            if (pq_is_send_pending())
                wakeEvents |= WL_SOCKET_WRITEABLE;
 
+           /* Report IO statistics, if needed */
+           if (TimestampDifferenceExceeds(last_flush, now,
+                                          WALSENDER_STATS_FLUSH_INTERVAL))
+           {
+               pgstat_flush_io(false);
+               last_flush = now;
+           }
+
            /* Sleep until something happens or we time out */
            WalSndWait(wakeEvents, sleeptime, WAIT_EVENT_WAL_SENDER_MAIN);
        }