--- v5-0001-Add-statistics-related-to-write-sync-wal-records.patch 2021-01-23 09:26:01.919248712 +0900 +++ v6-0001-Add-statistics-related-to-write-sync-wal-records.patch 2021-01-25 16:27:50.749429666 +0900 @@ -1,6 +1,6 @@ -From ee1b7d17391b9d9619f709afeacdd118973471d6 Mon Sep 17 00:00:00 2001 +From e9aad92097c5cff5565b67ce1a8ec6d7b4c8a4d9 Mon Sep 17 00:00:00 2001 From: Masahiro Ikeda -Date: Fri, 22 Jan 2021 21:38:31 +0900 +Date: Mon, 25 Jan 2021 16:26:04 +0900 Subject: [PATCH] Add statistics related to write/sync wal records. This patch adds following statistics to pg_stat_wal view @@ -24,20 +24,22 @@ (This requires a catversion bump, as well as an update to PGSTAT_FILE_FORMAT_ID) --- - doc/src/sgml/config.sgml | 21 +++++++ - doc/src/sgml/monitoring.sgml | 48 ++++++++++++++- - src/backend/access/transam/xlog.c | 59 ++++++++++++++++++- + doc/src/sgml/config.sgml | 21 ++++++++ + doc/src/sgml/monitoring.sgml | 48 ++++++++++++++++- + src/backend/access/transam/xlog.c | 51 ++++++++++++++++++- src/backend/catalog/system_views.sql | 4 ++ - src/backend/postmaster/pgstat.c | 4 ++ - src/backend/postmaster/walwriter.c | 3 + - src/backend/utils/adt/pgstatfuncs.c | 24 +++++++- - src/backend/utils/misc/guc.c | 9 +++ + src/backend/postmaster/checkpointer.c | 2 +- + src/backend/postmaster/pgstat.c | 26 ++++++++-- + src/backend/postmaster/walwriter.c | 3 ++ + src/backend/replication/walreceiver.c | 30 +++++++++++ + src/backend/utils/adt/pgstatfuncs.c | 24 +++++++-- + src/backend/utils/misc/guc.c | 9 ++++ src/backend/utils/misc/postgresql.conf.sample | 1 + src/include/access/xlog.h | 1 + src/include/catalog/pg_proc.dat | 14 ++--- - src/include/pgstat.h | 8 +++ - src/test/regress/expected/rules.out | 6 +- - 13 files changed, 189 insertions(+), 13 deletions(-) + src/include/pgstat.h | 10 +++- + src/test/regress/expected/rules.out | 6 ++- + 15 files changed, 232 insertions(+), 18 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 82864bbb24..43f3fbcaf8 100644 @@ -72,7 +74,7 @@ track_functions (enum) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml -index f05140dd42..36764dc64f 100644 +index f05140dd42..5a8fc4eb0c 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3485,7 +3485,53 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i @@ -80,7 +82,7 @@ - Number of times WAL data was written to disk because WAL buffers became full -+ Total number of times WAL data was written to disk because WAL buffers became full ++ Total number of WAL data written to disk because WAL buffers became full + + + @@ -89,7 +91,7 @@ + wal_write bigint + + -+ Total number of times WAL data was written to disk ++ Total number of WAL data written to disk + + + @@ -109,7 +111,7 @@ + wal_sync bigint + + -+ Total number of times WAL data was synced to disk ++ Total number of WAL data synced to disk + (if is open_datasync or + open_sync, this value is zero because WAL data is synced + when to write it). @@ -131,7 +133,7 @@ diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c -index 470e113b33..b3890f97a2 100644 +index 470e113b33..1c4860bee7 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 */ @@ -142,16 +144,15 @@ #ifdef WAL_DEBUG bool XLOG_DEBUG = false; -@@ -2540,6 +2541,8 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible) +@@ -2540,6 +2541,7 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible) Size nbytes; Size nleft; int written; + instr_time start; -+ instr_time duration; /* OK to write the page(s) */ from = XLogCtl->pages + startidx * (Size) XLOG_BLCKSZ; -@@ -2548,9 +2551,24 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible) +@@ -2548,9 +2550,27 @@ XLogWrite(XLogwrtRqst WriteRqst, bool flexible) do { errno = 0; @@ -164,8 +165,11 @@ written = pg_pwrite(openLogFile, from, nleft, startoffset); pgstat_report_wait_end(); + ++ /* increment the i/o timing and the number of WAL data written */ + 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); @@ -176,57 +180,47 @@ if (written <= 0) { char xlogfname[MAXFNAMELEN]; -@@ -10565,7 +10583,33 @@ assign_xlog_sync_method(int new_sync_method, void *extra) +@@ -10565,7 +10585,12 @@ assign_xlog_sync_method(int new_sync_method, void *extra) void issue_xlog_fsync(int fd, XLogSegNo segno) { - char *msg = NULL; + char *msg = NULL; -+ bool sync_called = false; /* whether to sync data right now. */ + instr_time start; -+ instr_time duration; -+ -+ /* check whether to sync WAL data to the disk right now. */ -+ if (enableFsync) -+ { -+ switch (sync_method) -+ { -+ case SYNC_METHOD_FSYNC: -+#ifdef HAVE_FSYNC_WRITETHROUGH -+ case SYNC_METHOD_FSYNC_WRITETHROUGH: -+#endif -+#ifdef HAVE_FDATASYNC -+ case SYNC_METHOD_FDATASYNC: -+#endif -+ sync_called = true; -+ default: -+ /* other method synced data already or it's not unrecognized. */ -+ break; -+ } -+ } + + /* Measure i/o timing to sync WAL data.*/ -+ if (track_wal_io_timing && sync_called) ++ if (track_wal_io_timing) + INSTR_TIME_SET_CURRENT(start); pgstat_report_wait_start(WAIT_EVENT_WAL_SYNC); switch (sync_method) -@@ -10610,6 +10654,19 @@ issue_xlog_fsync(int fd, XLogSegNo segno) +@@ -10610,6 +10635,30 @@ issue_xlog_fsync(int fd, XLogSegNo segno) } pgstat_report_wait_end(); + -+ if (sync_called) ++ /* ++ * check whether to sync WAL data to the disk right now because ++ * statistics must be incremented when syncing really occurred. ++ */ ++ if (enableFsync) + { -+ /* increment the i/o timing and the number of times to fsync WAL data */ -+ if (track_wal_io_timing) ++ if ((sync_method == SYNC_METHOD_FSYNC) || ++ (sync_method == SYNC_METHOD_FSYNC_WRITETHROUGH) || ++ (sync_method == SYNC_METHOD_FDATASYNC)) + { -+ INSTR_TIME_SET_CURRENT(duration); -+ INSTR_TIME_SUBTRACT(duration, start); -+ WalStats.m_wal_sync_time = INSTR_TIME_GET_MICROSEC(duration); -+ } ++ /* increment the i/o timing and the number of WAL data 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++; ++ WalStats.m_wal_sync++; ++ } + } } @@ -246,11 +240,69 @@ w.stats_reset FROM pg_stat_get_wal() w; +diff --git a/src/backend/postmaster/checkpointer.c b/src/backend/postmaster/checkpointer.c +index 54a818bf61..5d14a97e56 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_send_wal(true); + + /* + * 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..987bbd058d 100644 +index f75b52719d..256d8706ca 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c -@@ -6892,6 +6892,10 @@ pgstat_recv_wal(PgStat_MsgWal *msg, int len) +@@ -975,7 +975,7 @@ pgstat_report_stat(bool disconnect) + pgstat_send_funcstats(); + + /* Send WAL statistics */ +- pgstat_send_wal(); ++ pgstat_send_wal(true); + + /* Finally send SLRU statistics */ + pgstat_send_slru(); +@@ -4669,17 +4669,33 @@ pgstat_send_bgwriter(void) + /* ---------- + * pgstat_send_wal() - + * +- * Send WAL statistics to the collector ++ * Send WAL statistics to the collector. ++ * ++ * If force is false, don't send a message unless it's been at ++ * least PGSTAT_STAT_INTERVAL msec since we last sent one. + * ---------- + */ + void +-pgstat_send_wal(void) ++pgstat_send_wal(bool force) + { + /* We assume this initializes to zeroes */ + static const PgStat_MsgWal all_zeroes; ++ static TimestampTz last_report = 0; + ++ TimestampTz now; + WalUsage walusage; + ++ /* ++ * Don't send a message unless it's been at least PGSTAT_STAT_INTERVAL ++ * msec since we last sent one or specified "force". ++ */ ++ now = GetCurrentTimestamp(); ++ if (!force && ++ !TimestampDifferenceExceeds(last_report, now, PGSTAT_STAT_INTERVAL)) ++ return; ++ ++ last_report = now; ++ + /* + * Calculate how much WAL usage counters are increased by substracting the + * previous counters from the current ones. Fill the results in WAL stats +@@ -6892,6 +6908,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; @@ -262,7 +314,7 @@ /* ---------- diff --git a/src/backend/postmaster/walwriter.c b/src/backend/postmaster/walwriter.c -index 4f1a8e356b..104cba4581 100644 +index 4f1a8e356b..7fd56d1497 100644 --- a/src/backend/postmaster/walwriter.c +++ b/src/backend/postmaster/walwriter.c @@ -253,6 +253,9 @@ WalWriterMain(void) @@ -270,11 +322,68 @@ left_till_hibernate--; + /* Send WAL statistics */ -+ pgstat_send_wal(); ++ pgstat_send_wal(true); + /* * 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/replication/walreceiver.c b/src/backend/replication/walreceiver.c +index 723f513d8b..901b194773 100644 +--- a/src/backend/replication/walreceiver.c ++++ b/src/backend/replication/walreceiver.c +@@ -485,7 +485,18 @@ WalReceiverMain(void) + + /* Check if we need to exit the streaming loop. */ + if (endofwal) ++ { ++ /* Send WAL statistics to the stats collector. */ ++ pgstat_send_wal(true); + break; ++ } ++ ++ /* ++ * Send WAL statistics to the stats collector. ++ * Don't send a message unless it's been at least PGSTAT_STAT_INTERVAL ++ * msec since we last sent one. ++ */ ++ pgstat_send_wal(false); + + /* + * Ideally we would reuse a WaitEventSet object repeatedly +@@ -874,6 +885,7 @@ XLogWalRcvWrite(char *buf, Size nbytes, XLogRecPtr recptr) + while (nbytes > 0) + { + int segbytes; ++ instr_time start; + + if (recvFile < 0 || !XLByteInSeg(recptr, recvSegNo, wal_segment_size)) + { +@@ -931,7 +943,25 @@ XLogWalRcvWrite(char *buf, Size nbytes, XLogRecPtr recptr) + /* OK to write the logs */ + errno = 0; + ++ ++ /* Measure i/o timing to write WAL data */ ++ if (track_wal_io_timing) ++ INSTR_TIME_SET_CURRENT(start); ++ + byteswritten = pg_pwrite(recvFile, buf, segbytes, (off_t) startoff); ++ ++ /* increment the i/o timing and the number of WAL data written */ ++ 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 (byteswritten <= 0) + { + char xlogfname[MAXFNAMELEN]; diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 62bff52638..7296ef04ff 100644 --- a/src/backend/utils/adt/pgstatfuncs.c @@ -394,7 +503,7 @@ { oid => '2306', descr => 'statistics: information about SLRU caches', proname => 'pg_stat_get_slru', prorows => '100', proisstrict => 'f', diff --git a/src/include/pgstat.h b/src/include/pgstat.h -index 724068cf87..e689d27480 100644 +index 724068cf87..8ef959c0cc 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -474,6 +474,10 @@ typedef struct PgStat_MsgWal @@ -419,6 +528,15 @@ TimestampTz stat_reset_timestamp; } PgStat_WalStats; +@@ -1590,7 +1598,7 @@ 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_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 6173473de9..bc3909fd17 100644 --- a/src/test/regress/expected/rules.out