open-dsi
/
postgres
mirror of https://github.com/postgres/postgres
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
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
pull/145/head
Michael Paquier 2 years ago
parent 13d00729d4
commit 295c36c0c1
6 changed files with 40 additions and 3 deletions
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Show Stats Download Patch File Download Diff File
  1. 4
      doc/src/sgml/ref/explain.sgml
  2. 23
      src/backend/commands/explain.c
  3. 6
      src/backend/executor/instrument.c
  4. 4
      src/backend/utils/activity/pgstat_io.c
  5. 2
      src/include/executor/instrument.h
  6. 4
      src/test/regress/expected/explain.out

4
doc/src/sgml/ref/explain.sgml
Unescape 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
Unescape 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
Unescape 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
Unescape 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
Unescape 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
Unescape 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 +
}, +

Write Preview
Loading…
Cancel
Save