Fix pgstat_count_io_op_time() calls passing incorrect information

Several calls of pgstat_count_io_op_time() have been used as data to
count negative values returned by pg_pread() or pg_pwrite(), leading to
an incorrect count reported, casting them back to uint64.

Most of the problematic calls updated here are adjusted so as we do not
report buggy negative numbers anymore.  In xlogrecovery.c, the spot
updated still counts short reads.  In xlog.c, after a WAL segment
initialization, I/O numbers are aggregated only after checking that the
operation has succeeded.

issues introduced by a051e71e28a1.

Reported-by: Peter Eisentraut <peter@eisentraut.org>
Author: Bertrand Drouvot <bertranddrouvot.pg@gmail.com>
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Ayush Tiwari <ayushtiwari.slg01@gmail.com>
Discussion: https://postgr.es/m/0db864e6-4477-4eba-b2be-d3523cc86564@eisentraut.org
Backpatch-through: 18

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 4f74400f3ddde45465d891296932ce5359f90826..e07cb9103515f02a1c156ea2e544bf21f164657f 100644 (file)
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2434,9 +2434,6 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli, bool flexible)
                                written = pg_pwrite(openLogFile, from, nleft, startoffset);
                                pgstat_report_wait_end();
 
-                               pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL,
-                                                                               IOOP_WRITE, start, 1, written);
-
                                if (written <= 0)
                                {
                                        char            xlogfname[MAXFNAMELEN];
@@ -2454,6 +2451,9 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli, bool flexible)
                                                         errmsg("could not write to log file \"%s\" at offset %u, length %zu: %m",
                                                                        xlogfname, startoffset, nleft)));
                                }
+
+                               pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL,
+                                                                               IOOP_WRITE, start, 1, written);
                                nleft -= written;
                                from += written;
                                startoffset += written;
@@ -3276,14 +3276,6 @@ XLogFileInitInternal(XLogSegNo logsegno, TimeLineID logtli,
        }
        pgstat_report_wait_end();
 
-       /*
-        * A full segment worth of data is written when using wal_init_zero. One
-        * byte is written when not using it.
-        */
-       pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_INIT, IOOP_WRITE,
-                                                       io_start, 1,
-                                                       wal_init_zero ? wal_segment_size : 1);
-
        if (save_errno)
        {
                /*
@@ -3300,6 +3292,14 @@ XLogFileInitInternal(XLogSegNo logsegno, TimeLineID logtli,
                                 errmsg("could not write to file \"%s\": %m", tmppath)));
        }
 
+       /*
+        * A full segment worth of data is written when using wal_init_zero. One
+        * byte is written when not using it.
+        */
+       pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_INIT, IOOP_WRITE,
+                                                       io_start, 1,
+                                                       wal_init_zero ? wal_segment_size : 1);
+
        /* Measure I/O timing when flushing segment */
        io_start = pgstat_prepare_io_time(track_wal_io_timing);
 

diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c
index 5c26d33a60380341454f5a7927232650e5776f1b..29d4df7a996ef76ec6026d3245e88d8542429e60 100644 (file)
--- a/src/backend/access/transam/xlogreader.c
+++ b/src/backend/access/transam/xlogreader.c
@@ -1578,9 +1578,6 @@ WALRead(XLogReaderState *state,
 
 #ifndef FRONTEND
                pgstat_report_wait_end();
-
-               pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL, IOOP_READ,
-                                                               io_start, 1, readbytes);
 #endif
 
                if (readbytes <= 0)
@@ -1593,6 +1590,11 @@ WALRead(XLogReaderState *state,
                        return false;
                }
 
+#ifndef FRONTEND
+               pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL, IOOP_READ,
+                                                               io_start, 1, readbytes);
+#endif
+
                /* Update state for read */
                recptr += readbytes;
                nbytes -= readbytes;

diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c
index ff4d9edc7900f5f969774f901f90507931127458..476187113d4319d25937b29b17685cd176a53994 100644 (file)
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -3431,8 +3431,10 @@ retry:
 
                pgstat_report_wait_end();
 
-               pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL, IOOP_READ,
-                                                               io_start, 1, r);
+               /* Count I/O stats only for successful short reads */
+               if (r > 0)
+                       pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL, IOOP_READ,
+                                                                       io_start, 1, r);
 
                XLogFileName(fname, curFileTLI, readSegNo, wal_segment_size);
                if (r < 0)

diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c
index 8c4d0fd9aed2bfb4ce05da1eb58dc19352b8ecf6..6df19f89bef2a8ba93250f47ebbc8793490bd143 100644 (file)
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -931,9 +931,6 @@ XLogWalRcvWrite(char *buf, Size nbytes, XLogRecPtr recptr, TimeLineID tli)
                byteswritten = pg_pwrite(recvFile, buf, segbytes, (off_t) startoff);
                pgstat_report_wait_end();
 
-               pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL,
-                                                               IOOP_WRITE, start, 1, byteswritten);
-
                if (byteswritten <= 0)
                {
                        char            xlogfname[MAXFNAMELEN];
@@ -953,6 +950,9 @@ XLogWalRcvWrite(char *buf, Size nbytes, XLogRecPtr recptr, TimeLineID tli)
                                                        xlogfname, startoff, (unsigned long) segbytes)));
                }
 
+               pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL,
+                                                               IOOP_WRITE, start, 1, byteswritten);
+
                /* Update state for write */
                recptr += byteswritten;