Add local_blk_{read|write}_time I/O timing statistics for local blocks

There was no I/O timing statistics for counting read and write timings
on local blocks, contrary to the counterparts for temp and shared
blocks.  This information is available when track_io_timing is enabled.

The output of EXPLAIN is updated to show this information.  An update of
pg_stat_statements is planned next.

Author: Nazir Bilal Yavuz
Reviewed-by: Robert Haas, Melanie Plageman
Discussion: https://postgr.es/m/CAN55FZ19Ss279mZuqGbuUNxka0iPbLgYuOQXqAKewrjNrp27VA@mail.gmail.com

diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index ae493c86d6c1b323a66f6099ce43d8ed1850a459..5ba6486da199e3f219122cb0d8081ce266bb7af2 100644 (file)
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -183,8 +183,8 @@ ROLLBACK;
       Include information on buffer usage. Specifically, include the number of
       shared blocks hit, read, dirtied, and written, the number of local blocks
       hit, read, dirtied, and written, the number of temp blocks read and
-      written, and the time spent reading and writing data file blocks and
-      temporary file blocks (in milliseconds) if
+      written, and the time spent reading and writing data file blocks, local
+      blocks and temporary file blocks (in milliseconds) if
       <xref linkend="guc-track-io-timing"/> is enabled.  A
       <emphasis>hit</emphasis> means that a read was avoided because the block
       was found already in cache when needed.

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index d6cf948f384d6c7b96018ff674305ef3f7176b94..f1d71bc54e87bacd445c7da79505a8bfb1a486bc 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -3564,11 +3564,14 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
                                usage->temp_blks_written > 0);
        bool        has_shared_timing = (!INSTR_TIME_IS_ZERO(usage->shared_blk_read_time) ||
                                         !INSTR_TIME_IS_ZERO(usage->shared_blk_write_time));
+       bool        has_local_timing = (!INSTR_TIME_IS_ZERO(usage->local_blk_read_time) ||
+                                       !INSTR_TIME_IS_ZERO(usage->local_blk_write_time));
        bool        has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) ||
                                       !INSTR_TIME_IS_ZERO(usage->temp_blk_write_time));
        bool        show_planning = (planning && (has_shared ||
                                                  has_local || has_temp ||
                                                  has_shared_timing ||
+                                                 has_local_timing ||
                                                  has_temp_timing));
 
        if (show_planning)
@@ -3634,7 +3637,7 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
        }
 
        /* As above, show only positive counter values. */
-       if (has_shared_timing || has_temp_timing)
+       if (has_shared_timing || has_local_timing || has_temp_timing)
        {
            ExplainIndentText(es);
            appendStringInfoString(es->str, "I/O Timings:");
@@ -3648,6 +3651,18 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
                if (!INSTR_TIME_IS_ZERO(usage->shared_blk_write_time))
                    appendStringInfo(es->str, " write=%0.3f",
                                     INSTR_TIME_GET_MILLISEC(usage->shared_blk_write_time));
+               if (has_local_timing || has_temp_timing)
+                   appendStringInfoChar(es->str, ',');
+           }
+           if (has_local_timing)
+           {
+               appendStringInfoString(es->str, " local");
+               if (!INSTR_TIME_IS_ZERO(usage->local_blk_read_time))
+                   appendStringInfo(es->str, " read=%0.3f",
+                                    INSTR_TIME_GET_MILLISEC(usage->local_blk_read_time));
+               if (!INSTR_TIME_IS_ZERO(usage->local_blk_write_time))
+                   appendStringInfo(es->str, " write=%0.3f",
+                                    INSTR_TIME_GET_MILLISEC(usage->local_blk_write_time));
                if (has_temp_timing)
                    appendStringInfoChar(es->str, ',');
            }
@@ -3697,6 +3712,12 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
            ExplainPropertyFloat("Shared I/O Write Time", "ms",
                                 INSTR_TIME_GET_MILLISEC(usage->shared_blk_write_time),
                                 3, es);
+           ExplainPropertyFloat("Local I/O Read Time", "ms",
+                                INSTR_TIME_GET_MILLISEC(usage->local_blk_read_time),
+                                3, es);
+           ExplainPropertyFloat("Local I/O Write Time", "ms",
+                                INSTR_TIME_GET_MILLISEC(usage->local_blk_write_time),
+                                3, es);
            ExplainPropertyFloat("Temp I/O Read Time", "ms",
                                 INSTR_TIME_GET_MILLISEC(usage->temp_blk_read_time),
                                 3, es);

diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index ef2a24b7cfb0ed8a523bde7ba9c3e85a4710a4aa..c383f34c0663b87413ed3cbd7fea3c99ce0c9e7e 100644 (file)
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -237,6 +237,8 @@ BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
    dst->temp_blks_written += add->temp_blks_written;
    INSTR_TIME_ADD(dst->shared_blk_read_time, add->shared_blk_read_time);
    INSTR_TIME_ADD(dst->shared_blk_write_time, add->shared_blk_write_time);
+   INSTR_TIME_ADD(dst->local_blk_read_time, add->local_blk_read_time);
+   INSTR_TIME_ADD(dst->local_blk_write_time, add->local_blk_write_time);
    INSTR_TIME_ADD(dst->temp_blk_read_time, add->temp_blk_read_time);
    INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time);
 }
@@ -261,6 +263,10 @@ BufferUsageAccumDiff(BufferUsage *dst,
                          add->shared_blk_read_time, sub->shared_blk_read_time);
    INSTR_TIME_ACCUM_DIFF(dst->shared_blk_write_time,
                          add->shared_blk_write_time, sub->shared_blk_write_time);
+   INSTR_TIME_ACCUM_DIFF(dst->local_blk_read_time,
+                         add->local_blk_read_time, sub->local_blk_read_time);
+   INSTR_TIME_ACCUM_DIFF(dst->local_blk_write_time,
+                         add->local_blk_write_time, sub->local_blk_write_time);
    INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time,
                          add->temp_blk_read_time, sub->temp_blk_read_time);
    INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time,

diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index 297cfc15fb90a9a202c3a6617d115d3211f7b24f..490d5a9ab79a0832e16f591565399ca18ee88d5c 100644 (file)
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -124,12 +124,16 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
            pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
            if (io_object == IOOBJECT_RELATION)
                INSTR_TIME_ADD(pgBufferUsage.shared_blk_write_time, io_time);
+           else if (io_object == IOOBJECT_TEMP_RELATION)
+               INSTR_TIME_ADD(pgBufferUsage.local_blk_write_time, io_time);
        }
        else if (io_op == IOOP_READ)
        {
            pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time));
            if (io_object == IOOBJECT_RELATION)
                INSTR_TIME_ADD(pgBufferUsage.shared_blk_read_time, io_time);
+           else if (io_object == IOOBJECT_TEMP_RELATION)
+               INSTR_TIME_ADD(pgBufferUsage.local_blk_read_time, io_time);
        }
 
        INSTR_TIME_ADD(PendingIOStats.pending_times[io_object][io_context][io_op],

diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 14c3e3f656cb6dd1d2b0d60a18eed653a3dd6869..d5d69941c520561c4f3acf0bc2975e737ac3259e 100644 (file)
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -35,6 +35,8 @@ typedef struct BufferUsage
    int64       temp_blks_written;  /* # of temp blocks written */
    instr_time  shared_blk_read_time;   /* time spent reading shared blocks */
    instr_time  shared_blk_write_time;  /* time spent writing shared blocks */
+   instr_time  local_blk_read_time;    /* time spent reading local blocks */
+   instr_time  local_blk_write_time;   /* time spent writing local blocks */
    instr_time  temp_blk_read_time; /* time spent reading temp blocks */
    instr_time  temp_blk_write_time;    /* time spent writing temp blocks */
 } BufferUsage;

diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index a101886299eccd9606db935ad7b8d91d2f3497d3..809655e16ea72d47a8717f646d51cac662d15306 100644 (file)
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -260,6 +260,8 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
        "Temp Written Blocks": N,    +
        "Shared I/O Read Time": N.N, +
        "Shared I/O Write Time": N.N,+
+       "Local I/O Read Time": N.N,  +
+       "Local I/O Write Time": N.N, +
        "Temp I/O Read Time": N.N,   +
        "Temp I/O Write Time": N.N   +
      },                             +
@@ -276,6 +278,8 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
        "Temp Written Blocks": N,    +
        "Shared I/O Read Time": N.N, +
        "Shared I/O Write Time": N.N,+
+       "Local I/O Read Time": N.N,  +
+       "Local I/O Write Time": N.N, +
        "Temp I/O Read Time": N.N,   +
        "Temp I/O Write Time": N.N   +
      },                             +