From ff99918c625a84c91e7391db9032112ec8653623 Mon Sep 17 00:00:00 2001 From: Fujii Masao Date: Tue, 9 Mar 2021 16:52:06 +0900 Subject: Track total amounts of times spent writing and syncing WAL data to disk. This commit adds new GUC track_wal_io_timing. When this is enabled, the total amounts of time XLogWrite writes and issue_xlog_fsync syncs WAL data to disk are counted in pg_stat_wal. This information would be useful to check how much WAL write and sync affect the performance. Enabling track_wal_io_timing will make the server query the operating system for the current time every time WAL is written or synced, which may cause significant overhead on some platforms. To avoid such additional overhead in the server with track_io_timing enabled, this commit introduces track_wal_io_timing as a separate parameter from track_io_timing. Note that WAL write and sync activity by walreceiver has not been tracked yet. This commit makes the server also track the numbers of times XLogWrite writes and issue_xlog_fsync syncs WAL data to disk, in pg_stat_wal, regardless of the setting of track_wal_io_timing. This counters can be used to calculate the WAL write and sync time per request, for example. Bump PGSTAT_FILE_FORMAT_ID. Bump catalog version. Author: Masahiro Ikeda Reviewed-By: Japin Li, Hayato Kuroda, Masahiko Sawada, David Johnston, Fujii Masao Discussion: https://postgr.es/m/0509ad67b585a5b86a83d445dfa75392@oss.nttdata.com --- doc/src/sgml/config.sgml | 23 +++++++++++++++- doc/src/sgml/monitoring.sgml | 62 ++++++++++++++++++++++++++++++++++++++++++++ doc/src/sgml/wal.sgml | 29 +++++++++++++++++++++ 3 files changed, 113 insertions(+), 1 deletion(-) (limited to 'doc/src') diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 967de73596f..529876895b8 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; 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 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; + + 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_wal. Only superusers can + change this setting. + + + + track_functions (enum) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 51f73384041..3335d71eba0 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -185,6 +185,11 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser of block read and write times. + + The parameter enables monitoring + of WAL write times. + + Normally these parameters are set in postgresql.conf so that they apply to all server processes, but it is possible to turn @@ -3477,6 +3482,63 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i + + + wal_write bigint + + + Number of times WAL buffers were written out to disk via + XLogWrite request. + See for more information about + the internal WAL function XLogWrite. + + + + + + wal_sync bigint + + + Number of times WAL files were synced to disk via + issue_xlog_fsync request + (if is on and + is either + fdatasync, fsync or + fsync_writethrough, otherwise zero). + See for more information about + the internal WAL function issue_xlog_fsync. + + + + + + wal_write_time double precision + + + Total amount of time spent writing WAL buffers to disk via + XLogWrite request, in milliseconds + (if is enabled, + otherwise zero). This includes the sync time when + wal_sync_method is either + open_datasync or open_sync. + + + + + + wal_sync_time double precision + + + Total amount of time spent syncing WAL files to disk via + issue_xlog_fsync request, in milliseconds + (if track_wal_io_timing is enabled, + fsync is on, and + wal_sync_method is either + fdatasync, fsync or + fsync_writethrough, otherwise zero). + + + stats_reset timestamp with time zone diff --git a/doc/src/sgml/wal.sgml b/doc/src/sgml/wal.sgml index f75527f764a..ae4a3c12931 100644 --- a/doc/src/sgml/wal.sgml +++ b/doc/src/sgml/wal.sgml @@ -767,6 +767,35 @@ WAL call being logged to the server log. This option might be replaced by a more general mechanism in the future. + + + There are two internal functions to write WAL data to disk: + XLogWrite and issue_xlog_fsync. + When 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 + , 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. + issue_xlog_fsync is normally called by + XLogWrite to sync WAL files to disk. + 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 buffers to kernel cache and + issue_xlog_fsync syncs them 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. + -- cgit v1.2.3