]> granicus.if.org Git - postgresql/commitdiff
Publish checkpoint timing information to pg_stat_bgwriter.
authorRobert Haas <rhaas@postgresql.org>
Thu, 5 Apr 2012 18:03:21 +0000 (14:03 -0400)
committerRobert Haas <rhaas@postgresql.org>
Thu, 5 Apr 2012 18:04:37 +0000 (14:04 -0400)
Greg Smith, Peter Geoghegan, and Robert Haas

doc/src/sgml/monitoring.sgml
src/backend/access/transam/xlog.c
src/backend/catalog/system_views.sql
src/backend/postmaster/pgstat.c
src/backend/storage/smgr/md.c
src/backend/utils/adt/pgstatfuncs.c
src/include/catalog/catversion.h
src/include/catalog/pg_proc.h
src/include/pgstat.h
src/test/regress/expected/rules.out

index ed8aeb20c6094e842dba559c09a2d5f4e8b4677e..423f9b1a9a0697ba7af01b0e5a7beec0647a2653 100644 (file)
@@ -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>
index d2680149f49b0273e1eb74d206da27c089b31307..0c301b20b464b270ba9bc438c5e66639effe0e89 100644 (file)
@@ -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),
index 9daebdf54784fe70dac350e0fb92bc0ffaa93161..c98785bdf8b273c5b83d6820ceef0f244f1855f9 100644 (file)
@@ -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,
index a7cb036cac01f61e9679875fd39c027d928d028d..cc141dc980c599f3a9a9b7e35fc7cac8ea9098d2 100644 (file)
@@ -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;
index bfc9f06184a8c6262677e504d13ac7970db7f9e1..eeb20fdf633f4cf62f3e2a7c0ff9ffc8c5101e11 100644 (file)
@@ -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 */
                                }
index 20ee13db6cf545623570bc56d2b1976edaccae23..288243a7787ef994e4dceaf4e10da23709767490 100644 (file)
@@ -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)
 {
index 2c21a958f55cfbf1548aae9d3df916d53f729986..f0c3c66a6df9b4f0e6f84e2726bc3dda7ec5ae09 100644 (file)
@@ -53,6 +53,6 @@
  */
 
 /*                                                     yyyymmddN */
-#define CATALOG_VERSION_NO     201204051
+#define CATALOG_VERSION_NO     201204052
 
 #endif
index 597b9f5fe6a476bf1633fdafceed6617f0b58e5e..6414b33ed3d3bcf80bbb9b3f2d7ed6e30f558a00 100644 (file)
@@ -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_ ));
index b3618f28d01b8a08c82cf2d91d139e5a39f0c646..35b030a42c8ed084247529f44c2ecc3e45fc13fb 100644 (file)
@@ -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;
index 67ebb951ebf363f53a1b440114ea8755f0e30c08..4aedacd3b3f7c5d40f919b0c736658970773d66f 100644 (file)
@@ -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));