New GUC, track_iotiming, to track I/O timings.

Currently, the only way to see the numbers this gathers is via
EXPLAIN (ANALYZE, BUFFERS), but the plan is to add visibility through
the stats collector and pg_stat_statements in subsequent patches.

Ants Aasma, reviewed by Greg Smith, with some further changes by me.

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 3e178759a29e11b3346b7796b32f853aae9b4323..9baaa3fb36acd9c6a4ff50a7074a5b7491034dca 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -4284,6 +4284,21 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-track-iotiming" xreflabel="track_iotiming">
+      <term><varname>track_iotiming</varname> (<type>boolean</type>)</term>
+      <indexterm>
+       <primary><varname>track_iotiming</> configuration parameter</primary>
+      </indexterm>
+      <listitem>
+       <para>
+        Enables timing of database I/O calls.  This parameter is off by
+        default, because it will repeatedly query the operating system for
+        the current time, which may cause significant overhead on some
+        platforms.  Only superusers can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-track-functions" xreflabel="track_functions">
       <term><varname>track_functions</varname> (<type>enum</type>)</term>
       <indexterm>

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index a14cae144205a86956289e2f74c78350a8960553..81d63f87f10a3cedd335af7f9889d5157ae806fb 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1236,6 +1236,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
                                                                         usage->local_blks_written > 0);
                        bool            has_temp = (usage->temp_blks_read > 0 ||
                                                                        usage->temp_blks_written > 0);
+                       bool            has_timing = (!INSTR_TIME_IS_ZERO(usage->time_read) ||
+                                                                         !INSTR_TIME_IS_ZERO(usage->time_write));
 
                        /* Show only positive counter values. */
                        if (has_shared || has_local || has_temp)
@@ -1291,6 +1293,20 @@ ExplainNode(PlanState *planstate, List *ancestors,
                                }
                                appendStringInfoChar(es->str, '\n');
                        }
+
+                       /* As above, show only positive counter values. */
+                       if (has_timing)
+                       {
+                               appendStringInfoSpaces(es->str, es->indent * 2);
+                               appendStringInfoString(es->str, "I/O Timings:");
+                               if (!INSTR_TIME_IS_ZERO(usage->time_read))
+                                       appendStringInfo(es->str, " read=%0.2f",
+                                                                INSTR_TIME_GET_MILLISEC(usage->time_read));
+                               if (!INSTR_TIME_IS_ZERO(usage->time_write))
+                                       appendStringInfo(es->str, " write=%0.2f",
+                                                                INSTR_TIME_GET_MILLISEC(usage->time_write));
+                               appendStringInfoChar(es->str, '\n');
+                       }
                }
                else
                {
@@ -1304,6 +1320,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
                        ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es);
                        ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es);
                        ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es);
+                       ExplainPropertyFloat("I/O Read Time", INSTR_TIME_GET_MILLISEC(usage->time_read), 3, es);
+                       ExplainPropertyFloat("I/O Write Time", INSTR_TIME_GET_MILLISEC(usage->time_write), 3, es);
                }
        }
 

diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index 6e9f450d6886524ec23972cfdfee6e63b909dfeb..92e56d13ae6b501014e54a3112152ce25bdd7e57 100644 (file)
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -145,4 +145,6 @@ BufferUsageAccumDiff(BufferUsage *dst,
        dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
        dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
        dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
+       INSTR_TIME_ACCUM_DIFF(dst->time_read, add->time_read, sub->time_read);
+       INSTR_TIME_ACCUM_DIFF(dst->time_write, add->time_write, sub->time_write);
 }

diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index 3924a51c0c6d31e1b7612ee3cf78ca04639e58aa..4de6a7212ccce2482006b1340ad1de21882fe677 100644 (file)
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -67,6 +67,7 @@
 bool           zero_damaged_pages = false;
 int                    bgwriter_lru_maxpages = 100;
 double         bgwriter_lru_multiplier = 2.0;
+bool           track_iotiming = false;
 
 /*
  * How many buffers PrefetchBuffer callers should try to stay ahead of their
@@ -437,8 +438,21 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum,
                        MemSet((char *) bufBlock, 0, BLCKSZ);
                else
                {
+                       instr_time      io_start,
+                                               io_time;
+
+                       if (track_iotiming)
+                               INSTR_TIME_SET_CURRENT(io_start);
+
                        smgrread(smgr, forkNum, blockNum, (char *) bufBlock);
 
+                       if (track_iotiming)
+                       {
+                               INSTR_TIME_SET_CURRENT(io_time);
+                               INSTR_TIME_SUBTRACT(io_time, io_start);
+                               INSTR_TIME_ADD(pgBufferUsage.time_read, io_time);
+                       }
+
                        /* check for garbage data */
                        if (!PageHeaderIsValid((PageHeader) bufBlock))
                        {
@@ -1874,6 +1888,7 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln)
 {
        XLogRecPtr      recptr;
        ErrorContextCallback errcontext;
+       instr_time io_start, io_end;
 
        /*
         * Acquire the buffer's io_in_progress lock.  If StartBufferIO returns
@@ -1921,12 +1936,21 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln)
        buf->flags &= ~BM_JUST_DIRTIED;
        UnlockBufHdr(buf);
 
+       if (track_iotiming)
+               INSTR_TIME_SET_CURRENT(io_start);
+
        smgrwrite(reln,
                          buf->tag.forkNum,
                          buf->tag.blockNum,
                          (char *) BufHdrGetBlock(buf),
                          false);
 
+       if (track_iotiming)
+       {
+               INSTR_TIME_SET_CURRENT(io_end);
+               INSTR_TIME_ACCUM_DIFF(pgBufferUsage.time_write, io_end, io_start);
+       }
+
        pgBufferUsage.shared_blks_written++;
 
        /*

diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 3d2fe3ebc87c864155bcd69cd51856b4e42ddda7..8ea391a8e6cc1154751d46eda18231ab4230370f 100644 (file)
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -1018,6 +1018,15 @@ static struct config_bool ConfigureNamesBool[] =
                true,
                NULL, NULL, NULL
        },
+       {
+               {"track_iotiming", PGC_SUSET, STATS_COLLECTOR,
+                       gettext_noop("Collects timing information for database IO activity."),
+                       NULL
+               },
+               &track_iotiming,
+               false,
+               NULL, NULL, NULL
+       },
 
        {
                {"update_process_title", PGC_SUSET, STATS_COLLECTOR,

diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 96da086b0f4c8f8e6fcd9a934021bd7a170105bd..cbae3bfb2286fe8feff8a658273857e0f82c01a8 100644 (file)
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -424,6 +424,7 @@
 
 #track_activities = on
 #track_counts = on
+#track_iotiming = off
 #track_functions = none                        # none, pl, all
 #track_activity_query_size = 1024      # (change requires restart)
 #update_process_title = on

diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 066f684f330ca942958d94ab59ad4bb4aecbf604..d29ab9b9f341a7c1dabbe007f0584d92cb5229ad 100644 (file)
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -28,6 +28,8 @@ typedef struct BufferUsage
        long            local_blks_written;             /* # of local disk blocks written */
        long            temp_blks_read; /* # of temp blocks read */
        long            temp_blks_written;              /* # of temp blocks written */
+       instr_time      time_read;                              /* time spent reading */
+       instr_time      time_write;                             /* time spent writing */
 } BufferUsage;
 
 /* Flag bits included in InstrAlloc's instrument_options bitmask */

diff --git a/src/include/storage/bufmgr.h b/src/include/storage/bufmgr.h
index de1bbd01d839db3cdbf9dab2b466a67225d4cc8c..d72bad9f56143b36650a80fc1e16fcecd3d63fbd 100644 (file)
--- a/src/include/storage/bufmgr.h
+++ b/src/include/storage/bufmgr.h
@@ -48,6 +48,7 @@ extern PGDLLIMPORT int NBuffers;
 extern bool zero_damaged_pages;
 extern int     bgwriter_lru_maxpages;
 extern double bgwriter_lru_multiplier;
+extern bool track_iotiming;
 extern int     target_prefetch_pages;
 
 /* in buf_init.c */