From b736aef2ec57b520ebadb70cceac0fed3168a5df Mon Sep 17 00:00:00 2001
From: Robert Haas <rhaas@postgresql.org>
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 ed8aeb20c60..423f9b1a9a0 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 <function>pg_stat_get_bgwriter_requested_checkpoints</function> function.</entry>
</row>
+ <row>
+ <entry>checkpoint_write_time</entry>
+ <entry><type>bigint</type></entry>
+ <entry>
+ 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
+ <function>pg_stat_get_checkpoint_write_time</function>
+ function.
+ </entry>
+ </row>
+ <row>
+ <entry>checkpoint_sync_time</entry>
+ <entry><type>bigint</type></entry>
+ <entry>
+ 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 <function>pg_stat_get_checkpoint_sync_time</function>
+ function.
+ </entry>
+ </row>
<row>
<entry>buffers_checkpoint</entry>
<entry><type>bigint</type></entry>
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index d2680149f49..0c301b20b46 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 9daebdf5478..c98785bdf8b 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 a7cb036cac0..cc141dc980c 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 bfc9f06184a..eeb20fdf633 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 20ee13db6cf..288243a7787 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 2c21a958f55..f0c3c66a6df 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 597b9f5fe6a..6414b33ed3d 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 b3618f28d01..35b030a42c8 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 67ebb951ebf..4aedacd3b3f 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));
--
GitLab