From 3134d8863e8473e3ed791e27d484f9e548220411 Mon Sep 17 00:00:00 2001 From: Robert Haas Date: Mon, 15 Nov 2010 12:42:59 -0500 Subject: [PATCH] Add new buffers_backend_fsync field to pg_stat_bgwriter. This new field counts the number of times that a backend which writes a buffer out to the OS must also fsync() it. This happens when the bgwriter fsync request queue is full, and is generally detrimental to performance, so it's good to know when it's happening. Along the way, log a new message at level DEBUG1 whenever we fail to hand off an fsync, so that the problem can also be seen in examination of log files (if the logging level is cranked up high enough). Greg Smith, with minor tweaks by me. --- doc/src/sgml/monitoring.sgml | 6 ++++-- src/backend/catalog/system_views.sql | 1 + src/backend/postmaster/bgwriter.c | 16 ++++++++++++---- src/backend/postmaster/pgstat.c | 1 + src/backend/storage/smgr/md.c | 3 +++ src/backend/utils/adt/pgstatfuncs.c | 7 +++++++ src/include/catalog/catversion.h | 2 +- src/include/catalog/pg_proc.h | 2 ++ src/include/pgstat.h | 2 ++ src/test/regress/expected/rules.out | 2 +- 10 files changed, 34 insertions(+), 8 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index dbf966b631..5fd0213823 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -264,8 +264,10 @@ postgres: user database host diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 09574c3e82..82788fa14a 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -537,6 +537,7 @@ CREATE VIEW pg_stat_bgwriter AS pg_stat_get_bgwriter_buf_written_clean() AS buffers_clean, pg_stat_get_bgwriter_maxwritten_clean() AS maxwritten_clean, pg_stat_get_buf_written_backend() AS buffers_backend, + pg_stat_get_buf_fsync_backend() AS buffers_backend_fsync, pg_stat_get_buf_alloc() AS buffers_alloc; CREATE VIEW pg_user_mappings AS diff --git a/src/backend/postmaster/bgwriter.c b/src/backend/postmaster/bgwriter.c index 0690ab521e..620b1972a6 100644 --- a/src/backend/postmaster/bgwriter.c +++ b/src/backend/postmaster/bgwriter.c @@ -102,13 +102,15 @@ * * num_backend_writes is used to count the number of buffer writes performed * by non-bgwriter processes. This counter should be wide enough that it - * can't overflow during a single bgwriter cycle. + * can't overflow during a single bgwriter cycle. num_backend_fsync + * counts the subset of those writes that also had to do their own fsync, + * because the background writer failed to absorb their request. * * The requests array holds fsync requests sent by backends and not yet * absorbed by the bgwriter. * - * Unlike the checkpoint fields, num_backend_writes and the requests - * fields are protected by BgWriterCommLock. + * Unlike the checkpoint fields, num_backend_writes, num_backend_fsync, and + * the requests fields are protected by BgWriterCommLock. *---------- */ typedef struct @@ -132,6 +134,7 @@ typedef struct int ckpt_flags; /* checkpoint flags, as defined in xlog.h */ uint32 num_backend_writes; /* counts non-bgwriter buffer writes */ + uint32 num_backend_fsync; /* counts non-bgwriter fsync calls */ int num_requests; /* current # of requests */ int max_requests; /* allocated array size */ @@ -1084,12 +1087,14 @@ ForwardFsyncRequest(RelFileNodeBackend rnode, ForkNumber forknum, LWLockAcquire(BgWriterCommLock, LW_EXCLUSIVE); - /* we count non-bgwriter writes even when the request queue overflows */ + /* Count all backend writes regardless of if they fit in the queue */ BgWriterShmem->num_backend_writes++; if (BgWriterShmem->bgwriter_pid == 0 || BgWriterShmem->num_requests >= BgWriterShmem->max_requests) { + /* Also count the subset where backends have to do their own fsync */ + BgWriterShmem->num_backend_fsync++; LWLockRelease(BgWriterCommLock); return false; } @@ -1137,7 +1142,10 @@ AbsorbFsyncRequests(void) /* Transfer write count into pending pgstats message */ BgWriterStats.m_buf_written_backend += BgWriterShmem->num_backend_writes; + BgWriterStats.m_buf_fsync_backend += BgWriterShmem->num_backend_fsync; + BgWriterShmem->num_backend_writes = 0; + BgWriterShmem->num_backend_fsync = 0; n = BgWriterShmem->num_requests; if (n > 0) diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c index a1ad342953..c3c136a161 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c @@ -4188,6 +4188,7 @@ pgstat_recv_bgwriter(PgStat_MsgBgWriter *msg, int len) globalStats.buf_written_clean += msg->m_buf_written_clean; globalStats.maxwritten_clean += msg->m_maxwritten_clean; globalStats.buf_written_backend += msg->m_buf_written_backend; + globalStats.buf_fsync_backend += msg->m_buf_fsync_backend; globalStats.buf_alloc += msg->m_buf_alloc; } diff --git a/src/backend/storage/smgr/md.c b/src/backend/storage/smgr/md.c index 1219fcffeb..604db218ee 100644 --- a/src/backend/storage/smgr/md.c +++ b/src/backend/storage/smgr/md.c @@ -1224,6 +1224,9 @@ register_dirty_segment(SMgrRelation reln, ForkNumber forknum, MdfdVec *seg) if (ForwardFsyncRequest(reln->smgr_rnode, forknum, seg->mdfd_segno)) return; /* passed it off successfully */ + ereport(DEBUG1, + (errmsg("could not forward fsync request because request queue is full"))); + if (FileSync(seg->mdfd_vfd) < 0) ereport(ERROR, (errcode_for_file_access(), diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 6edb8bfd13..adab948e0d 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -78,6 +78,7 @@ extern Datum pg_stat_get_bgwriter_buf_written_checkpoints(PG_FUNCTION_ARGS); extern Datum pg_stat_get_bgwriter_buf_written_clean(PG_FUNCTION_ARGS); extern Datum pg_stat_get_bgwriter_maxwritten_clean(PG_FUNCTION_ARGS); extern Datum pg_stat_get_buf_written_backend(PG_FUNCTION_ARGS); +extern Datum pg_stat_get_buf_fsync_backend(PG_FUNCTION_ARGS); extern Datum pg_stat_get_buf_alloc(PG_FUNCTION_ARGS); extern Datum pg_stat_get_xact_numscans(PG_FUNCTION_ARGS); @@ -1165,6 +1166,12 @@ pg_stat_get_buf_written_backend(PG_FUNCTION_ARGS) } Datum +pg_stat_get_buf_fsync_backend(PG_FUNCTION_ARGS) +{ + PG_RETURN_INT64(pgstat_fetch_global()->buf_fsync_backend); +} + +Datum pg_stat_get_buf_alloc(PG_FUNCTION_ARGS) { PG_RETURN_INT64(pgstat_fetch_global()->buf_alloc); diff --git a/src/include/catalog/catversion.h b/src/include/catalog/catversion.h index 703cbea7d8..d6b6c71ba5 100644 --- a/src/include/catalog/catversion.h +++ b/src/include/catalog/catversion.h @@ -53,6 +53,6 @@ */ /* yyyymmddN */ -#define CATALOG_VERSION_NO 201011091 +#define CATALOG_VERSION_NO 201011151 #endif diff --git a/src/include/catalog/pg_proc.h b/src/include/catalog/pg_proc.h index 4f444aef83..8e5f50293f 100644 --- a/src/include/catalog/pg_proc.h +++ b/src/include/catalog/pg_proc.h @@ -3117,6 +3117,8 @@ DATA(insert OID = 2773 ( pg_stat_get_bgwriter_maxwritten_clean PGNSP PGUID 12 1 DESCR("statistics: number of times the bgwriter stopped processing when it had written too many buffers while cleaning"); DATA(insert OID = 2775 ( pg_stat_get_buf_written_backend PGNSP PGUID 12 1 0 0 f f f t f s 0 0 20 "" _null_ _null_ _null_ _null_ pg_stat_get_buf_written_backend _null_ _null_ _null_ )); DESCR("statistics: number of buffers written by backends"); +DATA(insert OID = 3063 ( pg_stat_get_buf_fsync_backend PGNSP PGUID 12 1 0 0 f f f t f s 0 0 20 "" _null_ _null_ _null_ _null_ pg_stat_get_buf_fsync_backend _null_ _null_ _null_ )); +DESCR("statistics: number of backend buffer writes that did their own fsync"); DATA(insert OID = 2859 ( pg_stat_get_buf_alloc PGNSP PGUID 12 1 0 0 f f f t f s 0 0 20 "" _null_ _null_ _null_ _null_ pg_stat_get_buf_alloc _null_ _null_ _null_ )); DESCR("statistics: number of buffer allocations"); diff --git a/src/include/pgstat.h b/src/include/pgstat.h index d49bd80526..42bf9c4f3a 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -360,6 +360,7 @@ typedef struct PgStat_MsgBgWriter PgStat_Counter m_buf_written_clean; PgStat_Counter m_maxwritten_clean; PgStat_Counter m_buf_written_backend; + PgStat_Counter m_buf_fsync_backend; PgStat_Counter m_buf_alloc; } PgStat_MsgBgWriter; @@ -562,6 +563,7 @@ typedef struct PgStat_GlobalStats PgStat_Counter buf_written_clean; PgStat_Counter maxwritten_clean; PgStat_Counter buf_written_backend; + PgStat_Counter buf_fsync_backend; PgStat_Counter buf_alloc; } PgStat_GlobalStats; diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index c7a796a2a5..be65be91dd 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1293,7 +1293,7 @@ SELECT viewname, definition FROM pg_views WHERE schemaname <> 'information_schem pg_stat_activity | SELECT s.datid, d.datname, s.procpid, s.usesysid, u.rolname AS usename, s.application_name, s.client_addr, s.client_port, s.backend_start, s.xact_start, s.query_start, s.waiting, s.current_query FROM pg_database d, pg_stat_get_activity(NULL::integer) s(datid, procpid, usesysid, application_name, current_query, waiting, xact_start, query_start, backend_start, client_addr, client_port), pg_authid u WHERE ((s.datid = d.oid) AND (s.usesysid = u.oid)); pg_stat_all_indexes | SELECT c.oid AS relid, i.oid AS indexrelid, n.nspname AS schemaname, c.relname, i.relname AS indexrelname, pg_stat_get_numscans(i.oid) AS idx_scan, pg_stat_get_tuples_returned(i.oid) AS idx_tup_read, pg_stat_get_tuples_fetched(i.oid) AS idx_tup_fetch FROM (((pg_class c JOIN pg_index x ON ((c.oid = x.indrelid))) JOIN pg_class i ON ((i.oid = x.indexrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) WHERE (c.relkind = ANY (ARRAY['r'::"char", 't'::"char"])); pg_stat_all_tables | SELECT c.oid AS relid, n.nspname AS schemaname, c.relname, pg_stat_get_numscans(c.oid) AS seq_scan, pg_stat_get_tuples_returned(c.oid) AS seq_tup_read, (sum(pg_stat_get_numscans(i.indexrelid)))::bigint AS idx_scan, ((sum(pg_stat_get_tuples_fetched(i.indexrelid)))::bigint + pg_stat_get_tuples_fetched(c.oid)) AS idx_tup_fetch, pg_stat_get_tuples_inserted(c.oid) AS n_tup_ins, pg_stat_get_tuples_updated(c.oid) AS n_tup_upd, pg_stat_get_tuples_deleted(c.oid) AS n_tup_del, pg_stat_get_tuples_hot_updated(c.oid) AS n_tup_hot_upd, pg_stat_get_live_tuples(c.oid) AS n_live_tup, pg_stat_get_dead_tuples(c.oid) AS n_dead_tup, pg_stat_get_last_vacuum_time(c.oid) AS last_vacuum, pg_stat_get_last_autovacuum_time(c.oid) AS last_autovacuum, pg_stat_get_last_analyze_time(c.oid) AS last_analyze, pg_stat_get_last_autoanalyze_time(c.oid) AS last_autoanalyze, pg_stat_get_vacuum_count(c.oid) AS vacuum_count, pg_stat_get_autovacuum_count(c.oid) AS autovacuum_count, pg_stat_get_analyze_count(c.oid) AS analyze_count, pg_stat_get_autoanalyze_count(c.oid) AS autoanalyze_count FROM ((pg_class c LEFT JOIN pg_index i ON ((c.oid = i.indrelid))) LEFT JOIN pg_namespace n ON ((n.oid = c.relnamespace))) WHERE (c.relkind = ANY (ARRAY['r'::"char", 't'::"char"])) GROUP BY c.oid, n.nspname, c.relname; - pg_stat_bgwriter | SELECT pg_stat_get_bgwriter_timed_checkpoints() AS checkpoints_timed, pg_stat_get_bgwriter_requested_checkpoints() AS checkpoints_req, pg_stat_get_bgwriter_buf_written_checkpoints() AS buffers_checkpoint, pg_stat_get_bgwriter_buf_written_clean() AS buffers_clean, pg_stat_get_bgwriter_maxwritten_clean() AS maxwritten_clean, pg_stat_get_buf_written_backend() AS buffers_backend, pg_stat_get_buf_alloc() AS buffers_alloc; + pg_stat_bgwriter | SELECT pg_stat_get_bgwriter_timed_checkpoints() AS checkpoints_timed, pg_stat_get_bgwriter_requested_checkpoints() AS checkpoints_req, pg_stat_get_bgwriter_buf_written_checkpoints() AS buffers_checkpoint, pg_stat_get_bgwriter_buf_written_clean() AS buffers_clean, pg_stat_get_bgwriter_maxwritten_clean() AS maxwritten_clean, pg_stat_get_buf_written_backend() AS buffers_backend, pg_stat_get_buf_fsync_backend() AS buffers_backend_fsync, pg_stat_get_buf_alloc() AS buffers_alloc; pg_stat_database | SELECT d.oid AS datid, d.datname, pg_stat_get_db_numbackends(d.oid) AS numbackends, pg_stat_get_db_xact_commit(d.oid) AS xact_commit, pg_stat_get_db_xact_rollback(d.oid) AS xact_rollback, (pg_stat_get_db_blocks_fetched(d.oid) - pg_stat_get_db_blocks_hit(d.oid)) AS blks_read, pg_stat_get_db_blocks_hit(d.oid) AS blks_hit, pg_stat_get_db_tuples_returned(d.oid) AS tup_returned, pg_stat_get_db_tuples_fetched(d.oid) AS tup_fetched, pg_stat_get_db_tuples_inserted(d.oid) AS tup_inserted, pg_stat_get_db_tuples_updated(d.oid) AS tup_updated, pg_stat_get_db_tuples_deleted(d.oid) AS tup_deleted FROM pg_database d; pg_stat_sys_indexes | SELECT pg_stat_all_indexes.relid, pg_stat_all_indexes.indexrelid, pg_stat_all_indexes.schemaname, pg_stat_all_indexes.relname, pg_stat_all_indexes.indexrelname, pg_stat_all_indexes.idx_scan, pg_stat_all_indexes.idx_tup_read, pg_stat_all_indexes.idx_tup_fetch FROM pg_stat_all_indexes WHERE ((pg_stat_all_indexes.schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (pg_stat_all_indexes.schemaname ~ '^pg_toast'::text)); pg_stat_sys_tables | SELECT pg_stat_all_tables.relid, pg_stat_all_tables.schemaname, pg_stat_all_tables.relname, pg_stat_all_tables.seq_scan, pg_stat_all_tables.seq_tup_read, pg_stat_all_tables.idx_scan, pg_stat_all_tables.idx_tup_fetch, pg_stat_all_tables.n_tup_ins, pg_stat_all_tables.n_tup_upd, pg_stat_all_tables.n_tup_del, pg_stat_all_tables.n_tup_hot_upd, pg_stat_all_tables.n_live_tup, pg_stat_all_tables.n_dead_tup, pg_stat_all_tables.last_vacuum, pg_stat_all_tables.last_autovacuum, pg_stat_all_tables.last_analyze, pg_stat_all_tables.last_autoanalyze, pg_stat_all_tables.vacuum_count, pg_stat_all_tables.autovacuum_count, pg_stat_all_tables.analyze_count, pg_stat_all_tables.autoanalyze_count FROM pg_stat_all_tables WHERE ((pg_stat_all_tables.schemaname = ANY (ARRAY['pg_catalog'::name, 'information_schema'::name])) OR (pg_stat_all_tables.schemaname ~ '^pg_toast'::text)); -- 2.11.0