--- v6-0001-Add-statistics-related-to-write-sync-wal-records.patch 2021-01-25 16:27:50.749429666 +0900 +++ v7-0001-Add-statistics-related-to-write-sync-wal-records.patch 2021-01-26 08:19:48.269760642 +0900 @@ -1,6 +1,6 @@ -From e9aad92097c5cff5565b67ce1a8ec6d7b4c8a4d9 Mon Sep 17 00:00:00 2001 +From 02f0888efeb09ae641d9ef905788d995d687c56f Mon Sep 17 00:00:00 2001 From: Masahiro Ikeda -Date: Mon, 25 Jan 2021 16:26:04 +0900 +Date: Tue, 26 Jan 2021 08:18:37 +0900 Subject: [PATCH] Add statistics related to write/sync wal records. This patch adds following statistics to pg_stat_wal view @@ -22,24 +22,24 @@ Reviewed-By: Japin Li, Hayato Kuroda, Masahiko Sawada Discussion: https://postgr.es/m/0509ad67b585a5b86a83d445dfa75392@oss.nttdata.com -(This requires a catversion bump, as well as an update to PGSTAT_FILE_FORMAT_ID) +(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 | 51 ++++++++++++++++++- + doc/src/sgml/config.sgml | 21 +++++++ + doc/src/sgml/monitoring.sgml | 48 +++++++++++++++- + src/backend/access/transam/xlog.c | 56 ++++++++++++++++++- src/backend/catalog/system_views.sql | 4 ++ 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/postmaster/pgstat.c | 4 ++ + src/backend/postmaster/walwriter.c | 3 + + src/backend/replication/walreceiver.c | 34 +++++++++++ + 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 | 10 +++- - src/test/regress/expected/rules.out | 6 ++- - 15 files changed, 232 insertions(+), 18 deletions(-) + src/include/pgstat.h | 8 +++ + src/test/regress/expected/rules.out | 6 +- + 15 files changed, 221 insertions(+), 14 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 82864bbb24..43f3fbcaf8 100644 @@ -133,7 +133,7 @@ diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c -index 470e113b33..1c4860bee7 100644 +index 470e113b33..f780a2eb4f 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 */ @@ -165,7 +165,7 @@ written = pg_pwrite(openLogFile, from, nleft, startoffset); pgstat_report_wait_end(); + -+ /* increment the i/o timing and the number of WAL data written */ ++ /* Increment the i/o timing and the number of WAL data written */ + if (track_wal_io_timing) + { + instr_time duration; @@ -180,47 +180,52 @@ if (written <= 0) { char xlogfname[MAXFNAMELEN]; -@@ -10565,7 +10585,12 @@ assign_xlog_sync_method(int new_sync_method, void *extra) +@@ -10565,7 +10585,22 @@ 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 issue_fsync = false; + instr_time start; + -+ /* Measure i/o timing to sync WAL data.*/ -+ if (track_wal_io_timing) -+ INSTR_TIME_SET_CURRENT(start); ++ /* Check whether to sync WAL data to the disk right now */ ++ if (enableFsync && ++ (sync_method == SYNC_METHOD_FSYNC || ++ sync_method == SYNC_METHOD_FSYNC_WRITETHROUGH || ++ sync_method == SYNC_METHOD_FDATASYNC)) ++ { ++ /* Measure i/o timing to sync WAL data */ ++ if (track_wal_io_timing) ++ INSTR_TIME_SET_CURRENT(start); ++ ++ issue_fsync = true; ++ } pgstat_report_wait_start(WAIT_EVENT_WAL_SYNC); switch (sync_method) -@@ -10610,6 +10635,30 @@ issue_xlog_fsync(int fd, XLogSegNo segno) +@@ -10610,6 +10645,25 @@ issue_xlog_fsync(int fd, XLogSegNo segno) } pgstat_report_wait_end(); + -+ /* -+ * check whether to sync WAL data to the disk right now because ++ /* ++ * Increment the i/o timing and the number of WAL data synced. ++ * ++ * Check whether to sync WAL data to the disk right now because + * statistics must be incremented when syncing really occurred. + */ -+ if (enableFsync) ++ if (issue_fsync) + { -+ if ((sync_method == SYNC_METHOD_FSYNC) || -+ (sync_method == SYNC_METHOD_FSYNC_WRITETHROUGH) || -+ (sync_method == SYNC_METHOD_FDATASYNC)) ++ if (track_wal_io_timing) + { -+ /* 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); -+ } ++ instr_time duration; + -+ WalStats.m_wal_sync++; ++ INSTR_TIME_SET_CURRENT(duration); ++ INSTR_TIME_SUBTRACT(duration, start); ++ WalStats.m_wal_sync_time = INSTR_TIME_GET_MICROSEC(duration); + } ++ WalStats.m_wal_sync++; + } } @@ -241,68 +246,23 @@ FROM pg_stat_get_wal() w; diff --git a/src/backend/postmaster/checkpointer.c b/src/backend/postmaster/checkpointer.c -index 54a818bf61..5d14a97e56 100644 +index 54a818bf61..80da8acaa4 100644 --- a/src/backend/postmaster/checkpointer.c +++ b/src/backend/postmaster/checkpointer.c -@@ -505,7 +505,7 @@ CheckpointerMain(void) +@@ -504,7 +504,7 @@ CheckpointerMain(void) + */ pgstat_send_bgwriter(); - /* Send WAL statistics to the stats collector. */ -- pgstat_send_wal(); -+ pgstat_send_wal(true); +- /* Send WAL statistics to the stats collector. */ ++ /* Send WAL statistics to stats collector */ + pgstat_send_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..256d8706ca 100644 +index f75b52719d..987bbd058d 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c -@@ -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) +@@ -6892,6 +6892,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; @@ -314,7 +274,7 @@ /* ---------- diff --git a/src/backend/postmaster/walwriter.c b/src/backend/postmaster/walwriter.c -index 4f1a8e356b..7fd56d1497 100644 +index 4f1a8e356b..104cba4581 100644 --- a/src/backend/postmaster/walwriter.c +++ b/src/backend/postmaster/walwriter.c @@ -253,6 +253,9 @@ WalWriterMain(void) @@ -322,35 +282,42 @@ left_till_hibernate--; + /* Send WAL statistics */ -+ pgstat_send_wal(true); ++ pgstat_send_wal(); + /* * 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 +index 723f513d8b..61e98c6eca 100644 --- a/src/backend/replication/walreceiver.c +++ b/src/backend/replication/walreceiver.c -@@ -485,7 +485,18 @@ WalReceiverMain(void) +@@ -485,7 +485,11 @@ WalReceiverMain(void) /* Check if we need to exit the streaming loop. */ if (endofwal) + { -+ /* Send WAL statistics to the stats collector. */ -+ pgstat_send_wal(true); ++ /* Send WAL statistics to stats collector */ ++ pgstat_send_wal(); 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) +@@ -550,8 +554,13 @@ WalReceiverMain(void) + wal_receiver_timeout); + + if (now >= timeout) ++ { ++ /* Send WAL statistics to stats collector before terminating */ ++ pgstat_send_wal(); ++ + ereport(ERROR, + (errmsg("terminating walreceiver due to timeout"))); ++ } + + /* + * We didn't receive anything new, for half of +@@ -874,6 +883,7 @@ XLogWalRcvWrite(char *buf, Size nbytes, XLogRecPtr recptr) while (nbytes > 0) { int segbytes; @@ -358,11 +325,24 @@ if (recvFile < 0 || !XLByteInSeg(recptr, recvSegNo, wal_segment_size)) { -@@ -931,7 +943,25 @@ XLogWalRcvWrite(char *buf, Size nbytes, XLogRecPtr recptr) +@@ -910,6 +920,13 @@ XLogWalRcvWrite(char *buf, Size nbytes, XLogRecPtr recptr) + XLogArchiveForceDone(xlogfname); + else + XLogArchiveNotify(xlogfname); ++ ++ /* ++ * Send WAL statistics to stats collector when finishing the ++ * current WAL segment file to avoid loading stats collector. ++ */ ++ pgstat_send_wal(); ++ + } + recvFile = -1; + +@@ -931,7 +948,24 @@ 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); @@ -503,7 +483,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..8ef959c0cc 100644 +index 724068cf87..e689d27480 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -474,6 +474,10 @@ typedef struct PgStat_MsgWal @@ -528,15 +508,6 @@ 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