Skip to content

Commit

Permalink
Add local_blk_{read|write}_time I/O timing statistics for local blocks
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
@michaelpq
michaelpq committed Oct 19, 2023
1 parent 13d0072 commit 295c36c
Show file tree
Hide file tree
Showing 6 changed files with 40 additions and 3 deletions.
4 changes: 2 additions & 2 deletions doc/src/sgml/ref/explain.sgml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
23 changes: 22 additions & 1 deletion src/backend/commands/explain.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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:");
Expand All @@ -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, ',');
}
Expand Down Expand Up @@ -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);
Expand Down
6 changes: 6 additions & 0 deletions src/backend/executor/instrument.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand All @@ -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,
Expand Down
4 changes: 4 additions & 0 deletions src/backend/utils/activity/pgstat_io.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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],
Expand Down
2 changes: 2 additions & 0 deletions src/include/executor/instrument.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
4 changes: 4 additions & 0 deletions src/test/regress/expected/explain.out
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 +
}, +
Expand All @@ -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 +
}, +
Expand Down

0 comments on commit 295c36c

Please sign in to comment.