Show WAL write and fsync stats in pg_stat_io

On Wed, Jun 28, 2023 at 6:09 AM Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:

This is a WIP patch to add WAL write and fsync stats to pg_stat_io
view.

Thanks for working on this! I have some feedback on the content of the
patch as well as some items that I feel are missing.

I think it would be good to count WAL reads even though they are not
currently represented in pg_stat_wal. Here is a thread discussing this
[1]: /messages/by-id/20230216191138.jotc73lqb7xhfqbi@awork3.anarazel.de

Eventually, the docs will need an update as well. You can wait until a
later version of the patch to do this, but I would include it in a list
of the remaining TODOs in your next version.

I think we will also want to add an IOContext for WAL initialization.
Then we can track how long is spent doing WAL init (including filling
the WAL file with zeroes). XLogFileInitInternal() is likely where we
would want to add it. And op_bytes for this would likely be
wal_segment_size. I thought I heard about someone proposing adding WAL
init to pg_stat_wal, but I can't find the thread.

I think there is also an argument for counting WAL files recycled as
IOOP_REUSES. We should start thinking about how to interpret the
different IOOps within the two IOContexts and discussing what would be
useful to count. For example, should removing a logfile count as an
IOOP_EVICT? Maybe it is not directly related to "IO" enough or even an
interesting statistic, but we should think about what kinds of
IO-related WAL statistics we want to track.

Any that we decide not to count for now should be "banned" in
pgstat_tracks_io_op() for clarity. For example, if we create a separate
IOContext for WAL file init, I'm not sure what would count as an
IOOP_EXTEND in IOCONTEXT_NORMAL for IOOBJECT_WAL.

Also, I think there are some backend types which will not generate WAL
and we should determine which those are and skip those rows in
pgstat_tracks_io_object().

diff --git a/src/backend/access/transam/xlog.c
b/src/backend/access/transam/xlog.c
index 8b0710abe6..2ee6c21398 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2207,6 +2207,10 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID
tli, bool flexible)

I think we should likely follow the pattern of using
pgstat_prepare_io_time() and pgstat_count_io_op_time() as it is done
elsewhere. You could pass the IOObject as a parameter to
pgstat_prepare_io_time() in order to determine if we should check
track_io_timing or track_wal_io_timing. And we'll want to check
track_wal_io_timing if IOObject is IOOBJECT_WAL in
pgstat_count_io_op_time().

INSTR_TIME_SET_CURRENT(duration);

INSTR_TIME_ACCUM_DIFF(PendingWalStats.wal_write_time, duration,
start);

+                    pgstat_count_io_op_time(IOOBJECT_WAL,
IOCONTEXT_NORMAL, IOOP_WRITE, start, 1);
+                } else
+                {

Other users of pgstat_count_io_op_time()/io_op_n() which write multiple
pages at a time pass the number of pages in as the cnt parameter. (see
ExtendBufferedRelLocal() as an example). I think we want to do that for
WAL also. In this case, it would be the local variable "npages" and we
can do it outside of this loop.

It is true that the existing WAL stats count wal_writes here. However,
this is essentially counting write system calls, which is probably not
what we want for pg_stat_io. See [2]/messages/by-id/20230504165738.4e2hfoddoels542c@awork3.anarazel.de for a discussion about whether to
count blocks written back or writeback system calls for a previous
pg_stat_io feature. All of the other block-based IO statistics in
pg_stat_io count the number of blocks.

This being said, we probably want to just leave
PendingWalStats.wal_write++ here. We would normally move it into
pg_stat_io like we have with pgBufferUsage and the db IO stats that are
updated in pgstat_count_io_op_time(). This consolidation makes it easier
to eventually reduce the duplication. However, in this case, it seems
wal_write counts something we don't count in pg_stat_io, so it can
probably be left here. I would still move the
PendingWalStats.wal_write_time into pgstat_count_io_op_time(), since
that seems like it is the same as what will be in pg_stat_io.

Also, op_bytes for IOOBJECT_WAL/IOCONTEXT_NORMAL should be XLOG_BLCKSZ
(see comment in pg_stat_get_io() in pgstatfuncs.c). Those default to the
same value but can be made to be different.

+ pgstat_count_io_op_n(IOOBJECT_WAL,
IOCONTEXT_NORMAL, IOOP_WRITE, 1);
}

PendingWalStats.wal_write++;

@@ -8233,6 +8237,10 @@ issue_xlog_fsync(int fd, XLogSegNo segno, TimeLineID tli)

INSTR_TIME_SET_CURRENT(duration);
INSTR_TIME_ACCUM_DIFF(PendingWalStats.wal_sync_time, duration, start);
+ pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL,
IOOP_FSYNC, start, 1);

I would wrap this line and check other lines to make sure they are not
too long.

+    } else
+    {
+        pgstat_count_io_op_n(IOOBJECT_WAL, IOCONTEXT_NORMAL, IOOP_FSYNC, 1);
     }

PendingWalStats.wal_sync++;

Same feedback as above about using the prepare/count pattern used for
pg_stat_io elsewhere. In this case, you should be able to move
PendingWalStats.wal_sync into there as well.

diff --git a/src/backend/utils/activity/pgstat_io.c
b/src/backend/utils/activity/pgstat_io.c
@@ -350,6 +352,11 @@ pgstat_tracks_io_object(BackendType bktype,
IOObject io_object,
     if (!pgstat_tracks_io_bktype(bktype))
         return false;

+
+    if (io_context != IOCONTEXT_NORMAL &&
+        io_object == IOOBJECT_WAL)
+        return false;

We should add more restrictions. See the top of my email for details.

There is a track_io_timing variable to control pg_stat_io
timings and a track_wal_io_timing variable to control WAL timings. I
couldn't decide on which logic to enable WAL timings on pg_stat_io.
For now, both pg_stat_io and track_wal_io_timing are needed to be
enabled to track WAL timings in pg_stat_io.

Hmm. I could see a case where someone doesn't want to incur the
overhead of track_io_timing for regular IO but does want to do so for
WAL because they are interested in a specific issue. I'm not sure
though. I could be convinced otherwise (based on relative overhead,
etc).

Also, if you compare WAL stats in pg_stat_wal and pg_stat_io; you can
come across differences. These differences are caused by the
background writer's WAL stats not being flushed. Because of that,
background writer's WAL stats are not seen in pg_stat_wal but in
pg_stat_io. I already sent a patch [1] to fix that.

Cool! Thanks for doing that.

- Melanie

[1]: /messages/by-id/20230216191138.jotc73lqb7xhfqbi@awork3.anarazel.de
[2]: /messages/by-id/20230504165738.4e2hfoddoels542c@awork3.anarazel.de

Hi,

Thanks for the review!

Current status of the patch is:
- 'WAL read' stats in xlogrecovery.c are added to pg_stat_io.
- IOCONTEXT_INIT is added to count 'WAL init'. 'WAL init' stats are
added to pg_stat_io.
- pg_stat_io shows different op_bytes for the IOOBJECT_WAL operations.
- Working on which 'BackendType / IOContext / IOOp' should be banned
in pg_stat_io.
- Working on adding 'WAL read' to the xlogreader.c and walsender.c.
- PendingWalStats.wal_sync and
PendingWalStats.wal_write_time/PendingWalStats.wal_sync_time are moved
to pgstat_count_io_op_n()/pgstat_count_io_op_time() respectively.

TODOs:
- Documentation.
- Thinking about how to interpret the different IOOps within the two
IOContexts and discussing what would be useful to count.
- Decide which 'BackendType / IOContext / IOOp' should not be tracked.
- Adding 'WAL read' to the xlogreader.c and walsender.c. (This could
be an another patch)
- Adding WAIT_EVENT_WAL_COPY_* operations to pg_stat_io if needed.
(This could be an another patch)

On Sat, 22 Jul 2023 at 01:30, Melanie Plageman
<melanieplageman@gmail.com> wrote:

I think it would be good to count WAL reads even though they are not
currently represented in pg_stat_wal. Here is a thread discussing this
[1].

I used the same implementation in the thread link [1]. I added 'WAL
read' to only xlogrecovery.c for now. I didn't add 'WAL read' to
xlogreader.c and walsender.c because they cause some failures on:
'!pgStatLocal.shmem->is_shutdown' asserts. I will spend more time on
these. Also, I added Bharath to CC. I have a question about 'WAL
read':
1. There are two places where 'WAL read' happens.
a. In WALRead() in xlogreader.c, it reads 'count' bytes, most of the
time count is equal to XLOG_BLCKSZ but there are some cases it is not.
For example
- in XLogSendPhysical() in walsender.c WALRead() is called by nbytes
- in WALDumpReadPage() in pg_waldump.c WALRead() is called by count
These nbytes and count variables could be different from XLOG_BLCKSZ.

b. in XLogPageRead() in xlogreader.c, it reads exactly XLOG_BLCKSZ bytes:
pg_pread(readFile, readBuf, XLOG_BLCKSZ, (off_t) readOff);

So, what should op_bytes be set to for 'WAL read' operations?

Eventually, the docs will need an update as well. You can wait until a
later version of the patch to do this, but I would include it in a list
of the remaining TODOs in your next version.

Done. I shared TODOs at the top.

I think we will also want to add an IOContext for WAL initialization.
Then we can track how long is spent doing 'WAL init' (including filling
the WAL file with zeroes). XLogFileInitInternal() is likely where we
would want to add it. And op_bytes for this would likely be
wal_segment_size. I thought I heard about someone proposing adding WAL
init to pg_stat_wal, but I can't find the thread.

Done. I created a new IOCONTEXT_INIT IOContext for the 'WAL init'. I
have a question there:
1. Some of the WAL processes happens at initdb (standalone backend
IOCONTEXT_NORMAL/(IOOP_READ & IOOP_WRITE) and
IOCONTEXT_INIT/(IOOP_WRITE & IOOP_FSYNC)). Since this happens at the
initdb, AFAIK there is no way to set 'track_wal_io_timing' and
'track_io_timing' variables there. So, their timings appear as 0.
Should I use IsBootstrapProcessingMode() to enable WAL io timings at
the initdb or are they not that much important?

I think there is also an argument for counting WAL files recycled as
IOOP_REUSES. We should start thinking about how to interpret the
different IOOps within the two IOContexts and discussing what would be
useful to count. For example, should removing a logfile count as an
IOOP_EVICT? Maybe it is not directly related to "IO" enough or even an
interesting statistic, but we should think about what kinds of
IO-related WAL statistics we want to track.

I added that to TODOs.

Any that we decide not to count for now should be "banned" in
pgstat_tracks_io_op() for clarity. For example, if we create a separate
IOContext for WAL file init, I'm not sure what would count as an
IOOP_EXTEND in IOCONTEXT_NORMAL for IOOBJECT_WAL.

Also, I think there are some backend types which will not generate WAL
and we should determine which those are and skip those rows in
pgstat_tracks_io_object().

I agree, I am working on this. I have a couple of questions:
1. Can client backend and background worker do IOCONTEXT_NORMAL/IOOP_READ?
2. Is there an easy way to check if 'BackendType / IOOBJECT_WAL' does
specific IOOp operations?

diff --git a/src/backend/access/transam/xlog.c
b/src/backend/access/transam/xlog.c
index 8b0710abe6..2ee6c21398 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2207,6 +2207,10 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID
tli, bool flexible)

I think we should likely follow the pattern of using
pgstat_prepare_io_time() and pgstat_count_io_op_time() as it is done
elsewhere. You could pass the IOObject as a parameter to
pgstat_prepare_io_time() in order to determine if we should check
track_io_timing or track_wal_io_timing. And we'll want to check
track_wal_io_timing if IOObject is IOOBJECT_WAL in
pgstat_count_io_op_time().

Done. Instead of passing parameters to pgstat_prepare_io_time(), I
used a slightly different implementation. I return the current time if
there is a chance that any 'time' can be tracked.

INSTR_TIME_SET_CURRENT(duration);

INSTR_TIME_ACCUM_DIFF(PendingWalStats.wal_write_time, duration,
start);

+                    pgstat_count_io_op_time(IOOBJECT_WAL,
IOCONTEXT_NORMAL, IOOP_WRITE, start, 1);
+                } else
+                {

Other users of pgstat_count_io_op_time()/io_op_n() which write multiple
pages at a time pass the number of pages in as the cnt parameter. (see
ExtendBufferedRelLocal() as an example). I think we want to do that for
WAL also. In this case, it would be the local variable "npages" and we
can do it outside of this loop.

It is true that the existing WAL stats count wal_writes here. However,
this is essentially counting write system calls, which is probably not
what we want for pg_stat_io. See [2] for a discussion about whether to
count blocks written back or writeback system calls for a previous
pg_stat_io feature. All of the other block-based IO statistics in
pg_stat_io count the number of blocks.

This being said, we probably want to just leave
PendingWalStats.wal_write++ here. We would normally move it into
pg_stat_io like we have with pgBufferUsage and the db IO stats that are
updated in pgstat_count_io_op_time(). This consolidation makes it easier
to eventually reduce the duplication. However, in this case, it seems
wal_write counts something we don't count in pg_stat_io, so it can
probably be left here. I would still move the
PendingWalStats.wal_write_time into pgstat_count_io_op_time(), since
that seems like it is the same as what will be in pg_stat_io.

Done. I moved PendingWalStats.wal_sync and
PendingWalStats.wal_write_time/PendingWalStats.wal_sync_time to
pgstat_count_io_op_n()/pgstat_count_io_op_time() respectively. Because
of this change, pg_stat_wal's and pg_stat_io's
IOOBJECT_WAL/IOCONTEXT_NORMAL/IOOP_WRITE counts are different but the
rest are the same.

Also, op_bytes for IOOBJECT_WAL/IOCONTEXT_NORMAL should be XLOG_BLCKSZ
(see comment in pg_stat_get_io() in pgstatfuncs.c). Those default to the
same value but can be made to be different.

Done.

I would wrap this line and check other lines to make sure they are not
too long.

Done.

+    } else
+    {
+        pgstat_count_io_op_n(IOOBJECT_WAL, IOCONTEXT_NORMAL, IOOP_FSYNC, 1);
}

PendingWalStats.wal_sync++;

Same feedback as above about using the prepare/count pattern used for
pg_stat_io elsewhere. In this case, you should be able to move
PendingWalStats.wal_sync into there as well.

Done.

There is a track_io_timing variable to control pg_stat_io
timings and a track_wal_io_timing variable to control WAL timings. I
couldn't decide on which logic to enable WAL timings on pg_stat_io.
For now, both pg_stat_io and track_wal_io_timing are needed to be
enabled to track WAL timings in pg_stat_io.

Hmm. I could see a case where someone doesn't want to incur the
overhead of track_io_timing for regular IO but does want to do so for
WAL because they are interested in a specific issue. I'm not sure
though. I could be convinced otherwise (based on relative overhead,
etc).

Done. IOOBJECT_WAL uses track_wal_io_timing regardless of
track_io_timing for now.

[1] /messages/by-id/20230216191138.jotc73lqb7xhfqbi@awork3.anarazel.de
[2] /messages/by-id/20230504165738.4e2hfoddoels542c@awork3.anarazel.de

In addition to these, are WAIT_EVENT_WAL_COPY_* operations needed to
be added to pg_stat_io? If the answer is yes, should I add them to the
current patch?

Any kind of feedback would be appreciated.

Regards,
Nazir Bilal Yavuz
Microsoft

On Thu, Aug 03, 2023 at 04:38:41PM +0300, Nazir Bilal Yavuz wrote:

Current status of the patch is:
- 'WAL read' stats in xlogrecovery.c are added to pg_stat_io.
- IOCONTEXT_INIT is added to count 'WAL init'. 'WAL init' stats are
added to pg_stat_io.
- pg_stat_io shows different op_bytes for the IOOBJECT_WAL operations.
- Working on which 'BackendType / IOContext / IOOp' should be banned
in pg_stat_io.
- Working on adding 'WAL read' to the xlogreader.c and walsender.c.
- PendingWalStats.wal_sync and
PendingWalStats.wal_write_time/PendingWalStats.wal_sync_time are moved
to pgstat_count_io_op_n()/pgstat_count_io_op_time() respectively.

Cool! Thanks for the summary and for continuing to work on this.

TODOs:
- Documentation.
- Thinking about how to interpret the different IOOps within the two
IOContexts and discussing what would be useful to count.
- Decide which 'BackendType / IOContext / IOOp' should not be tracked.
- Adding 'WAL read' to the xlogreader.c and walsender.c. (This could
be an another patch)

Yes, I would be explicit that you are not including WAL IO done exclusively in
the context of replication.

- Adding WAIT_EVENT_WAL_COPY_* operations to pg_stat_io if needed.
(This could be an another patch)

Yes, I think it makes sense as another patch.

On Sat, 22 Jul 2023 at 01:30, Melanie Plageman
<melanieplageman@gmail.com> wrote:

I think it would be good to count WAL reads even though they are not
currently represented in pg_stat_wal. Here is a thread discussing this
[1].

I used the same implementation in the thread link [1]. I added 'WAL
read' to only xlogrecovery.c for now. I didn't add 'WAL read' to
xlogreader.c and walsender.c because they cause some failures on:
'!pgStatLocal.shmem->is_shutdown' asserts. I will spend more time on
these. Also, I added Bharath to CC. I have a question about 'WAL
read':
1. There are two places where 'WAL read' happens.
a. In WALRead() in xlogreader.c, it reads 'count' bytes, most of the
time count is equal to XLOG_BLCKSZ but there are some cases it is not.
For example
- in XLogSendPhysical() in walsender.c WALRead() is called by nbytes
- in WALDumpReadPage() in pg_waldump.c WALRead() is called by count
These nbytes and count variables could be different from XLOG_BLCKSZ.

b. in XLogPageRead() in xlogreader.c, it reads exactly XLOG_BLCKSZ bytes:
pg_pread(readFile, readBuf, XLOG_BLCKSZ, (off_t) readOff);

So, what should op_bytes be set to for 'WAL read' operations?

If there is any combination of BackendType and IOContext which will
always read XLOG_BLCKSZ bytes, we could use XLOG_BLCKSZ for that row's
op_bytes. For other cases, we may have to consider using op_bytes 1 and
tracking reads and write IOOps in number of bytes (instead of number of
pages). I don't actually know if there is a clear separation by
BackendType for these different cases.

The other alternative I see is to use XLOG_BLCKSZ as the op_bytes and
treat op_bytes * number of reads as an approximation of the number of
bytes read. I don't actually know what makes more sense. I don't think I
would like having a number for bytes that is not accurate.

I think we will also want to add an IOContext for WAL initialization.
Then we can track how long is spent doing 'WAL init' (including filling
the WAL file with zeroes). XLogFileInitInternal() is likely where we
would want to add it. And op_bytes for this would likely be
wal_segment_size. I thought I heard about someone proposing adding WAL
init to pg_stat_wal, but I can't find the thread.

Done. I created a new IOCONTEXT_INIT IOContext for the 'WAL init'. I
have a question there:
1. Some of the WAL processes happens at initdb (standalone backend
IOCONTEXT_NORMAL/(IOOP_READ & IOOP_WRITE) and
IOCONTEXT_INIT/(IOOP_WRITE & IOOP_FSYNC)). Since this happens at the
initdb, AFAIK there is no way to set 'track_wal_io_timing' and
'track_io_timing' variables there. So, their timings appear as 0.
Should I use IsBootstrapProcessingMode() to enable WAL io timings at
the initdb or are they not that much important?

I don't have an opinion about this. I can see an argument for doing it
either way. We do track other IO during initdb in pg_stat_io.

Any that we decide not to count for now should be "banned" in
pgstat_tracks_io_op() for clarity. For example, if we create a separate
IOContext for WAL file init, I'm not sure what would count as an
IOOP_EXTEND in IOCONTEXT_NORMAL for IOOBJECT_WAL.

Also, I think there are some backend types which will not generate WAL
and we should determine which those are and skip those rows in
pgstat_tracks_io_object().

I agree, I am working on this. I have a couple of questions:
1. Can client backend and background worker do IOCONTEXT_NORMAL/IOOP_READ?

I don't know the answer to this.

2. Is there an easy way to check if 'BackendType / IOOBJECT_WAL' does
specific IOOp operations?

I don't think there is a general answer to this. You'll have to look at
the code and think about specific things that backend might do that
would require WAL. I think we'll definitely need other community members
to check our work for the valid combinations.

Completing the matrix of valid combinations of BackendType, IOOp, and
IOContext and defining each one is the biggest area where we could use
help from community members.

As an additional TODO, I would explore adding some tests to prevent
accidental removal of the pg_stat_io WAL tracking.

I think we can easily test IOCONTEXT_NORMAL WAL writes in
src/test/regress/sql/stats.sql (perhaps it is worth checking that
synchronous_commit is on in the test). IOCONTEXT_NORMAL WAL fsyncs
should again be easy to test if synchronous_commit is on and fsync is
on.

I'm not sure how to reliably test WAL reads (given timing). Logically,
you can sum WAL reads before a crash is initiated in one of the tests in
the recovery suite, and then sum them after the db has restarted and
there should definitely be an increase in WAL reads, but I don't know if
we need to do something to guarantee that there will have been WAL reads
(to avoid test flakes).

I'm also not sure how to reliably test any IOCONTEXT_INIT operations. We
need a before and after and I can't think of a cheap operation to ensure
a new WAL segment is written to or fsyncd in between a before and after
for the purposes of testing.

diff --git a/src/backend/access/transam/xlog.c
b/src/backend/access/transam/xlog.c
index 8b0710abe6..2ee6c21398 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2207,6 +2207,10 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID
tli, bool flexible)

I think we should likely follow the pattern of using
pgstat_prepare_io_time() and pgstat_count_io_op_time() as it is done
elsewhere. You could pass the IOObject as a parameter to
pgstat_prepare_io_time() in order to determine if we should check
track_io_timing or track_wal_io_timing. And we'll want to check
track_wal_io_timing if IOObject is IOOBJECT_WAL in
pgstat_count_io_op_time().

Done. Instead of passing parameters to pgstat_prepare_io_time(), I
used a slightly different implementation. I return the current time if
there is a chance that any 'time' can be tracked.

Cool!

From 574fdec6ed8073dbc49053e6933db0310c7c62f5 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Thu, 3 Aug 2023 16:11:16 +0300
Subject: [PATCH v2] Show WAL stats on pg_stat_io

This patch aims to showing WAL stats per backend on pg_stat_io view.

With this patch, it can be seen how many WAL operations it makes, their
context, types and total timings per backend in pg_stat_io view.

In the commit message, I would describe what kinds of WAL IO this
patchset currently covers -- i.e. not streaming replication WAL IO.

---
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 60c0b7ec3af..ee7b85e18ca 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2245,6 +2229,9 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli, bool flexible)
startoffset += written;
} while (nleft > 0);

I'm not sure if the right location is here or in
pgstat_count_io_op_time(), but I would explain why you did not move
PendingWalStats.wal_writes counter into pg_stat_io code (and why you did
move the other PendingWalStats counters there.

+			pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_NORMAL,
+									IOOP_WRITE, io_start, npages);
+
npages = 0;

/*
@@ -2938,6 +2925,7 @@ XLogFileInitInternal(XLogSegNo logsegno, TimeLineID logtli,
int fd;
int save_errno;
int open_flags = O_RDWR | O_CREAT | O_EXCL | PG_BINARY;
+ instr_time io_start;

Assert(logtli != 0);

@@ -2981,6 +2969,8 @@ XLogFileInitInternal(XLogSegNo logsegno, TimeLineID logtli,
(errcode_for_file_access(),
errmsg("could not create file \"%s\": %m", tmppath)));

Since you have two calls to pgstat_prepare_io_time() in this function, I
think it would be nice to have a comment above each to the effect of
"start timing writes for stats" and "start timing fsyncs for stats"

+	io_start = pgstat_prepare_io_time();
+
pgstat_report_wait_start(WAIT_EVENT_WAL_INIT_WRITE);

diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c
index becc2bda62e..ee850af5514 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -1587,6 +1587,7 @@ PerformWalRecovery(void)
XLogRecord *record;
bool		reachedRecoveryTarget = false;
TimeLineID	replayTLI;
+	uint32		pgstat_report_wal_frequency = 0;

/*
* Initialize shared variables for tracking progress of WAL replay, as if
@@ -1745,6 +1746,16 @@ PerformWalRecovery(void)
*/
ApplyWalRecord(xlogreader, record, &replayTLI);

+			/*
+			 * Report pending statistics to the cumulative stats system once
+			 * every PGSTAT_REPORT_FREQUENCY times to not hinder performance.
+			 */
+			if (pgstat_report_wal_frequency++ == PGSTAT_REPORT_FREQUENCY)
+			{
+				pgstat_report_wal(false);
+				pgstat_report_wal_frequency = 0;
+			}
+

Is the above needed for your patch to work? What does it do? It should
probably be in a separate commit and should definitely have an
explanation.

--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -87,17 +87,25 @@ pgstat_count_io_op_n(IOObject io_object, IOContext io_context, IOOp io_op, uint3
Assert((unsigned int) io_op < IOOP_NUM_TYPES);
Assert(pgstat_tracks_io_op(MyBackendType, io_object, io_context, io_op));

I would add a comment here explaining that pg_stat_wal doesn't count WAL
init or WAL reads.

+	if(io_object == IOOBJECT_WAL && io_context == IOCONTEXT_NORMAL &&
+	   io_op == IOOP_FSYNC)
+		PendingWalStats.wal_sync += cnt;
+
PendingIOStats.counts[io_object][io_context][io_op] += cnt;

have_iostats = true;
}

+/*
+ * Prepares io_time for pgstat_count_io_op_time() function. It needs to return
+ * current time if there is a chance that any 'time' can be tracked.
+ */
instr_time
pgstat_prepare_io_time(void)
{
instr_time	io_start;

-	if (track_io_timing)
+	if(track_io_timing || track_wal_io_timing)
INSTR_TIME_SET_CURRENT(io_start);
else
INSTR_TIME_SET_ZERO(io_start);

Since you asked me off-list why we had to do INSTR_TIME_SET_ZERO() and I
couldn't remember, it is probably worth a comment.

pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
instr_time start_time, uint32 cnt)
{
-	if (track_io_timing)
+	if (pgstat_should_track_io_time(io_object, io_context))
{
instr_time	io_time;

@@ -124,6 +148,9 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));

Now that we are adding more if statements to this function, I think we
should start adding more comments.

We should explain what the different counters here are for e.g.
pgBufferUsage for EXPLAIN, PendingWalStats for pg_stat_wal.

We should also explain what is tracked for each and why it differs --
e.g. some track time and some don't, some track only reads or writes,
etc.

Also we should mention why we are consolidating them here. That is, we
want to eventually deduplicate these counters, so we are consolidating
them first. This also makes it easy to compare what is tracked for which
stats or instrumentation purpose.

And for those IO counters that we haven't moved here, we should mention
it is because they track at a different level of granularity or at a
different point in the call stack.

if (io_object == IOOBJECT_RELATION)
INSTR_TIME_ADD(pgBufferUsage.blk_write_time, io_time);
+			/* Track IOOBJECT_WAL/IOCONTEXT_NORMAL times on PendingWalStats */
+			else if (io_object == IOOBJECT_WAL && io_context == IOCONTEXT_NORMAL)
+				INSTR_TIME_ADD(PendingWalStats.wal_write_time, io_time);
}

Also, I would reorder the if statements to be in order of the enum
values (e.g. FSYNC, READ, WRITE).

else if (io_op == IOOP_READ)
{
@@ -131,6 +158,12 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
if (io_object == IOOBJECT_RELATION)
INSTR_TIME_ADD(pgBufferUsage.blk_read_time, io_time);
}
+		else if (io_op == IOOP_FSYNC)
+		{
+			/* Track IOOBJECT_WAL/IOCONTEXT_NORMAL times on PendingWalStats */

I wouldn't squeeze this comment here like this. It is hard to read

+			if (io_object == IOOBJECT_WAL && io_context == IOCONTEXT_NORMAL)
+				INSTR_TIME_ADD(PendingWalStats.wal_sync_time, io_time);

+ * op_bytes can change according to IOObject and IOContext.
+ * Return BLCKSZ as default.
+ */
+int
+pgstat_get_io_op_btyes(IOObject io_object, IOContext io_context)
+{

Small typo in function name:
pgstat_get_io_op_btyes -> pgstat_get_io_op_bytes
I'd also mention why BLCKSZ is the default

+	if (io_object == IOOBJECT_WAL)
+	{
+		if (io_context == IOCONTEXT_NORMAL)
+			return XLOG_BLCKSZ;
+		else if (io_context == IOCONTEXT_INIT)
+			return wal_segment_size;
+	}
+
+	return BLCKSZ;
+}

@@ -350,6 +405,15 @@ pgstat_tracks_io_object(BackendType bktype, IOObject io_object,
if (!pgstat_tracks_io_bktype(bktype))
return false;

+	/*
+	 * Currently, IO on IOOBJECT_WAL IOObject can only occur in the
+	 * IOCONTEXT_NORMAL and IOCONTEXT_INIT IOContext.
+	 */
+	if (io_object == IOOBJECT_WAL &&
+		(io_context != IOCONTEXT_NORMAL &&

Little bit of errant whitespace here.

/*
* Currently, IO on temporary relations can only occur in the
* IOCONTEXT_NORMAL IOContext.
@@ -439,6 +503,14 @@ pgstat_tracks_io_op(BackendType bktype, IOObject io_object,
if (io_context == IOCONTEXT_BULKREAD && io_op == IOOP_EXTEND)
return false;

I would expand on the comment to explain what NORMAL is for WAL -- what
we consider normal to be and why. And why it is different than INIT.

+	if(io_object == IOOBJECT_WAL && io_context == IOCONTEXT_INIT &&
+	   !(io_op == IOOP_WRITE || io_op == IOOP_FSYNC))
+	   return false;
+
+	if(io_object == IOOBJECT_WAL && io_context == IOCONTEXT_NORMAL &&
+	   !(io_op == IOOP_WRITE || io_op == IOOP_READ || io_op == IOOP_FSYNC))
+	   return false;

These are the first "bans" that we have for an IOOp for a specific
combination of io_context and io_object. We should add a new comment for
this and perhaps consider what ordering makes most sense. I tried to
organize the bans from most broad to most specific at the bottom.

--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -1409,7 +1410,8 @@ pg_stat_get_io(PG_FUNCTION_ARGS)
* and constant multipliers, once non-block-oriented IO (e.g.
* temporary file IO) is tracked.
*/
-				values[IO_COL_CONVERSION] = Int64GetDatum(BLCKSZ);

There's a comment above this in the code that says this is hard-coded to
BLCKSZ. That comment needs to be updated or removed (in lieu of the
comment in your pgstat_get_io_op_bytes() function).

+				op_bytes = pgstat_get_io_op_btyes(io_obj, io_context);
+				values[IO_COL_CONVERSION] = Int64GetDatum(op_bytes);

+extern PGDLLIMPORT bool track_wal_io_timing;
+extern PGDLLIMPORT int wal_segment_size;

These shouldn't be in two places (i.e. they are already in xlog.h and
you added them in pgstat.h. pg_stat_io.c includes bufmgr.h for
track_io_timing, so you can probably justify including xlog.h.

- Melanie

Hi,

Thanks for the review!

Current status of the patch is:
- IOOBJECT_WAL / IOCONTEXT_NORMAL read, write and fsync stats are added.
- IOOBJECT_WAL / IOCONTEXT_NORMAL write and fsync tests are added.
- IOOBJECT_WAL / IOCONTEXT_INIT stats are added.
- pg_stat_io shows different op_bytes for the IOOBJECT_WAL operations.
- Working on which 'BackendType / IOContext / IOOp' should be banned in
pg_stat_io.
- PendingWalStats.wal_sync and PendingWalStats.wal_write_time /
PendingWalStats.wal_sync_time are moved to pgstat_count_io_op_n() /
pgstat_count_io_op_time() respectively.

TODOs:
- Documentation.
- Try to set op_bytes for BackendType / IOContext.
- Decide which 'BackendType / IOContext / IOOp' should not be tracked.
- Add IOOBJECT_WAL / IOCONTEXT_NORMAL read tests.
- Add IOOBJECT_WAL / IOCONTEXT_INIT tests.

I am adding tracking of BackendType / IOContext / IOOp as tables, empty
cell means it is not decided yet:

IOCONTEXT_NORMAL / Backend / IOOp table:

╔═════════════════════╦═══════╦═══════╦═══════╗
║ IOCONTEXT_NORMAL ║ read ║ write ║ fsync ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ autovacuum launcher ║ FALSE ║ FALSE ║ FALSE ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ autovacuum worker ║ FALSE ║ TRUE ║ TRUE ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ client backend ║ ║ TRUE ║ TRUE ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ background worker ║ ║ ║ ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ background writer ║ ║ TRUE ║ TRUE ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ checkpointer ║ ║ TRUE ║ TRUE ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ standalone backend ║ TRUE ║ TRUE ║ TRUE ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ startup ║ TRUE ║ ║ ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ walreceiver ║ ║ ║ ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ walsender ║ ║ ║ ║
╠═════════════════════╬═══════╬═══════╬═══════╣
║ walwriter ║ ║ TRUE ║ TRUE ║
╚═════════════════════╩═══════╩═══════╩═══════╝

IOCONTEXT_WAL_INIT / Backend / IOOp table:

╔═════════════════════╦═══════╦═══════╗
║ IOCONTEXT_WAL_INIT ║ write ║ fsync ║
╠═════════════════════╬═══════╬═══════╣
║ autovacuum launcher ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ autovacuum worker ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ client backend ║ TRUE ║ TRUE ║
╠═════════════════════╬═══════╬═══════╣
║ background worker ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ background writer ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ checkpointer ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ standalone backend ║ TRUE ║ TRUE ║
╠═════════════════════╬═══════╬═══════╣
║ startup ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ walreceiver ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ walsender ║ ║ ║
╠═════════════════════╬═══════╬═══════╣
║ walwriter ║ ║ ║
╚═════════════════════╩═══════╩═══════╝

On Wed, 9 Aug 2023 at 21:52, Melanie Plageman <melanieplageman@gmail.com>
wrote:

On Sat, 22 Jul 2023 at 01:30, Melanie Plageman
<melanieplageman@gmail.com> wrote:

I think it would be good to count WAL reads even though they are not
currently represented in pg_stat_wal. Here is a thread discussing this
[1].

I used the same implementation in the thread link [1]. I added 'WAL
read' to only xlogrecovery.c for now. I didn't add 'WAL read' to
xlogreader.c and walsender.c because they cause some failures on:
'!pgStatLocal.shmem->is_shutdown' asserts. I will spend more time on
these. Also, I added Bharath to CC. I have a question about 'WAL
read':
1. There are two places where 'WAL read' happens.
a. In WALRead() in xlogreader.c, it reads 'count' bytes, most of the
time count is equal to XLOG_BLCKSZ but there are some cases it is not.
For example
- in XLogSendPhysical() in walsender.c WALRead() is called by nbytes
- in WALDumpReadPage() in pg_waldump.c WALRead() is called by count
These nbytes and count variables could be different from XLOG_BLCKSZ.

b. in XLogPageRead() in xlogreader.c, it reads exactly XLOG_BLCKSZ

bytes:

pg_pread(readFile, readBuf, XLOG_BLCKSZ, (off_t) readOff);

So, what should op_bytes be set to for 'WAL read' operations?

If there is any combination of BackendType and IOContext which will
always read XLOG_BLCKSZ bytes, we could use XLOG_BLCKSZ for that row's
op_bytes. For other cases, we may have to consider using op_bytes 1 and
tracking reads and write IOOps in number of bytes (instead of number of
pages). I don't actually know if there is a clear separation by
BackendType for these different cases.

I agree. I will edit that later, added to TODOs.

The other alternative I see is to use XLOG_BLCKSZ as the op_bytes and
treat op_bytes * number of reads as an approximation of the number of
bytes read. I don't actually know what makes more sense. I don't think I
would like having a number for bytes that is not accurate.

Yes, the prior one makes more sense to me.

Should I use IsBootstrapProcessingMode() to enable WAL io timings at
the initdb or are they not that much important?

I don't have an opinion about this. I can see an argument for doing it
either way. We do track other IO during initdb in pg_stat_io.

I didn't add it for now. It is an easy change, it could be added later.

As an additional TODO, I would explore adding some tests to prevent
accidental removal of the pg_stat_io WAL tracking.

I think we can easily test IOCONTEXT_NORMAL WAL writes in
src/test/regress/sql/stats.sql (perhaps it is worth checking that
synchronous_commit is on in the test). IOCONTEXT_NORMAL WAL fsyncs
should again be easy to test if synchronous_commit is on and fsync is
on.

I'm not sure how to reliably test WAL reads (given timing). Logically,
you can sum WAL reads before a crash is initiated in one of the tests in
the recovery suite, and then sum them after the db has restarted and
there should definitely be an increase in WAL reads, but I don't know if
we need to do something to guarantee that there will have been WAL reads
(to avoid test flakes).

I'm also not sure how to reliably test any IOCONTEXT_INIT operations. We
need a before and after and I can't think of a cheap operation to ensure
a new WAL segment is written to or fsyncd in between a before and after
for the purposes of testing.

IOOBJECT_WAL / IOCONTEXT_NORMAL write and fsync tests are added.
For the IOCONTEXT_NORMAL reads and IOCONTEXT_INIT tests, I couldn't find a
way to avoid test flakes. I am open to suggestions. I added these to TODOs.

---
diff --git a/src/backend/access/transam/xlog.c

b/src/backend/access/transam/xlog.c

index 60c0b7ec3af..ee7b85e18ca 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2245,6 +2229,9 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli,

bool flexible)

startoffset += written;
} while (nleft > 0);

I'm not sure if the right location is here or in
pgstat_count_io_op_time(), but I would explain why you did not move
PendingWalStats.wal_writes counter into pg_stat_io code (and why you did
move the other PendingWalStats counters there.

+ pgstat_count_io_op_time(IOOBJECT_WAL,

IOCONTEXT_NORMAL,

+

IOOP_WRITE, io_start, npages);

+
npages = 0;

/*
@@ -2938,6 +2925,7 @@ XLogFileInitInternal(XLogSegNo logsegno,

TimeLineID logtli,

int fd;
int save_errno;
int open_flags = O_RDWR | O_CREAT | O_EXCL |

PG_BINARY;

+ instr_time io_start;

Assert(logtli != 0);

@@ -2981,6 +2969,8 @@ XLogFileInitInternal(XLogSegNo logsegno,

TimeLineID logtli,

(errcode_for_file_access(),
errmsg("could not create file \"%s\":

%m", tmppath)));

Since you have two calls to pgstat_prepare_io_time() in this function, I
think it would be nice to have a comment above each to the effect of
"start timing writes for stats" and "start timing fsyncs for stats"

Done.

+     io_start = pgstat_prepare_io_time();
+
pgstat_report_wait_start(WAIT_EVENT_WAL_INIT_WRITE);

diff --git a/src/backend/access/transam/xlogrecovery.c

b/src/backend/access/transam/xlogrecovery.c

index becc2bda62e..ee850af5514 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -1587,6 +1587,7 @@ PerformWalRecovery(void)
XLogRecord *record;
bool            reachedRecoveryTarget = false;
TimeLineID      replayTLI;
+     uint32          pgstat_report_wal_frequency = 0;

/*
* Initialize shared variables for tracking progress of WAL

replay, as if

@@ -1745,6 +1746,16 @@ PerformWalRecovery(void)
*/
ApplyWalRecord(xlogreader, record, &replayTLI);

+                     /*
+                      * Report pending statistics to the cumulative

stats system once

+ * every PGSTAT_REPORT_FREQUENCY times to not

hinder performance.

+                      */
+                     if (pgstat_report_wal_frequency++ ==

PGSTAT_REPORT_FREQUENCY)

+                     {
+                             pgstat_report_wal(false);
+                             pgstat_report_wal_frequency = 0;
+                     }
+

Is the above needed for your patch to work? What does it do? It should
probably be in a separate commit and should definitely have an
explanation.

Done, I omit that part.

--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -87,17 +87,25 @@ pgstat_count_io_op_n(IOObject io_object, IOContext

io_context, IOOp io_op, uint3

Assert((unsigned int) io_op < IOOP_NUM_TYPES);
Assert(pgstat_tracks_io_op(MyBackendType, io_object, io_context,

io_op));

I would add a comment here explaining that pg_stat_wal doesn't count WAL
init or WAL reads.

Done.

+     if(io_object == IOOBJECT_WAL && io_context == IOCONTEXT_NORMAL &&
+        io_op == IOOP_FSYNC)
+             PendingWalStats.wal_sync += cnt;
+
PendingIOStats.counts[io_object][io_context][io_op] += cnt;

have_iostats = true;
}

+/*
+ * Prepares io_time for pgstat_count_io_op_time() function. It needs

to return

+ * current time if there is a chance that any 'time' can be tracked.
+ */
instr_time
pgstat_prepare_io_time(void)
{
instr_time      io_start;

-     if (track_io_timing)
+     if(track_io_timing || track_wal_io_timing)
INSTR_TIME_SET_CURRENT(io_start);
else
INSTR_TIME_SET_ZERO(io_start);

Since you asked me off-list why we had to do INSTR_TIME_SET_ZERO() and I
couldn't remember, it is probably worth a comment.

Done.

pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp

io_op,

instr_time start_time,

uint32 cnt)

{
-     if (track_io_timing)
+     if (pgstat_should_track_io_time(io_object, io_context))
{
instr_time      io_time;

@@ -124,6 +148,9 @@ pgstat_count_io_op_time(IOObject io_object,

IOContext io_context, IOOp io_op,

pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));

Now that we are adding more if statements to this function, I think we
should start adding more comments.

We should explain what the different counters here are for e.g.
pgBufferUsage for EXPLAIN, PendingWalStats for pg_stat_wal.

We should also explain what is tracked for each and why it differs --
e.g. some track time and some don't, some track only reads or writes,
etc.

Also we should mention why we are consolidating them here. That is, we
want to eventually deduplicate these counters, so we are consolidating
them first. This also makes it easy to compare what is tracked for which
stats or instrumentation purpose.

And for those IO counters that we haven't moved here, we should mention
it is because they track at a different level of granularity or at a
different point in the call stack.

Done.

if (io_object == IOOBJECT_RELATION)

INSTR_TIME_ADD(pgBufferUsage.blk_write_time, io_time);

+ /* Track IOOBJECT_WAL/IOCONTEXT_NORMAL times on

PendingWalStats */

+ else if (io_object == IOOBJECT_WAL && io_context

== IOCONTEXT_NORMAL)

+

INSTR_TIME_ADD(PendingWalStats.wal_write_time, io_time);

}

Also, I would reorder the if statements to be in order of the enum
values (e.g. FSYNC, READ, WRITE).

Done.

else if (io_op == IOOP_READ)
{
@@ -131,6 +158,12 @@ pgstat_count_io_op_time(IOObject io_object,

IOContext io_context, IOOp io_op,

if (io_object == IOOBJECT_RELATION)

INSTR_TIME_ADD(pgBufferUsage.blk_read_time, io_time);

}
+             else if (io_op == IOOP_FSYNC)
+             {
+                     /* Track IOOBJECT_WAL/IOCONTEXT_NORMAL times on

PendingWalStats */

I wouldn't squeeze this comment here like this. It is hard to read

Done.

+ if (io_object == IOOBJECT_WAL && io_context ==

IOCONTEXT_NORMAL)

+

INSTR_TIME_ADD(PendingWalStats.wal_sync_time, io_time);

+ * op_bytes can change according to IOObject and IOContext.
+ * Return BLCKSZ as default.
+ */
+int
+pgstat_get_io_op_btyes(IOObject io_object, IOContext io_context)
+{

Small typo in function name:
pgstat_get_io_op_btyes -> pgstat_get_io_op_bytes
I'd also mention why BLCKSZ is the default

Done.

+     if (io_object == IOOBJECT_WAL)
+     {
+             if (io_context == IOCONTEXT_NORMAL)
+                     return XLOG_BLCKSZ;
+             else if (io_context == IOCONTEXT_INIT)
+                     return wal_segment_size;
+     }
+
+     return BLCKSZ;
+}

@@ -350,6 +405,15 @@ pgstat_tracks_io_object(BackendType bktype,

IOObject io_object,

if (!pgstat_tracks_io_bktype(bktype))
return false;

+     /*
+      * Currently, IO on IOOBJECT_WAL IOObject can only occur in the
+      * IOCONTEXT_NORMAL and IOCONTEXT_INIT IOContext.
+      */
+     if (io_object == IOOBJECT_WAL &&
+             (io_context != IOCONTEXT_NORMAL &&

Little bit of errant whitespace here.

Done.

/*
* Currently, IO on temporary relations can only occur in the
* IOCONTEXT_NORMAL IOContext.
@@ -439,6 +503,14 @@ pgstat_tracks_io_op(BackendType bktype, IOObject

io_object,

if (io_context == IOCONTEXT_BULKREAD && io_op == IOOP_EXTEND)
return false;

I would expand on the comment to explain what NORMAL is for WAL -- what
we consider normal to be and why. And why it is different than INIT.

Done.

+     if(io_object == IOOBJECT_WAL && io_context == IOCONTEXT_INIT &&
+        !(io_op == IOOP_WRITE || io_op == IOOP_FSYNC))
+        return false;
+
+     if(io_object == IOOBJECT_WAL && io_context == IOCONTEXT_NORMAL &&
+        !(io_op == IOOP_WRITE || io_op == IOOP_READ || io_op ==

IOOP_FSYNC))

+ return false;

These are the first "bans" that we have for an IOOp for a specific
combination of io_context and io_object. We should add a new comment for
this and perhaps consider what ordering makes most sense. I tried to
organize the bans from most broad to most specific at the bottom.

Done.

--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -1409,7 +1410,8 @@ pg_stat_get_io(PG_FUNCTION_ARGS)
* and constant multipliers, once

non-block-oriented IO (e.g.

* temporary file IO) is tracked.
*/
- values[IO_COL_CONVERSION] =

Int64GetDatum(BLCKSZ);

There's a comment above this in the code that says this is hard-coded to
BLCKSZ. That comment needs to be updated or removed (in lieu of the
comment in your pgstat_get_io_op_bytes() function).

Done.

+ op_bytes = pgstat_get_io_op_btyes(io_obj,

io_context);

+ values[IO_COL_CONVERSION] =

Int64GetDatum(op_bytes);

+extern PGDLLIMPORT bool track_wal_io_timing;
+extern PGDLLIMPORT int wal_segment_size;

These shouldn't be in two places (i.e. they are already in xlog.h and
you added them in pgstat.h. pg_stat_io.c includes bufmgr.h for
track_io_timing, so you can probably justify including xlog.h.

Done.

Any kind of feedback would be appreciated.

Regards,
Nazir Bilal Yavuz
Microsoft

On Wed, Sep 20, 2023 at 10:57:48AM +0300, Nazir Bilal Yavuz wrote:

Any kind of feedback would be appreciated.

This was registered in the CF, so I have given it a look. Note that
0001 has a conflict with pgstat_count_io_op_time(), so it cannot be
applied.

+pgstat_should_track_io_time(IOObject io_object, IOContext io_context)
+{
+	/*
+	 * io times of IOOBJECT_WAL IOObject needs to be tracked when
+	 * 'track_wal_io_timing' is set regardless of 'track_io_timing'.
+	 */
+	if (io_object == IOOBJECT_WAL)
+		return track_wal_io_timing;
+
+	return track_io_timing;

I can see the temptation to do that, but I have mixed feelings about
the approach of mixing two GUCs in a code path dedicated to pg_stat_io
where now we only rely on track_io_timing. The result brings
confusion, while making pg_stat_io, which is itself only used for
block-based operations, harder to read.

The suggestion I am seeing here to have a pg_stat_io_wal (with a SRF)
is quite tempting, actually, creating a neat separation between the
existing pg_stat_io and pg_stat_wal (not a SRF), with a third view
that provides more details about the contexts and backend types for
the WAL stats with its relevant fields:
/messages/by-id/CAAKRu_bM55pj3pPRW0nd_-paWHLRkOU69r816AeztBBa-N1HLA@mail.gmail.com

And perhaps just putting that everything that calls
pgstat_count_io_op_time() under track_io_timing is just natural?
What's the performance regression you would expect if both WAL and
block I/O are controlled by that, still one would expect only one of
them?

On top of that pg_stat_io is now for block-based I/O operations, so
that does not fit entirely in the picture, though I guess that Melanie
has thought more on the matter than me. That may be also a matter of
taste.

+      /*  Report pending statistics to the cumulative stats system */
+      pgstat_report_wal(false);

This is hidden in 0001, still would be better if handled as a patch on
its own and optionally backpatch it as we did for the bgwriter with
e64c733bb1?

Side note: I think that we should spend more efforts in documenting
what IOContext and IOOp mean. Not something directly related to this
patch, still this patch or things similar make it a bit harder which
part of it is used for what by reading pgstat.h.
--
Michael

Hi,

Thank you for the feedback!

On Thu, 26 Oct 2023 at 09:28, Michael Paquier <michael@paquier.xyz> wrote:

On Wed, Sep 20, 2023 at 10:57:48AM +0300, Nazir Bilal Yavuz wrote:

Any kind of feedback would be appreciated.

This was registered in the CF, so I have given it a look. Note that
0001 has a conflict with pgstat_count_io_op_time(), so it cannot be
applied.

+pgstat_should_track_io_time(IOObject io_object, IOContext io_context)
+{
+       /*
+        * io times of IOOBJECT_WAL IOObject needs to be tracked when
+        * 'track_wal_io_timing' is set regardless of 'track_io_timing'.
+        */
+       if (io_object == IOOBJECT_WAL)
+               return track_wal_io_timing;
+
+       return track_io_timing;

I can see the temptation to do that, but I have mixed feelings about
the approach of mixing two GUCs in a code path dedicated to pg_stat_io
where now we only rely on track_io_timing. The result brings
confusion, while making pg_stat_io, which is itself only used for
block-based operations, harder to read.

The suggestion I am seeing here to have a pg_stat_io_wal (with a SRF)
is quite tempting, actually, creating a neat separation between the
existing pg_stat_io and pg_stat_wal (not a SRF), with a third view
that provides more details about the contexts and backend types for
the WAL stats with its relevant fields:
/messages/by-id/CAAKRu_bM55pj3pPRW0nd_-paWHLRkOU69r816AeztBBa-N1HLA@mail.gmail.com

And perhaps just putting that everything that calls
pgstat_count_io_op_time() under track_io_timing is just natural?
What's the performance regression you would expect if both WAL and
block I/O are controlled by that, still one would expect only one of
them?

I will check these and I hope I will come back with something meaningful.

+      /*  Report pending statistics to the cumulative stats system */
+      pgstat_report_wal(false);

This is hidden in 0001, still would be better if handled as a patch on
its own and optionally backpatch it as we did for the bgwriter with
e64c733bb1?

I thought about it again and found the use of
'pgstat_report_wal(false);' here wrong. This was mainly for flushing
WAL stats because of the WAL reads but pg_stat_wal doesn't have WAL
read stats, so there is no need to flush WAL stats here. I think this
should be replaced with 'pgstat_flush_io(false);'.

Side note: I think that we should spend more efforts in documenting
what IOContext and IOOp mean. Not something directly related to this
patch, still this patch or things similar make it a bit harder which
part of it is used for what by reading pgstat.h.

I agree.

Regards,
Nazir Bilal Yavuz
Microsoft

Hi,

On Tue, 31 Oct 2023 at 16:57, Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:

On Thu, 26 Oct 2023 at 09:28, Michael Paquier <michael@paquier.xyz> wrote:

And perhaps just putting that everything that calls
pgstat_count_io_op_time() under track_io_timing is just natural?
What's the performance regression you would expect if both WAL and
block I/O are controlled by that, still one would expect only one of
them?

I will check these and I hope I will come back with something meaningful.

I applied the patches on upstream postgres and then run pgbench for each
available clock sources couple of times:
# Set fsync = off and track_io_timing = on
# pgbench -i -s 100 test
# pgbench -M prepared -c16 -j8 -f <( echo "SELECT
pg_logical_emit_message(true, \:client_id::text, '1234567890');") -T60 test

Results are:

╔═════════╦═══════════════════════════════╦════════╗
║ ║ track_wal_io_timing ║ ║
╠═════════╬═══════════════╦═══════════════╬════════╣
║ clock ║ on ║ off ║ change ║
║ sources ║ ║ ║ ║
╠═════════╬═══════════════╬═══════════════╬════════╣
║ tsc ║ ║ ║ ║
║ ║ 514814.459170 ║ 519826.284139 ║ %1 ║
╠═════════╬═══════════════╬═══════════════╬════════╣
║ hpet ║ ║ ║ ║
║ ║ 132116.272121 ║ 141820.548447 ║ %7 ║
╠═════════╬═══════════════╬═══════════════╬════════╣
║ acpi_pm ║ ║ ║ ║
║ ║ 394793.092255 ║ 403723.874719 ║ %2 ║
╚═════════╩═══════════════╩═══════════════╩════════╝

Regards,
Nazir Bilal Yavuz
Microsoft

On Mon, Nov 06, 2023 at 03:35:01PM +0300, Nazir Bilal Yavuz wrote:

Results are:

╔═════════╦═══════════════════════════════╦════════╗
║ ║ track_wal_io_timing ║ ║
╠═════════╬═══════════════╦═══════════════╬════════╣
║ clock ║ on ║ off ║ change ║
║ sources ║ ║ ║ ║
╠═════════╬═══════════════╬═══════════════╬════════╣
║ tsc ║ ║ ║ ║
║ ║ 514814.459170 ║ 519826.284139 ║ %1 ║
╠═════════╬═══════════════╬═══════════════╬════════╣
║ hpet ║ ║ ║ ║
║ ║ 132116.272121 ║ 141820.548447 ║ %7 ║
╠═════════╬═══════════════╬═══════════════╬════════╣
║ acpi_pm ║ ║ ║ ║
║ ║ 394793.092255 ║ 403723.874719 ║ %2 ║
╚═════════╩═══════════════╩═══════════════╩════════╝

Thanks for the tests. That's indeed noticeable under this load.
Better to keep track_io_timing and track_wal_io_timing as two
separated beasts, at least that's clear.
--
Michael

Hi,

On 2023-10-26 15:28:32 +0900, Michael Paquier wrote:

On top of that pg_stat_io is now for block-based I/O operations, so
that does not fit entirely in the picture, though I guess that Melanie
has thought more on the matter than me. That may be also a matter of
taste.

I strongly disagree. A significant part of the design of pg_stat_io was to
make it possible to collect multiple sources of IO in a single view, so that
sysadmins don't have to look in dozens of places to figure out what is causing
what kind of IO.

We should over time collect all sources of IO in pg_stat_io. For some things
we might want to also have more detailed information in other views (e.g. it
doesn't make sense to track FPIs in pg_stat_io, but does make sense in
pg_stat_wal) - but that should be in addition, not instead of.

Greetings,

Andres Freund

On Tue, Nov 07, 2023 at 03:30:48PM -0800, Andres Freund wrote:

I strongly disagree. A significant part of the design of pg_stat_io was to
make it possible to collect multiple sources of IO in a single view, so that
sysadmins don't have to look in dozens of places to figure out what is causing
what kind of IO.

Okay. Point taken.

We should over time collect all sources of IO in pg_stat_io. For some things
we might want to also have more detailed information in other views (e.g. it
doesn't make sense to track FPIs in pg_stat_io, but does make sense in
pg_stat_wal) - but that should be in addition, not instead of.

Sure. I understand here that you mean the number of FPIs counted when
a record is inserted, different from the path where we decide to write
and/or flush WAL. The proposed patch seems to be a bit inconsistent
regarding wal_sync_time, by the way.

By the way, if the write/sync quantities and times begin to be tracked
by pg_stat_io, I'd see a pretty good argument in removing the
equivalent columns in pg_stat_wal. It looks like this would reduce
the confusion related to the handling of PendingWalStats added in
pgstat_io.c, for one.
--
Michael

Hi,

On 2023-11-08 09:52:16 +0900, Michael Paquier wrote:

By the way, if the write/sync quantities and times begin to be tracked
by pg_stat_io, I'd see a pretty good argument in removing the
equivalent columns in pg_stat_wal. It looks like this would reduce
the confusion related to the handling of PendingWalStats added in
pgstat_io.c, for one.

Another approach would be to fetch the relevant columns from pg_stat_io in the
pg_stat_wal view. That'd avoid double accounting and breaking existing
monitoring.

Greetings,

Andres Freund

On Tue, Nov 07, 2023 at 05:19:28PM -0800, Andres Freund wrote:

Another approach would be to fetch the relevant columns from pg_stat_io in the
pg_stat_wal view. That'd avoid double accounting and breaking existing
monitoring.

Yep, I'd be OK with that as well to maintain compatibility.
--
Michael

On Wed, Nov 08, 2023 at 10:27:44AM +0900, Michael Paquier wrote:

Yep, I'd be OK with that as well to maintain compatibility.

By the way, note that the patch is failing to apply, and that I've
switched it as waiting on author on 10/26.
--
Michael

On Wed, Sep 20, 2023 at 1:28 PM Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:

Hi,

Thanks for the review!

Current status of the patch is:
- IOOBJECT_WAL / IOCONTEXT_NORMAL read, write and fsync stats are added.
- IOOBJECT_WAL / IOCONTEXT_NORMAL write and fsync tests are added.
- IOOBJECT_WAL / IOCONTEXT_INIT stats are added.
- pg_stat_io shows different op_bytes for the IOOBJECT_WAL operations.
- Working on which 'BackendType / IOContext / IOOp' should be banned in pg_stat_io.
- PendingWalStats.wal_sync and PendingWalStats.wal_write_time / PendingWalStats.wal_sync_time are moved to pgstat_count_io_op_n() / pgstat_count_io_op_time() respectively.

TODOs:
- Documentation.
- Try to set op_bytes for BackendType / IOContext.
- Decide which 'BackendType / IOContext / IOOp' should not be tracked.
- Add IOOBJECT_WAL / IOCONTEXT_NORMAL read tests.
- Add IOOBJECT_WAL / IOCONTEXT_INIT tests.

This patchset currently covers:
- IOOBJECT_WAL / IOCONTEXT_NORMAL read, write and fsync.
- IOOBJECT_WAL / IOCONTEXT_INIT write and fsync.

doesn't cover:
- Streaming replication WAL IO.

Is there any plan to account for WAL read stats in the WALRead()
function which will cover walsenders i.e. WAL read by logical and
streaming replication, WAL read by pg_walinspect and so on? I see the
patch already covers WAL read stats by recovery in XLogPageRead(), but
not other page_read callbacks which will end up in WALRead()
eventually. If added, the feature at
/messages/by-id/CALj2ACXKKK=wbiG5_t6dGao5GoecMwRkhr7GjVBM_jg54+Na=Q@mail.gmail.com
can then extend it to cover WAL read from WAL buffer stats.

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

Hi,

Thanks for all the feedback!

On Wed, 8 Nov 2023 at 08:59, Michael Paquier <michael@paquier.xyz> wrote:

By the way, note that the patch is failing to apply, and that I've
switched it as waiting on author on 10/26.

Here is an updated patchset in attachment. Rebased on the latest HEAD
and changed 'pgstat_report_wal(false)' to 'pgstat_flush_io(false)' in
xlogrecovery.c. I will share the new version of the patchset once I
address the feedback.

Regards,
Nazir Bilal Yavuz
Microsoft

Hi,

On Wed, 8 Nov 2023 at 04:19, Andres Freund <andres@anarazel.de> wrote:

Hi,

On 2023-11-08 09:52:16 +0900, Michael Paquier wrote:

By the way, if the write/sync quantities and times begin to be tracked
by pg_stat_io, I'd see a pretty good argument in removing the
equivalent columns in pg_stat_wal. It looks like this would reduce
the confusion related to the handling of PendingWalStats added in
pgstat_io.c, for one.

Another approach would be to fetch the relevant columns from pg_stat_io in the
pg_stat_wal view. That'd avoid double accounting and breaking existing
monitoring.

There are some differences between pg_stat_wal and pg_stat_io while
collecting WAL stats. For example in the XLogWrite() function in the
xlog.c file, pg_stat_wal counts wal_writes as write system calls. This
is not something we want for pg_stat_io since pg_stat_io counts the
number of blocks rather than the system calls, so instead incremented
pg_stat_io by npages.

Could that cause a problem since pg_stat_wal's behaviour will be
changed? Of course, as an alternative we could change pg_stat_io's
behaviour but in the end either pg_stat_wal's or pg_stat_io's
behaviour will be changed.

Regards,
Nazir Bilal Yavuz
Microsoft

On Thu, Nov 09, 2023 at 02:39:26PM +0300, Nazir Bilal Yavuz wrote:

There are some differences between pg_stat_wal and pg_stat_io while
collecting WAL stats. For example in the XLogWrite() function in the
xlog.c file, pg_stat_wal counts wal_writes as write system calls. This
is not something we want for pg_stat_io since pg_stat_io counts the
number of blocks rather than the system calls, so instead incremented
pg_stat_io by npages.

Could that cause a problem since pg_stat_wal's behaviour will be
changed? Of course, as an alternative we could change pg_stat_io's
behaviour but in the end either pg_stat_wal's or pg_stat_io's
behaviour will be changed.

Yep, that could be confusing for existing applications that track the
information of pg_stat_wal. The number of writes is not something
that can be correctly shared between both. The timings for the writes
and the syncs could be shared at least, right?

This slightly relates to pgstat_count_io_op_n() in your latest patch,
where it feels a bit weird to see an update of
PendingWalStats.wal_sync sit in the middle of a routine dedicated to
pg_stat_io.. I am not completely sure what's the right balance here,
but I would try to implement things so as pg_stat_io paths does not
need to know about PendingWalStats.
--
Michael

Hi,

Thanks for the feedback.

On Mon, 20 Nov 2023 at 10:47, Michael Paquier <michael@paquier.xyz> wrote:

On Thu, Nov 09, 2023 at 02:39:26PM +0300, Nazir Bilal Yavuz wrote:

There are some differences between pg_stat_wal and pg_stat_io while
collecting WAL stats. For example in the XLogWrite() function in the
xlog.c file, pg_stat_wal counts wal_writes as write system calls. This
is not something we want for pg_stat_io since pg_stat_io counts the
number of blocks rather than the system calls, so instead incremented
pg_stat_io by npages.

Could that cause a problem since pg_stat_wal's behaviour will be
changed? Of course, as an alternative we could change pg_stat_io's
behaviour but in the end either pg_stat_wal's or pg_stat_io's
behaviour will be changed.

Yep, that could be confusing for existing applications that track the
information of pg_stat_wal. The number of writes is not something
that can be correctly shared between both. The timings for the writes
and the syncs could be shared at least, right?

Yes, the timings for the writes and the syncs should work. Another
question I have in mind is the pg_stat_reset_shared() function. When
we call it with 'io' it will reset pg_stat_wal's timings and when we
call it with 'wal' it won't reset them, right?

This slightly relates to pgstat_count_io_op_n() in your latest patch,
where it feels a bit weird to see an update of
PendingWalStats.wal_sync sit in the middle of a routine dedicated to
pg_stat_io.. I am not completely sure what's the right balance here,
but I would try to implement things so as pg_stat_io paths does not
need to know about PendingWalStats.

Write has block vs system calls differentiation but it is the same for
sync. Because of that I put PendingWalStats.wal_sync to pg_stat_io but
I agree that it looks a bit weird.

--
Regards,
Nazir Bilal Yavuz
Microsoft

On Mon, Nov 20, 2023 at 05:43:17PM +0300, Nazir Bilal Yavuz wrote:

Yes, the timings for the writes and the syncs should work. Another
question I have in mind is the pg_stat_reset_shared() function. When
we call it with 'io' it will reset pg_stat_wal's timings and when we
call it with 'wal' it won't reset them, right?

pg_stat_reset_shared() with a target is IMO a very edge case, so I'm
OK with the approach of resetting timings in pg_stat_wal even if 'io'
was implied because pg_stat_wal would feed partially from pg_stat_io.
I'd take that as a side-cost in favor of compatibility while making
the stats gathering cheaper overall. I'm OK as well if people
counter-argue on this point, though that would mean to keep entirely
separate views with duplicated fields that serve the same purpose,
impacting all deployments because it would make the stats gathering
heavier for all.
--
Michael