On 2021-03-08 13:44, Fujii Masao wrote:
On 2021/03/05 19:54, Masahiro Ikeda wrote:
On 2021-03-05 12:47, Fujii Masao wrote:
On 2021/03/05 8:38, Masahiro Ikeda wrote:
On 2021-03-05 01:02, Fujii Masao wrote:
On 2021/03/04 16:14, Masahiro Ikeda wrote:
On 2021-03-03 20:27, Masahiro Ikeda wrote:
On 2021-03-03 16:30, Fujii Masao wrote:
On 2021/03/03 14:33, Masahiro Ikeda wrote:
On 2021-02-24 16:14, Fujii Masao wrote:
On 2021/02/15 11:59, Masahiro Ikeda wrote:
On 2021-02-10 00:51, David G. Johnston wrote:
On Thu, Feb 4, 2021 at 4:45 PM Masahiro Ikeda
<ikeda...@oss.nttdata.com> wrote:
I pgindented the patches.
... <function>XLogWrite</function>, which is invoked during
an
<function>XLogFlush</function> request (see ...). This is
also
incremented by the WAL receiver during replication.
("which normally called" should be "which is normally
called" or
"which normally is called" if you want to keep true to the
original)
You missed the adding the space before an opening
parenthesis here and
elsewhere (probably copy-paste)
is ether -> is either
"This parameter is off by default as it will repeatedly
query the
operating system..."
", because" -> "as"
Thanks, I fixed them.
wal_write_time and the sync items also need the note: "This
is also
incremented by the WAL receiver during replication."
I skipped changing it since I separated the stats for the WAL
receiver
in pg_stat_wal_receiver.
"The number of times it happened..." -> " (the tally of this
event is
reported in wal_buffers_full in....) This is undesirable
because ..."
Thanks, I fixed it.
I notice that the patch for WAL receiver doesn't require
explicitly
computing the sync statistics but does require computing the
write
statistics. This is because of the presence of
issue_xlog_fsync but
absence of an equivalent pg_xlog_pwrite. Additionally, I
observe that
the XLogWrite code path calls pgstat_report_wait_*() while
the WAL
receiver path does not. It seems technically
straight-forward to
refactor here to avoid the almost-duplicated logic in the
two places,
though I suspect there may be a trade-off for not adding
another
function call to the stack given the importance of WAL
processing
(though that seems marginalized compared to the cost of
actually
writing the WAL). Or, as Fujii noted, go the other way and
don't have
any shared code between the two but instead implement the
WAL receiver
one to use pg_stat_wal_receiver instead. In either case,
this
half-and-half implementation seems undesirable.
OK, as Fujii-san mentioned, I separated the WAL receiver
stats.
(v10-0002-Makes-the-wal-receiver-report-WAL-statistics.patch)
Thanks for updating the patches!
I added the infrastructure code to communicate the WAL
receiver stats messages between the WAL receiver and the
stats collector, and
the stats for WAL receiver is counted in
pg_stat_wal_receiver.
What do you think?
On second thought, this idea seems not good. Because those
stats are
collected between multiple walreceivers, but other values in
pg_stat_wal_receiver is only related to the walreceiver
process running
at that moment. IOW, it seems strange that some values show
dynamic
stats and the others show collected stats, even though they
are in
the same view pg_stat_wal_receiver. Thought?
OK, I fixed it.
The stats collected in the WAL receiver is exposed in
pg_stat_wal view in v11 patch.
Thanks for updating the patches! I'm now reading 001 patch.
+ /* Check whether the WAL file was synced to disk right now
*/
+ if (enableFsync &&
+ (sync_method == SYNC_METHOD_FSYNC ||
+ sync_method == SYNC_METHOD_FSYNC_WRITETHROUGH ||
+ sync_method == SYNC_METHOD_FDATASYNC))
+ {
Isn't it better to make issue_xlog_fsync() return immediately
if enableFsync is off, sync_method is open_sync or
open_data_sync,
to simplify the code more?
Thanks for the comments.
I added the above code in v12 patch.
+ /*
+ * Send WAL statistics only if WalWriterDelay has
elapsed to minimize
+ * the overhead in WAL-writing.
+ */
+ if (rc & WL_TIMEOUT)
+ pgstat_send_wal();
On second thought, this change means that it always takes
wal_writer_delay
before walwriter's WAL stats is sent after XLogBackgroundFlush()
is called.
For example, if wal_writer_delay is set to several seconds, some
values in
pg_stat_wal would be not up-to-date meaninglessly for those
seconds.
So I'm thinking to withdraw my previous comment and it's ok to
send
the stats every after XLogBackgroundFlush() is called. Thought?
Thanks, I didn't notice that.
Although PGSTAT_STAT_INTERVAL is 500msec, wal_writer_delay's
default value is 200msec and it may be set shorter time.
Yeah, if wal_writer_delay is set to very small value, there is a
risk
that the WAL stats are sent too frequently. I agree that's a
problem.
Why don't to make another way to check the timestamp?
+ /*
+ * Don't send a message unless it's been at least
PGSTAT_STAT_INTERVAL
+ * msec since we last sent one
+ */
+ now = GetCurrentTimestamp();
+ if (TimestampDifferenceExceeds(last_report, now,
PGSTAT_STAT_INTERVAL))
+ {
+ pgstat_send_wal();
+ last_report = now;
+ }
+
Although I worried that it's better to add the check code in
pgstat_send_wal(),
Agreed.
I didn't do so because to avoid to double check
PGSTAT_STAT_INTERVAL.
pgstat_send_wal() is invoked pg_report_stat() and it already
checks the
PGSTAT_STAT_INTERVAL.
I think that we can do that. What about the attached patch?
Thanks, I thought it's better.
I forgot to remove an unused variable.
The attached v13 patch is fixed.
Thanks for updating the patch!
+ w.wal_write,
+ w.wal_write_time,
+ w.wal_sync,
+ w.wal_sync_time,
It's more natural to put wal_write_time and wal_sync_time next to
each other? That is, what about the following order of columns?
wal_write
wal_sync
wal_write_time
wal_sync_time
Yes, I fixed it.
- case SYNC_METHOD_OPEN:
- case SYNC_METHOD_OPEN_DSYNC:
- /* write synced it already */
- break;
IMO it's better to add Assert(false) here to ensure that we never
reach
here, as follows. Thought?
+ case SYNC_METHOD_OPEN:
+ case SYNC_METHOD_OPEN_DSYNC:
+ /* not reachable */
+ Assert(false);
I agree.
Even when a backend exits, it sends the stats via
pgstat_beshutdown_hook().
On the other hand, walwriter doesn't do that. Walwriter also should
send
the stats even at its exit? Otherwise some stats can fail to be
collected.
But ISTM that this issue existed from before, for example
checkpointer
doesn't call pgstat_send_bgwriter() at its exit, so it's overkill
to fix
this issue in this patch?
Thanks, I thought it's better to do so.
I added the shutdown hook for the walwriter and the checkpointer in
v14-0003 patch.
Thanks!
Seems you forgot to include the changes of expected/rules.out in 0001
patch,
and which caused the regression test to fail. Attached is the updated
version
of the patch. I included expected/rules.out in it.
Sorry.
+ PgStat_Counter m_wal_write_time; /* time spend writing wal
records in
+ * micro seconds */
+ PgStat_Counter m_wal_sync_time; /* time spend syncing wal
records in micro
+ * seconds */
IMO "spend" should be "spent". Also "micro seconds" should be
"microseconds"
in sake of consistent with other comments in pgstat.h. I fixed them.
Thanks.
Regarding pgstat_report_wal() and pgstat_send_wal(), I found one bug.
Even
when pgstat_send_wal() returned without sending any message,
pgstat_report_wal() saved current pgWalUsage and that counter was
used for
the subsequent calculation of WAL usage. This caused some counters
not to
be sent to the collector. This is a bug that I added. I fixed this
bug.
Thanks.
+ walStats.wal_write += msg->m_wal_write;
+ walStats.wal_write_time += msg->m_wal_write_time;
+ walStats.wal_sync += msg->m_wal_sync;
+ walStats.wal_sync_time += msg->m_wal_sync_time;
I changed the order of the above in pgstat.c so that wal_write_time
and
wal_sync_time are placed in next to each other.
I forgot to fix them, thanks.
The followings are the comments for the docs part. I've not updated
this
in the patch yet because I'm not sure how to change them for now.
+ Number of times WAL buffers were written out to disk via
+ <function>XLogWrite</function>, which is invoked during an
+ <function>XLogFlush</function> request (see <xref
linkend="wal-configuration"/>)
+ </para></entry>
XLogWrite() can be invoked during the functions other than
XLogFlush().
For example, XLogBackgroundFlush(). So the above description might be
confusing?
+ Number of times WAL files were synced to disk via
+ <function>issue_xlog_fsync</function>, which is invoked
during an
+ <function>XLogFlush</function> request (see <xref
linkend="wal-configuration"/>)
Same as above.
Yes, why don't you remove "XLogFlush" in the above comments
because XLogWrite() description is covered in wal.sgml?
But, now it's mentioned only for backend,
I added the comments for the wal writer in the attached patch.
+ while <xref linkend="guc-wal-sync-method"/> was set to one of
the
+ "sync at commit" options (i.e., <literal>fdatasync</literal>,
+ <literal>fsync</literal>, or
<literal>fsync_writethrough</literal>).
Even open_sync and open_datasync do the sync at commit. No? I'm not
sure
if "sync at commit" is right term to indicate fdatasync, fsync and
fsync_writethrough.
Yes, why don't you change to the following comments?
```
while <xref linkend="guc-wal-sync-method"/> was set to one of
the
options which specific fsync method is called (i.e.,
<literal>fdatasync</literal>,
<literal>fsync</literal>, or
<literal>fsync_writethrough</literal>)
```
+ <literal>open_sync</literal>. Units are in milliseconds with
microsecond resolution.
"with microsecond resolution" part is really necessary?
I removed it because blk_read_time in pg_stat_database is the same
above,
but it doesn't mention it.
+ transaction records are flushed to permanent storage.
+ <function>XLogFlush</function> calls
<function>XLogWrite</function> to write
+ and <function>issue_xlog_fsync</function> to flush them, which
are
counted as
+ <literal>wal_write</literal> and <literal>wal_sync</literal> in
+ <xref linkend="pg-stat-wal-view"/>. On systems with high log
output,
This description might cause users to misread that XLogFlush() calls
issue_xlog_fsync(). Since issue_xlog_fsync() is called by
XLogWrite(),
ISTM that this description needs to be updated.
I understood. I fixed to mention that XLogWrite()
calls issue_xlog_fsync().
Each line in the above seems to end with a space character.
This space character should be removed.
Sorry for that. I removed it.
Thanks for updating the patch! I think it's getting good shape!
- pid | wait_event_type | wait_event
+ pid | wait_event_type | wait_event
This change is not necessary?
No, sorry.
I removed it by mistake when I remove trailing space characters.
- every <xref linkend="guc-wal-writer-delay"/> milliseconds.
+ every <xref linkend="guc-wal-writer-delay"/> milliseconds, which
calls
+ <function>XLogWrite</function> to write and
<function>XLogWrite</function>
+ <function>issue_xlog_fsync</function> to flush them. They are
counted as
+ <literal>wal_write</literal> and <literal>wal_sync</literal> in
+ <xref linkend="pg-stat-wal-view"/>.
Isn't it better to avoid using the terms like XLogWrite or
issue_xlog_fsync
before explaining what they are? They are explained later. At least for
me
I'm ok without this change.
OK. I removed them and add a new paragraph.
- to write (move to kernel cache) a few filled <acronym>WAL</acronym>
- buffers. This is undesirable because
<function>XLogInsertRecord</function>
+ to call <function>XLogWrite</function> to write (move to kernel
cache) a
+ few filled <acronym>WAL</acronym> buffers (the tally of this event
is reported in
+ <literal>wal_buffers_full</literal> in <xref
linkend="pg-stat-wal-view"/>).
+ This is undesirable because <function>XLogInsertRecord</function>
This paragraph explains the relationshp between WAL writes and WAL
buffers. I don't think it's good to add different context to this
paragraph. Instead, what about adding new paragraph like the follwing?
----------------------------------
When track_wal_io_timing is enabled, the total amounts of time
XLogWrite writes and issue_xlog_fsync syncs WAL data to disk are
counted as wal_write_time and wal_sync_time in pg_stat_wal view,
respectively. XLogWrite is normally called by XLogInsertRecord (when
there is no space for the new record in WAL buffers), XLogFlush and
the WAL writer, to write WAL buffers to disk and call
issue_xlog_fsync. If wal_sync_method is either open_datasync or
open_sync, a write operation in XLogWrite guarantees to sync written
WAL data to disk and issue_xlog_fsync does nothing. If wal_sync_method
is either fdatasync, fsync, or fsync_writethrough, the write operation
moves WAL buffer to kernel cache and issue_xlog_fsync syncs WAL files
to disk. Regardless of the setting of track_wal_io_timing, the numbers
of times XLogWrite writes and issue_xlog_fsync syncs WAL data to disk
are also counted as wal_write and wal_sync in pg_stat_wal,
respectively.
----------------------------------
Thanks, I agree it's better.
+ <function>issue_xlog_fsync</function> (see <xref
linkend="wal-configuration"/>)
"request" should be place just before "(see"?
Yes, thanks.
+ Number of times WAL files were synced to disk via
+ <function>issue_xlog_fsync</function> (see <xref
linkend="wal-configuration"/>)
+ while <xref linkend="guc-wal-sync-method"/> was set to one of
the
+ options which specific fsync method is called (i.e.,
<literal>fdatasync</literal>,
+ <literal>fsync</literal>, or
<literal>fsync_writethrough</literal>).
Isn't it better to mention the case of fsync=off? What about the
following?
----------------------------------
Number of times WAL files were synced to disk via issue_xlog_fsync
(see ...). This is zero when fsync is off or wal_sync_method is either
open_datasync or open_sync.
----------------------------------
Yes.
+ Total amount of time spent writing WAL buffers were written
out to disk via
"were written out" is not necessary?
Yes, removed it.
+ Total amount of time spent syncing WAL files to disk via
+ <function>issue_xlog_fsync</function> request (see <xref
linkend="wal-configuration"/>)
+ while <xref linkend="guc-wal-sync-method"/> was set to one of
the
+ options which specific fsync method is called (i.e.,
<literal>fdatasync</literal>,
+ <literal>fsync</literal>, or
<literal>fsync_writethrough</literal>).
+ Units are in milliseconds.
+ This is zero when <xref linkend="guc-track-wal-io-timing"/> is
disabled.
Isn't it better to explain the case where this counter is zero a bit
more clearly as follows?
---------------------
This is zero when track_wal_io_timing is disabled, fsync is off, or
wal_sync_method is either open_datasync or open_sync.
---------------------
Yes, thanks.
Regards,
--
Masahiro Ikeda
NTT DATA CORPORATION
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 967de73596..56eb55bab7 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7450,7 +7450,7 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
<listitem>
<para>
Enables timing of database I/O calls. This parameter is off by
- default, because it will repeatedly query the operating system for
+ default, as it will repeatedly query the operating system for
the current time, which may cause significant overhead on some
platforms. You can use the <xref linkend="pgtesttiming"/> tool to
measure the overhead of timing on your system.
@@ -7464,6 +7464,27 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
</listitem>
</varlistentry>
+ <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing">
+ <term><varname>track_wal_io_timing</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>track_wal_io_timing</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Enables timing of WAL I/O calls. This parameter is off by default,
+ as it will repeatedly query the operating system for
+ the current time, which may cause significant overhead on some
+ platforms. You can use the <xref linkend="pgtesttiming"/> tool to
+ measure the overhead of timing on your system.
+ I/O timing information is
+ displayed in <link linkend="monitoring-pg-stat-wal-view">
+ <structname>pg_stat_wal</structname></link>. Only superusers can
+ change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-track-functions" xreflabel="track_functions">
<term><varname>track_functions</varname> (<type>enum</type>)
<indexterm>
diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index 3513e127b7..a8506d0486 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -3487,6 +3487,57 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i
</para></entry>
</row>
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>wal_write</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times WAL buffers were written out to disk via
+ <function>XLogWrite</function> request (see <xref linkend="wal-configuration"/>)
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>wal_sync</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times WAL files were synced to disk via
+ <function>issue_xlog_fsync</function> request (see <xref linkend="wal-configuration"/>).
+ This is zero when <xref linkend="guc-fsync"/> is off or
+ <xref linkend="guc-wal-sync-method"/> is either <literal>open_datasync</literal>
+ or <literal>open_sync</literal>.
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>wal_write_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total amount of time spent writing WAL buffers to disk via
+ <function>XLogWrite</function> request (see <xref linkend="wal-configuration"/>),
+ excluding sync time unless
+ <xref linkend="guc-wal-sync-method"/> is either <literal>open_datasync</literal> or
+ <literal>open_sync</literal>. Units are in milliseconds.
+ This is zero when <xref linkend="guc-track-wal-io-timing"/> is disabled.
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>wal_sync_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total amount of time spent syncing WAL files to disk via
+ <function>issue_xlog_fsync</function> request (see <xref linkend="wal-configuration"/>).
+ Units are in milliseconds.
+ This is zero when <xref linkend="guc-track-wal-io-timing"/> is disabled,
+ <xref linkend="guc-fsync"/> is off, or <xref linkend="guc-wal-sync-method"/> is
+ either <literal>open_datasync</literal> or <literal>open_sync</literal>.
+ </para></entry>
+ </row>
+
<row>
<entry role="catalog_table_entry"><para role="column_definition">
<structfield>stats_reset</structfield> <type>timestamp with time zone</type>
diff --git a/doc/src/sgml/wal.sgml b/doc/src/sgml/wal.sgml
index f75527f764..a3c7e0d26c 100644
--- a/doc/src/sgml/wal.sgml
+++ b/doc/src/sgml/wal.sgml
@@ -767,6 +767,32 @@
<acronym>WAL</acronym> call being logged to the server log. This
option might be replaced by a more general mechanism in the future.
</para>
+
+ <para>
+ When <xref linkend="guc-track-wal-io-timing"/> is enabled, the total
+ amounts of time <function>XLogWrite</function> writes and
+ <function>issue_xlog_fsync</function> syncs WAL data to disk are
+ counted as <literal>wal_write_time</literal> and
+ <literal>wal_sync_time</literal> in
+ <xref linkend="pg-stat-wal-view"/>, respectively.
+ <function>XLogWrite</function> is normally called by
+ <function>XLogInsertRecord</function> (when there is no space for
+ the new record in WAL buffers), <function>XLogFlush</function> and
+ the WAL writer, to write WAL buffers to disk and call
+ <function>issue_xlog_fsync</function>. If <xref linkend="guc-wal-sync-method"/>
+ is either <literal>open_datasync</literal> or <literal>open_sync</literal>,
+ a write operation in <function>XLogWrite</function> guarantees to sync written
+ WAL data to disk and <function>issue_xlog_fsync</function> does nothing.
+ If <xref linkend="guc-wal-sync-method"/> is either <literal>fdatasync</literal>,
+ <literal>fsync</literal>, or <literal>fsync_writethrough</literal>,
+ the write operation moves WAL buffer to kernel cache and
+ <function>issue_xlog_fsync</function> syncs WAL files to disk. Regardless
+ of the setting of <xref linkend="guc-track-wal-io-timing"/>, the numbers
+ of times <function>XLogWrite</function> writes and
+ <function>issue_xlog_fsync</function> syncs WAL data to disk are also
+ counted as <literal>wal_write</literal> and <literal>wal_sync</literal>
+ in <xref linkend="pg-stat-wal-view"/>, respectively.
+ </para>
</sect1>
<sect1 id="wal-internals">
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index fe56324439..24c3dd32f8 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -110,6 +110,7 @@ int CommitDelay = 0; /* precommit delay in microseconds */
int CommitSiblings = 5; /* # concurrent xacts needed to sleep */
int wal_retrieve_retry_interval = 5000;
int max_slot_wal_keep_size_mb = -1;
+bool track_wal_io_timing = false;
#ifdef WAL_DEBUG
bool XLOG_DEBUG = false;
@@ -2533,6 +2534,7 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible)
Size nbytes;
Size nleft;
int written;
+ instr_time start;
/* OK to write the page(s) */
from = XLogCtl->pages + startidx * (Size) XLOG_BLCKSZ;
@@ -2541,9 +2543,30 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible)
do
{
errno = 0;
+
+ /* Measure I/O timing to write WAL data */
+ if (track_wal_io_timing)
+ INSTR_TIME_SET_CURRENT(start);
+
pgstat_report_wait_start(WAIT_EVENT_WAL_WRITE);
written = pg_pwrite(openLogFile, from, nleft, startoffset);
pgstat_report_wait_end();
+
+ /*
+ * Increment the I/O timing and the number of times WAL data
+ * were written out to disk.
+ */
+ if (track_wal_io_timing)
+ {
+ instr_time duration;
+
+ INSTR_TIME_SET_CURRENT(duration);
+ INSTR_TIME_SUBTRACT(duration, start);
+ WalStats.m_wal_write_time += INSTR_TIME_GET_MICROSEC(duration);
+ }
+
+ WalStats.m_wal_write++;
+
if (written <= 0)
{
char xlogfname[MAXFNAMELEN];
@@ -10526,6 +10549,20 @@ void
issue_xlog_fsync(int fd, XLogSegNo segno)
{
char *msg = NULL;
+ instr_time start;
+
+ /*
+ * Quick exit if fsync is disabled or write() has already synced the WAL
+ * file.
+ */
+ if (!enableFsync ||
+ sync_method == SYNC_METHOD_OPEN ||
+ sync_method == SYNC_METHOD_OPEN_DSYNC)
+ return;
+
+ /* Measure I/O timing to sync the WAL file */
+ if (track_wal_io_timing)
+ INSTR_TIME_SET_CURRENT(start);
pgstat_report_wait_start(WAIT_EVENT_WAL_SYNC);
switch (sync_method)
@@ -10548,7 +10585,8 @@ issue_xlog_fsync(int fd, XLogSegNo segno)
#endif
case SYNC_METHOD_OPEN:
case SYNC_METHOD_OPEN_DSYNC:
- /* write synced it already */
+ /* not reachable */
+ Assert(false);
break;
default:
elog(PANIC, "unrecognized wal_sync_method: %d", sync_method);
@@ -10570,6 +10608,20 @@ issue_xlog_fsync(int fd, XLogSegNo segno)
}
pgstat_report_wait_end();
+
+ /*
+ * Increment the I/O timing and the number of times WAL files were synced.
+ */
+ if (track_wal_io_timing)
+ {
+ instr_time duration;
+
+ INSTR_TIME_SET_CURRENT(duration);
+ INSTR_TIME_SUBTRACT(duration, start);
+ WalStats.m_wal_sync_time += INSTR_TIME_GET_MICROSEC(duration);
+ }
+
+ WalStats.m_wal_sync++;
}
/*
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index fc94a73a54..51ba1b5826 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -1005,6 +1005,10 @@ CREATE VIEW pg_stat_wal AS
w.wal_fpi,
w.wal_bytes,
w.wal_buffers_full,
+ w.wal_write,
+ w.wal_sync,
+ w.wal_write_time,
+ w.wal_sync_time,
w.stats_reset
FROM pg_stat_get_wal() w;
diff --git a/src/backend/postmaster/checkpointer.c b/src/backend/postmaster/checkpointer.c
index 0bbeece19d..3894f4a270 100644
--- a/src/backend/postmaster/checkpointer.c
+++ b/src/backend/postmaster/checkpointer.c
@@ -505,7 +505,7 @@ CheckpointerMain(void)
pgstat_send_bgwriter();
/* Send WAL statistics to the stats collector. */
- pgstat_send_wal();
+ pgstat_report_wal();
/*
* If any checkpoint flags have been set, redo the loop to handle the
diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c
index f75b52719d..6a51c39396 100644
--- a/src/backend/postmaster/pgstat.c
+++ b/src/backend/postmaster/pgstat.c
@@ -146,8 +146,8 @@ PgStat_MsgWal WalStats;
/*
* WAL usage counters saved from pgWALUsage at the previous call to
- * pgstat_send_wal(). This is used to calculate how much WAL usage
- * happens between pgstat_send_wal() calls, by substracting
+ * pgstat_report_wal(). This is used to calculate how much WAL usage
+ * happens between pgstat_report_wal() calls, by substracting
* the previous counters from the current ones.
*/
static WalUsage prevWalUsage;
@@ -975,7 +975,7 @@ pgstat_report_stat(bool disconnect)
pgstat_send_funcstats();
/* Send WAL statistics */
- pgstat_send_wal();
+ pgstat_report_wal();
/* Finally send SLRU statistics */
pgstat_send_slru();
@@ -3118,7 +3118,7 @@ pgstat_initialize(void)
}
/*
- * Initialize prevWalUsage with pgWalUsage so that pgstat_send_wal() can
+ * Initialize prevWalUsage with pgWalUsage so that pgstat_report_wal() can
* calculate how much pgWalUsage counters are increased by substracting
* prevWalUsage from pgWalUsage.
*/
@@ -4667,17 +4667,17 @@ pgstat_send_bgwriter(void)
}
/* ----------
- * pgstat_send_wal() -
+ * pgstat_report_wal() -
*
- * Send WAL statistics to the collector
+ * Calculate how much WAL usage counters are increased and send
+ * WAL statistics to the collector.
+ *
+ * Must be called by processes that generate WAL.
* ----------
*/
void
-pgstat_send_wal(void)
+pgstat_report_wal(void)
{
- /* We assume this initializes to zeroes */
- static const PgStat_MsgWal all_zeroes;
-
WalUsage walusage;
/*
@@ -4692,13 +4692,56 @@ pgstat_send_wal(void)
WalStats.m_wal_fpi = walusage.wal_fpi;
WalStats.m_wal_bytes = walusage.wal_bytes;
+ /*
+ * Send WAL stats message to the collector.
+ */
+ if (!pgstat_send_wal(true))
+ return;
+
+ /*
+ * Save the current counters for the subsequent calculation of WAL usage.
+ */
+ prevWalUsage = pgWalUsage;
+}
+
+/* ----------
+ * pgstat_send_wal() -
+ *
+ * Send WAL statistics to the collector.
+ *
+ * If 'force' is not set, WAL stats message is only sent if enough time has
+ * passed since last one was sent to reach PGSTAT_STAT_INTERVAL.
+ *
+ * Return true if the message is sent, and false otherwise.
+ * ----------
+ */
+bool
+pgstat_send_wal(bool force)
+{
+ /* We assume this initializes to zeroes */
+ static const PgStat_MsgWal all_zeroes;
+ static TimestampTz sendTime = 0;
+
/*
* This function can be called even if nothing at all has happened. In
* this case, avoid sending a completely empty message to the stats
* collector.
*/
if (memcmp(&WalStats, &all_zeroes, sizeof(PgStat_MsgWal)) == 0)
- return;
+ return false;
+
+ if (!force)
+ {
+ TimestampTz now = GetCurrentTimestamp();
+
+ /*
+ * Don't send a message unless it's been at least PGSTAT_STAT_INTERVAL
+ * msec since we last sent one.
+ */
+ if (!TimestampDifferenceExceeds(sendTime, now, PGSTAT_STAT_INTERVAL))
+ return false;
+ sendTime = now;
+ }
/*
* Prepare and send the message
@@ -4706,15 +4749,12 @@ pgstat_send_wal(void)
pgstat_setheader(&WalStats.m_hdr, PGSTAT_MTYPE_WAL);
pgstat_send(&WalStats, sizeof(WalStats));
- /*
- * Save the current counters for the subsequent calculation of WAL usage.
- */
- prevWalUsage = pgWalUsage;
-
/*
* Clear out the statistics buffer, so it can be re-used.
*/
MemSet(&WalStats, 0, sizeof(WalStats));
+
+ return true;
}
/* ----------
@@ -6892,6 +6932,10 @@ pgstat_recv_wal(PgStat_MsgWal *msg, int len)
walStats.wal_fpi += msg->m_wal_fpi;
walStats.wal_bytes += msg->m_wal_bytes;
walStats.wal_buffers_full += msg->m_wal_buffers_full;
+ walStats.wal_write += msg->m_wal_write;
+ walStats.wal_sync += msg->m_wal_sync;
+ walStats.wal_write_time += msg->m_wal_write_time;
+ walStats.wal_sync_time += msg->m_wal_sync_time;
}
/* ----------
diff --git a/src/backend/postmaster/walwriter.c b/src/backend/postmaster/walwriter.c
index 4f1a8e356b..132df29aba 100644
--- a/src/backend/postmaster/walwriter.c
+++ b/src/backend/postmaster/walwriter.c
@@ -253,6 +253,9 @@ WalWriterMain(void)
else if (left_till_hibernate > 0)
left_till_hibernate--;
+ /* Send WAL statistics to the stats collector */
+ pgstat_send_wal(false);
+
/*
* Sleep until we are signaled or WalWriterDelay has elapsed. If we
* haven't done anything useful for quite some time, lengthen the
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index 62bff52638..04e1a7e8b9 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -1799,7 +1799,7 @@ pg_stat_get_buf_alloc(PG_FUNCTION_ARGS)
Datum
pg_stat_get_wal(PG_FUNCTION_ARGS)
{
-#define PG_STAT_GET_WAL_COLS 5
+#define PG_STAT_GET_WAL_COLS 9
TupleDesc tupdesc;
Datum values[PG_STAT_GET_WAL_COLS];
bool nulls[PG_STAT_GET_WAL_COLS];
@@ -1820,7 +1820,15 @@ pg_stat_get_wal(PG_FUNCTION_ARGS)
NUMERICOID, -1, 0);
TupleDescInitEntry(tupdesc, (AttrNumber) 4, "wal_buffers_full",
INT8OID, -1, 0);
- TupleDescInitEntry(tupdesc, (AttrNumber) 5, "stats_reset",
+ TupleDescInitEntry(tupdesc, (AttrNumber) 5, "wal_write",
+ INT8OID, -1, 0);
+ TupleDescInitEntry(tupdesc, (AttrNumber) 6, "wal_sync",
+ INT8OID, -1, 0);
+ TupleDescInitEntry(tupdesc, (AttrNumber) 7, "wal_write_time",
+ FLOAT8OID, -1, 0);
+ TupleDescInitEntry(tupdesc, (AttrNumber) 8, "wal_sync_time",
+ FLOAT8OID, -1, 0);
+ TupleDescInitEntry(tupdesc, (AttrNumber) 9, "stats_reset",
TIMESTAMPTZOID, -1, 0);
BlessTupleDesc(tupdesc);
@@ -1840,7 +1848,14 @@ pg_stat_get_wal(PG_FUNCTION_ARGS)
Int32GetDatum(-1));
values[3] = Int64GetDatum(wal_stats->wal_buffers_full);
- values[4] = TimestampTzGetDatum(wal_stats->stat_reset_timestamp);
+ values[4] = Int64GetDatum(wal_stats->wal_write);
+ values[5] = Int64GetDatum(wal_stats->wal_sync);
+
+ /* Convert counters from microsec to millisec for display */
+ values[6] = Float8GetDatum(((double) wal_stats->wal_write_time) / 1000.0);
+ values[7] = Float8GetDatum(((double) wal_stats->wal_sync_time) / 1000.0);
+
+ values[8] = TimestampTzGetDatum(wal_stats->stat_reset_timestamp);
/* Returns the record as Datum */
PG_RETURN_DATUM(HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls)));
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 442850e8ad..da05b5acb1 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -1485,6 +1485,15 @@ static struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
+ {
+ {"track_wal_io_timing", PGC_SUSET, STATS_COLLECTOR,
+ gettext_noop("Collects timing statistics for WAL I/O activity."),
+ NULL
+ },
+ &track_wal_io_timing,
+ false,
+ NULL, NULL, NULL
+ },
{
{"update_process_title", PGC_SUSET, PROCESS_TITLE,
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index ee06528bb0..c6483fa1ff 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -586,6 +586,7 @@
#track_activities = on
#track_counts = on
#track_io_timing = off
+#track_wal_io_timing = off
#track_functions = none # none, pl, all
#track_activity_query_size = 1024 # (change requires restart)
#stats_temp_directory = 'pg_stat_tmp'
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 75ec1073bd..1e53d9d4ca 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -131,6 +131,7 @@ extern int recovery_min_apply_delay;
extern char *PrimaryConnInfo;
extern char *PrimarySlotName;
extern bool wal_receiver_create_temp_slot;
+extern bool track_wal_io_timing;
/* indirectly set via GUC system */
extern TransactionId recoveryTargetXid;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index d2cfe9b6a3..41ceaf1ee7 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5546,9 +5546,9 @@
{ oid => '1136', descr => 'statistics: information about WAL activity',
proname => 'pg_stat_get_wal', proisstrict => 'f', provolatile => 's',
proparallel => 'r', prorettype => 'record', proargtypes => '',
- proallargtypes => '{int8,int8,numeric,int8,timestamptz}',
- proargmodes => '{o,o,o,o,o}',
- proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,stats_reset}',
+ proallargtypes => '{int8,int8,numeric,int8,int8,int8,float8,float8,timestamptz}',
+ proargmodes => '{o,o,o,o,o,o,o,o,o}',
+ proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_write,wal_sync,wal_write_time,wal_sync_time,stats_reset}',
prosrc => 'pg_stat_get_wal' },
{ oid => '2306', descr => 'statistics: information about SLRU caches',
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 724068cf87..5c6c8efc5a 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -474,6 +474,12 @@ typedef struct PgStat_MsgWal
PgStat_Counter m_wal_fpi;
uint64 m_wal_bytes;
PgStat_Counter m_wal_buffers_full;
+ PgStat_Counter m_wal_write;
+ PgStat_Counter m_wal_sync;
+ PgStat_Counter m_wal_write_time; /* time spent writing wal records in
+ * microseconds */
+ PgStat_Counter m_wal_sync_time; /* time spent syncing wal records in
+ * microseconds */
} PgStat_MsgWal;
/* ----------
@@ -839,6 +845,10 @@ typedef struct PgStat_WalStats
PgStat_Counter wal_fpi;
uint64 wal_bytes;
PgStat_Counter wal_buffers_full;
+ PgStat_Counter wal_write;
+ PgStat_Counter wal_sync;
+ PgStat_Counter wal_write_time;
+ PgStat_Counter wal_sync_time;
TimestampTz stat_reset_timestamp;
} PgStat_WalStats;
@@ -1590,7 +1600,8 @@ extern void pgstat_twophase_postabort(TransactionId xid, uint16 info,
extern void pgstat_send_archiver(const char *xlog, bool failed);
extern void pgstat_send_bgwriter(void);
-extern void pgstat_send_wal(void);
+extern void pgstat_report_wal(void);
+extern bool pgstat_send_wal(bool force);
/* ----------
* Support functions for the SQL-callable functions to
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index b1c9b7bdfe..e03ef0555a 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -2160,8 +2160,12 @@ pg_stat_wal| SELECT w.wal_records,
w.wal_fpi,
w.wal_bytes,
w.wal_buffers_full,
+ w.wal_write,
+ w.wal_sync,
+ w.wal_write_time,
+ w.wal_sync_time,
w.stats_reset
- FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, stats_reset);
+ FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, wal_write, wal_sync, wal_write_time, wal_sync_time, stats_reset);
pg_stat_wal_receiver| SELECT s.pid,
s.status,
s.receive_start_lsn,
