From b736aef2ec57b520ebadb70cceac0fed3168a5df Mon Sep 17 00:00:00 2001 From: Robert Haas Date: Thu, 5 Apr 2012 14:03:21 -0400 Subject: [PATCH] Publish checkpoint timing information to pg_stat_bgwriter. Greg Smith, Peter Geoghegan, and Robert Haas --- doc/src/sgml/monitoring.sgml | 22 ++++++++++++++++++++ src/backend/access/transam/xlog.c | 30 +++++++++++++++++++--------- src/backend/catalog/system_views.sql | 2 ++ src/backend/postmaster/pgstat.c | 2 ++ src/backend/storage/smgr/md.c | 25 ++++++++++------------- src/backend/utils/adt/pgstatfuncs.c | 14 +++++++++++++ src/include/catalog/catversion.h | 2 +- src/include/catalog/pg_proc.h | 4 ++++ src/include/pgstat.h | 4 ++++ src/test/regress/expected/rules.out | 2 +- 10 files changed, 81 insertions(+), 26 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index ed8aeb20c6..423f9b1a9a 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -767,6 +767,28 @@ SELECT pg_stat_get_backend_pid(s.backendid) AS pid, This value can also be returned by directly calling the pg_stat_get_bgwriter_requested_checkpoints function. + + checkpoint_write_time + bigint + + Total amount of time that has been spent in the portion of + checkpoint processing where files are written to disk, in milliseconds. + This value can also be returned by directly calling the + pg_stat_get_checkpoint_write_time + function. + + + + checkpoint_sync_time + bigint + + Total amount of time that has been spent in the portion of + checkpoint processing where files are synchronized to disk, in + milliseconds. This value can also be returned by directly calling + the pg_stat_get_checkpoint_sync_time + function. + + buffers_checkpoint bigint diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index d2680149f4..0c301b20b4 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -7511,9 +7511,6 @@ LogCheckpointEnd(bool restartpoint) CheckpointStats.ckpt_end_t = GetCurrentTimestamp(); - TimestampDifference(CheckpointStats.ckpt_start_t, - CheckpointStats.ckpt_end_t, - &total_secs, &total_usecs); TimestampDifference(CheckpointStats.ckpt_write_t, CheckpointStats.ckpt_sync_t, @@ -7523,6 +7520,23 @@ LogCheckpointEnd(bool restartpoint) CheckpointStats.ckpt_sync_end_t, &sync_secs, &sync_usecs); + /* Record checkpoint timing summary data. */ + BgWriterStats.m_checkpoint_write_time += + write_secs * 1000 + write_usecs / 1000; + BgWriterStats.m_checkpoint_sync_time += + sync_secs * 1000 + sync_usecs / 1000; + + /* + * All of the published timing statistics are accounted for. Only + * continue if a log message is to be written. + */ + if (!log_checkpoints) + return; + + TimestampDifference(CheckpointStats.ckpt_start_t, + CheckpointStats.ckpt_end_t, + &total_secs, &total_usecs); + /* * Timing values returned from CheckpointStats are in microseconds. * Convert to the second plus microsecond form that TimestampDifference @@ -7971,9 +7985,8 @@ CreateCheckPoint(int flags) if (!RecoveryInProgress()) TruncateSUBTRANS(GetOldestXmin(true, false)); - /* All real work is done, but log before releasing lock. */ - if (log_checkpoints) - LogCheckpointEnd(false); + /* Real work is done, but log and update stats before releasing lock. */ + LogCheckpointEnd(false); TRACE_POSTGRESQL_CHECKPOINT_DONE(CheckpointStats.ckpt_bufs_written, NBuffers, @@ -8237,9 +8250,8 @@ CreateRestartPoint(int flags) if (EnableHotStandby) TruncateSUBTRANS(GetOldestXmin(true, false)); - /* All real work is done, but log before releasing lock. */ - if (log_checkpoints) - LogCheckpointEnd(true); + /* Real work is done, but log and update before releasing lock. */ + LogCheckpointEnd(true); xtime = GetLatestXTime(); ereport((log_checkpoints ? LOG : DEBUG2), diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 9daebdf547..c98785bdf8 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -648,6 +648,8 @@ CREATE VIEW pg_stat_bgwriter AS SELECT pg_stat_get_bgwriter_timed_checkpoints() AS checkpoints_timed, pg_stat_get_bgwriter_requested_checkpoints() AS checkpoints_req, + pg_stat_get_checkpoint_write_time() AS checkpoint_write_time, + pg_stat_get_checkpoint_sync_time() AS checkopint_sync_time, 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, diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c index a7cb036cac..cc141dc980 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c @@ -4455,6 +4455,8 @@ pgstat_recv_bgwriter(PgStat_MsgBgWriter *msg, int len) { globalStats.timed_checkpoints += msg->m_timed_checkpoints; globalStats.requested_checkpoints += msg->m_requested_checkpoints; + globalStats.checkpoint_write_time += msg->m_checkpoint_write_time; + globalStats.checkpoint_sync_time += msg->m_checkpoint_sync_time; globalStats.buf_written_checkpoints += msg->m_buf_written_checkpoints; globalStats.buf_written_clean += msg->m_buf_written_clean; globalStats.maxwritten_clean += msg->m_maxwritten_clean; diff --git a/src/backend/storage/smgr/md.c b/src/backend/storage/smgr/md.c index bfc9f06184..eeb20fdf63 100644 --- a/src/backend/storage/smgr/md.c +++ b/src/backend/storage/smgr/md.c @@ -1094,27 +1094,22 @@ mdsync(void) entry->tag.segno * ((BlockNumber) RELSEG_SIZE), false, EXTENSION_RETURN_NULL); - if (log_checkpoints) - INSTR_TIME_SET_CURRENT(sync_start); - else - INSTR_TIME_SET_ZERO(sync_start); + INSTR_TIME_SET_CURRENT(sync_start); if (seg != NULL && FileSync(seg->mdfd_vfd) >= 0) { - if (log_checkpoints && (!INSTR_TIME_IS_ZERO(sync_start))) - { - INSTR_TIME_SET_CURRENT(sync_end); - sync_diff = sync_end; - INSTR_TIME_SUBTRACT(sync_diff, sync_start); - elapsed = INSTR_TIME_GET_MICROSEC(sync_diff); - if (elapsed > longest) - longest = elapsed; - total_elapsed += elapsed; - processed++; + INSTR_TIME_SET_CURRENT(sync_end); + sync_diff = sync_end; + INSTR_TIME_SUBTRACT(sync_diff, sync_start); + elapsed = INSTR_TIME_GET_MICROSEC(sync_diff); + if (elapsed > longest) + longest = elapsed; + total_elapsed += elapsed; + processed++; + if (log_checkpoints) elog(DEBUG1, "checkpoint sync: number=%d file=%s time=%.3f msec", processed, FilePathName(seg->mdfd_vfd), (double) elapsed / 1000); - } break; /* success; break out of retry loop */ } diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 20ee13db6c..288243a778 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -87,6 +87,8 @@ extern Datum pg_stat_get_db_block_time_write(PG_FUNCTION_ARGS); extern Datum pg_stat_get_bgwriter_timed_checkpoints(PG_FUNCTION_ARGS); extern Datum pg_stat_get_bgwriter_requested_checkpoints(PG_FUNCTION_ARGS); +extern Datum pg_stat_get_checkpoint_write_time(PG_FUNCTION_ARGS); +extern Datum pg_stat_get_checkpoint_sync_time(PG_FUNCTION_ARGS); 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); @@ -1419,6 +1421,18 @@ pg_stat_get_bgwriter_maxwritten_clean(PG_FUNCTION_ARGS) PG_RETURN_INT64(pgstat_fetch_global()->maxwritten_clean); } +Datum +pg_stat_get_checkpoint_write_time(PG_FUNCTION_ARGS) +{ + PG_RETURN_INT64(pgstat_fetch_global()->checkpoint_write_time); +} + +Datum +pg_stat_get_checkpoint_sync_time(PG_FUNCTION_ARGS) +{ + PG_RETURN_INT64(pgstat_fetch_global()->checkpoint_sync_time); +} + Datum pg_stat_get_bgwriter_stat_reset_time(PG_FUNCTION_ARGS) { diff --git a/src/include/catalog/catversion.h b/src/include/catalog/catversion.h index 2c21a958f5..f0c3c66a6d 100644 --- a/src/include/catalog/catversion.h +++ b/src/include/catalog/catversion.h @@ -53,6 +53,6 @@ */ /* yyyymmddN */ -#define CATALOG_VERSION_NO 201204051 +#define CATALOG_VERSION_NO 201204052 #endif diff --git a/src/include/catalog/pg_proc.h b/src/include/catalog/pg_proc.h index 597b9f5fe6..6414b33ed3 100644 --- a/src/include/catalog/pg_proc.h +++ b/src/include/catalog/pg_proc.h @@ -2678,6 +2678,10 @@ 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 = 3075 ( pg_stat_get_bgwriter_stat_reset_time PGNSP PGUID 12 1 0 0 0 f f f f t f s 0 0 1184 "" _null_ _null_ _null_ _null_ pg_stat_get_bgwriter_stat_reset_time _null_ _null_ _null_ )); DESCR("statistics: last reset for the bgwriter"); +DATA(insert OID = 3160 ( pg_stat_get_checkpoint_write_time PGNSP PGUID 12 1 0 0 0 f f f f t f s 0 0 20 "" _null_ _null_ _null_ _null_ pg_stat_get_checkpoint_write_time _null_ _null_ _null_ )); +DESCR("statistics: total amount of checkpoint time spent writing buffers to disk"); +DATA(insert OID = 3161 ( pg_stat_get_checkpoint_sync_time PGNSP PGUID 12 1 0 0 0 f f f f t f s 0 0 20 "" _null_ _null_ _null_ _null_ pg_stat_get_checkpoint_sync_time _null_ _null_ _null_ )); +DESCR("statistics: total amount of checkpoint time spent synchronizing buffers to disk"); DATA(insert OID = 2775 ( pg_stat_get_buf_written_backend PGNSP PGUID 12 1 0 0 0 f 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 0 f f f f t f s 0 0 20 "" _null_ _null_ _null_ _null_ pg_stat_get_buf_fsync_backend _null_ _null_ _null_ )); diff --git a/src/include/pgstat.h b/src/include/pgstat.h index b3618f28d0..35b030a42c 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -366,6 +366,8 @@ typedef struct PgStat_MsgBgWriter PgStat_Counter m_buf_written_backend; PgStat_Counter m_buf_fsync_backend; PgStat_Counter m_buf_alloc; + PgStat_Counter m_checkpoint_write_time; + PgStat_Counter m_checkpoint_sync_time; } PgStat_MsgBgWriter; /* ---------- @@ -612,6 +614,8 @@ typedef struct PgStat_GlobalStats TimestampTz stats_timestamp; /* time of stats file update */ PgStat_Counter timed_checkpoints; PgStat_Counter requested_checkpoints; + PgStat_Counter checkpoint_write_time; /* times in milliseconds */ + PgStat_Counter checkpoint_sync_time; PgStat_Counter buf_written_checkpoints; PgStat_Counter buf_written_clean; PgStat_Counter maxwritten_clean; diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 67ebb951eb..4aedacd3b3 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1295,7 +1295,7 @@ SELECT viewname, definition FROM pg_views WHERE schemaname <> 'information_schem pg_stat_activity | SELECT s.datid, d.datname, s.pid, s.usesysid, u.rolname AS usename, s.application_name, s.client_addr, s.client_hostname, s.client_port, s.backend_start, s.xact_start, s.query_start, s.state_change, s.waiting, s.state, s.query FROM pg_database d, pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, waiting, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, 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_fsync_backend() AS buffers_backend_fsync, pg_stat_get_buf_alloc() AS buffers_alloc, pg_stat_get_bgwriter_stat_reset_time() AS stats_reset; + 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_checkpoint_write_time() AS checkpoint_write_time, pg_stat_get_checkpoint_sync_time() AS checkopint_sync_time, 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_get_bgwriter_stat_reset_time() AS stats_reset; 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, pg_stat_get_db_conflict_all(d.oid) AS conflicts, pg_stat_get_db_temp_files(d.oid) AS temp_files, pg_stat_get_db_temp_bytes(d.oid) AS temp_bytes, pg_stat_get_db_deadlocks(d.oid) AS deadlocks, (pg_stat_get_db_block_time_read(d.oid) / 1000) AS block_read_time, (pg_stat_get_db_block_time_write(d.oid) / 1000) AS block_write_time, pg_stat_get_db_stat_reset_time(d.oid) AS stats_reset FROM pg_database d; pg_stat_database_conflicts | SELECT d.oid AS datid, d.datname, pg_stat_get_db_conflict_tablespace(d.oid) AS confl_tablespace, pg_stat_get_db_conflict_lock(d.oid) AS confl_lock, pg_stat_get_db_conflict_snapshot(d.oid) AS confl_snapshot, pg_stat_get_db_conflict_bufferpin(d.oid) AS confl_bufferpin, pg_stat_get_db_conflict_startup_deadlock(d.oid) AS confl_deadlock FROM pg_database d; pg_stat_replication | SELECT s.pid, s.usesysid, u.rolname AS usename, s.application_name, s.client_addr, s.client_hostname, s.client_port, s.backend_start, w.state, w.sent_location, w.write_location, w.flush_location, w.replay_location, w.sync_priority, w.sync_state FROM pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, waiting, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, client_port), pg_authid u, pg_stat_get_wal_senders() w(pid, state, sent_location, write_location, flush_location, replay_location, sync_priority, sync_state) WHERE ((s.usesysid = u.oid) AND (s.pid = w.pid)); -- 2.40.0