rdelaage
/
postgresql
mirror of https://git.postgresql.org/git/postgresql.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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
This commit is contained in:
Michael Paquier 2023-10-19 13:39:38 +09:00
parent 13d00729d4
commit 295c36c0c1
6 changed files with 40 additions and 3 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
doc/src/sgml/ref/explain.sgml
View File

@ -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.

23
src/backend/commands/explain.c
View File

@ -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);

6
src/backend/executor/instrument.c
View File

@ -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,

4
src/backend/utils/activity/pgstat_io.c
View File

@ -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],

2
src/include/executor/instrument.h
View File

@ -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;

4
src/test/regress/expected/explain.out
View File

@ -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 +
}, +