From 196f84b8bd8f817b6e21e65de90464d32a27b286 Mon Sep 17 00:00:00 2001 From: Bertrand Drouvot Date: Mon, 24 Feb 2025 11:29:35 +0000 Subject: [PATCH v2] re-introduce track_wal_io_timing a051e71e28a added the "timing tracking" in the WAL code path with "only" track_io_timing enabled (and track_wal_io_timing still false). Then it made sense for 2421e9a51d2 to get rid of the track_wal_io_timing GUC. Concerns have been raised about the fact that a051e71e28a added the "timing tracking" in the WAL code path with "only" track_io_timing enabled. So this commit re-introduces the track_wal_io_timing GUC and ensure that WAL timing is tracked in pg_stat_io only if track_io_timing and track_wal_io_timing are both enabled. --- src/include/access/xlog.h | 1 + src/include/pgstat.h | 2 +- src/backend/access/transam/xlog.c | 9 +++--- src/backend/access/transam/xlogreader.c | 2 +- src/backend/access/transam/xlogrecovery.c | 2 +- src/backend/storage/buffer/bufmgr.c | 10 +++--- src/backend/storage/buffer/localbuf.c | 4 +-- src/backend/storage/smgr/md.c | 4 +-- src/backend/utils/activity/pgstat_backend.c | 3 +- src/backend/utils/activity/pgstat_io.c | 9 +++--- src/backend/utils/misc/guc_tables.c | 9 ++++++ src/backend/utils/misc/postgresql.conf.sample | 1 + doc/src/sgml/config.sgml | 25 +++++++++++++++ doc/src/sgml/monitoring.sgml | 31 ++++++++++++++++--- doc/src/sgml/wal.sgml | 4 +-- 15 files changed, 88 insertions(+), 28 deletions(-) diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h index 0a50d160bba8..d313099c027f 100644 --- a/src/include/access/xlog.h +++ b/src/include/access/xlog.h @@ -54,6 +54,7 @@ extern PGDLLIMPORT char *wal_consistency_checking_string; extern PGDLLIMPORT bool log_checkpoints; extern PGDLLIMPORT int CommitDelay; extern PGDLLIMPORT int CommitSiblings; +extern PGDLLIMPORT bool track_wal_io_timing; extern PGDLLIMPORT int wal_decode_buffer_size; extern PGDLLIMPORT int CheckPointSegments; diff --git a/src/include/pgstat.h b/src/include/pgstat.h index fc651d03cf97..e64c527265b9 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -564,7 +564,7 @@ extern bool pgstat_bktype_io_stats_valid(PgStat_BktypeIO *backend_io, BackendType bktype); extern void pgstat_count_io_op(IOObject io_object, IOContext io_context, IOOp io_op, uint32 cnt, uint64 bytes); -extern instr_time pgstat_prepare_io_time(void); +extern instr_time pgstat_prepare_io_time(bool track_io_guc); extern void pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, instr_time start_time, uint32 cnt, uint64 bytes); diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 919314f82587..799fc739e18c 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -134,6 +134,7 @@ int CommitSiblings = 5; /* # concurrent xacts needed to sleep */ int wal_retrieve_retry_interval = 5000; int max_slot_wal_keep_size_mb = -1; int wal_decode_buffer_size = 512 * 1024; +bool track_wal_io_timing = false; #ifdef WAL_DEBUG bool XLOG_DEBUG = false; @@ -2437,7 +2438,7 @@ XLogWrite(XLogwrtRqst WriteRqst, TimeLineID tli, bool flexible) /* * Measure I/O timing to write WAL data, for pg_stat_io. */ - start = pgstat_prepare_io_time(); + start = pgstat_prepare_io_time(track_wal_io_timing); pgstat_report_wait_start(WAIT_EVENT_WAL_WRITE); written = pg_pwrite(openLogFile, from, nleft, startoffset); @@ -3248,7 +3249,7 @@ XLogFileInitInternal(XLogSegNo logsegno, TimeLineID logtli, errmsg("could not create file \"%s\": %m", tmppath))); /* Measure I/O timing when initializing segment */ - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_wal_io_timing); pgstat_report_wait_start(WAIT_EVENT_WAL_INIT_WRITE); save_errno = 0; @@ -3310,7 +3311,7 @@ XLogFileInitInternal(XLogSegNo logsegno, TimeLineID logtli, } /* Measure I/O timing when flushing segment */ - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_wal_io_timing); pgstat_report_wait_start(WAIT_EVENT_WAL_INIT_SYNC); if (pg_fsync(fd) != 0) @@ -8744,7 +8745,7 @@ issue_xlog_fsync(int fd, XLogSegNo segno, TimeLineID tli) /* * Measure I/O timing to sync the WAL file for pg_stat_io. */ - start = pgstat_prepare_io_time(); + start = pgstat_prepare_io_time(track_wal_io_timing); pgstat_report_wait_start(WAIT_EVENT_WAL_SYNC); switch (wal_sync_method) diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c index 995e4f7c26fd..5483d4f0dd2b 100644 --- a/src/backend/access/transam/xlogreader.c +++ b/src/backend/access/transam/xlogreader.c @@ -1557,7 +1557,7 @@ WALRead(XLogReaderState *state, #ifndef FRONTEND /* Measure I/O timing when reading segment */ - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_wal_io_timing); pgstat_report_wait_start(WAIT_EVENT_WAL_READ); #endif diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c index 915cb330295c..c5475aaa97a1 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -3401,7 +3401,7 @@ retry: readOff = targetPageOff; /* Measure I/O timing when reading segment */ - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_wal_io_timing); pgstat_report_wait_start(WAIT_EVENT_WAL_READ); r = pg_pread(readFile, readBuf, XLOG_BLCKSZ, (off_t) readOff); diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index d3216ef6ba75..75cfc2b6fe96 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -1509,7 +1509,7 @@ WaitReadBuffers(ReadBuffersOperation *operation) io_pages[io_buffers_len++] = BufferGetBlock(buffers[i]); } - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); smgrreadv(operation->smgr, forknum, io_first_block, io_pages, io_buffers_len); pgstat_count_io_op_time(io_object, io_context, IOOP_READ, io_start, 1, io_buffers_len * BLCKSZ); @@ -2401,7 +2401,7 @@ ExtendBufferedRelShared(BufferManagerRelation bmr, } } - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); /* * Note: if smgrzeroextend fails, we will end up with buffers that are @@ -3858,7 +3858,7 @@ FlushBuffer(BufferDesc *buf, SMgrRelation reln, IOObject io_object, */ bufToWrite = PageSetChecksumCopy((Page) bufBlock, buf->tag.blockNum); - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); /* * bufToWrite is either the shared buffer or a copy, as appropriate. @@ -4460,7 +4460,7 @@ FlushRelationBuffers(Relation rel) PageSetChecksumInplace(localpage, bufHdr->tag.blockNum); - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); smgrwrite(srel, BufTagGetForkNum(&bufHdr->tag), @@ -5917,7 +5917,7 @@ IssuePendingWritebacks(WritebackContext *wb_context, IOContext io_context) sort_pending_writebacks(wb_context->pending_writebacks, wb_context->nr_pending); - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); /* * Coalesce neighbouring writes, but nothing else. For that we iterate diff --git a/src/backend/storage/buffer/localbuf.c b/src/backend/storage/buffer/localbuf.c index 78b65fb160ad..64931efaa756 100644 --- a/src/backend/storage/buffer/localbuf.c +++ b/src/backend/storage/buffer/localbuf.c @@ -244,7 +244,7 @@ GetLocalVictimBuffer(void) PageSetChecksumInplace(localpage, bufHdr->tag.blockNum); - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); /* And write... */ smgrwrite(oreln, @@ -414,7 +414,7 @@ ExtendBufferedRelLocal(BufferManagerRelation bmr, } } - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); /* actually extend relation */ smgrzeroextend(bmr.smgr, fork, first_block, extend_by, false); diff --git a/src/backend/storage/smgr/md.c b/src/backend/storage/smgr/md.c index 298754d1b64a..7bf0b45e2c34 100644 --- a/src/backend/storage/smgr/md.c +++ b/src/backend/storage/smgr/md.c @@ -1381,7 +1381,7 @@ register_dirty_segment(SMgrRelation reln, ForkNumber forknum, MdfdVec *seg) ereport(DEBUG1, (errmsg_internal("could not forward fsync request because request queue is full"))); - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); if (FileSync(seg->mdfd_vfd, WAIT_EVENT_DATA_FILE_SYNC) < 0) ereport(data_sync_elevel(ERROR), @@ -1786,7 +1786,7 @@ mdsyncfiletag(const FileTag *ftag, char *path) need_to_close = true; } - io_start = pgstat_prepare_io_time(); + io_start = pgstat_prepare_io_time(track_io_timing); /* Sync the file. */ result = FileSync(file, WAIT_EVENT_DATA_FILE_SYNC); diff --git a/src/backend/utils/activity/pgstat_backend.c b/src/backend/utils/activity/pgstat_backend.c index 4a667e7019cc..338da73a9a91 100644 --- a/src/backend/utils/activity/pgstat_backend.c +++ b/src/backend/utils/activity/pgstat_backend.c @@ -24,6 +24,7 @@ #include "postgres.h" +#include "access/xlog.h" #include "storage/bufmgr.h" #include "utils/memutils.h" #include "utils/pgstat_internal.h" @@ -43,7 +44,7 @@ void pgstat_count_backend_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, instr_time io_time) { - Assert(track_io_timing); + Assert(track_io_timing || track_wal_io_timing); if (!pgstat_tracks_backend_bktype(MyBackendType)) return; diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c index e7362b52a37b..edb489f3a864 100644 --- a/src/backend/utils/activity/pgstat_io.c +++ b/src/backend/utils/activity/pgstat_io.c @@ -83,14 +83,15 @@ pgstat_count_io_op(IOObject io_object, IOContext io_context, IOOp io_op, } /* - * Initialize the internal timing for an IO operation. + * Initialize the internal timing for an IO operation, depending on an + * IO timing GUC. */ instr_time -pgstat_prepare_io_time(void) +pgstat_prepare_io_time(bool track_io_guc) { instr_time io_start; - if (track_io_timing) + if (track_io_guc) INSTR_TIME_SET_CURRENT(io_start); else { @@ -119,7 +120,7 @@ void pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, instr_time start_time, uint32 cnt, uint64 bytes) { - if (track_io_timing) + if (!INSTR_TIME_IS_ZERO(start_time)) { instr_time io_time; diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c index 690bf96ef030..ad25cbb39c55 100644 --- a/src/backend/utils/misc/guc_tables.c +++ b/src/backend/utils/misc/guc_tables.c @@ -1501,6 +1501,15 @@ struct config_bool ConfigureNamesBool[] = false, NULL, NULL, NULL }, + { + {"track_wal_io_timing", PGC_SUSET, STATS_CUMULATIVE, + 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 e771d87da1fb..5362ff805195 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -641,6 +641,7 @@ #track_counts = on #track_cost_delay_timing = off #track_io_timing = off +#track_wal_io_timing = off #track_functions = none # none, pl, all #stats_fetch_consistency = cache # cache, none, snapshot diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index a83545761085..6186648ccaf5 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8393,6 +8393,31 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; + + track_wal_io_timing (boolean) + + track_wal_io_timing configuration parameter + + + + + 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 pg_test_timing tool to + measure the overhead of timing on your system. + I/O timing information is displayed in + + pg_stat_io for the + object wal and in the output of + the + pg_stat_get_backend_io() function. + Only superusers and users with the appropriate SET + privilege can change this setting. + + + + track_functions (enum) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 3dfd059b7ee8..9178f1d34efd 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -183,6 +183,11 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser of block read, write, extend, and fsync times. + + The parameter enables monitoring + of WAL read, write and fsync times. + + Normally these parameters are set in postgresql.conf so that they apply to all server processes, but it is possible to turn @@ -2723,7 +2728,11 @@ description | Waiting for a newly initialized WAL file to reach durable storage Time spent in read operations in milliseconds (if - is enabled, otherwise zero) + is enabled and + object is not wal, + or if is enabled + and object is wal, + otherwise zero) @@ -2757,7 +2766,11 @@ description | Waiting for a newly initialized WAL file to reach durable storage Time spent in write operations in milliseconds (if - is enabled, otherwise zero) + is enabled and + object is not wal, + or if is enabled + and object is wal, + otherwise zero) @@ -2816,8 +2829,12 @@ description | Waiting for a newly initialized WAL file to reach durable storage extend_time double precision - Time spent in extend operations in milliseconds (if - is enabled, otherwise zero) + Time spent in extend operations in milliseconds. (if + is enabled and + object is not wal, + or if is enabled + and object is wal, + otherwise zero) @@ -2887,7 +2904,11 @@ description | Waiting for a newly initialized WAL file to reach durable storage Time spent in fsync operations in milliseconds (if - is enabled, otherwise zero) + is enabled and + object is not wal, + or if is enabled + and object is wal, + otherwise zero) diff --git a/doc/src/sgml/wal.sgml b/doc/src/sgml/wal.sgml index 4fc09761115e..f3b86b26be90 100644 --- a/doc/src/sgml/wal.sgml +++ b/doc/src/sgml/wal.sgml @@ -808,7 +808,7 @@ There are two internal functions to write WAL data to disk: XLogWrite and issue_xlog_fsync. - When is enabled, the total + When is enabled, the total amounts of time XLogWrite writes and issue_xlog_fsync syncs WAL data to disk are counted as write_time and fsync_time in @@ -828,7 +828,7 @@ fsync, or fsync_writethrough, the write operation moves WAL buffers to kernel cache and issue_xlog_fsync syncs them to disk. Regardless - of the setting of track_io_timing, the number + of the setting of track_wal_io_timing, the number of times XLogWrite writes and issue_xlog_fsync syncs WAL data to disk are also counted as writes and fsyncs -- 2.47.2