Skip to content

Commit 295c36c

Browse files
michaelpqmichaelpq
committed
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
1 parent 13d0072 commit 295c36c

File tree

6 files changed

+40
-3
lines changed

6 files changed

+40
-3
lines changed

‎doc/src/sgml/ref/explain.sgml

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -183,8 +183,8 @@ ROLLBACK;
183183
Include information on buffer usage. Specifically, include the number of
184184
shared blocks hit, read, dirtied, and written, the number of local blocks
185185
hit, read, dirtied, and written, the number of temp blocks read and
186-
written, and the time spent reading and writing data file blocks and
187-
temporary file blocks (in milliseconds) if
186+
written, and the time spent reading and writing data file blocks, local
187+
blocks and temporary file blocks (in milliseconds) if
188188
<xref linkend="guc-track-io-timing"/> is enabled. A
189189
<emphasis>hit</emphasis> means that a read was avoided because the block
190190
was found already in cache when needed.

‎src/backend/commands/explain.c

Lines changed: 22 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3564,11 +3564,14 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
35643564
usage->temp_blks_written > 0);
35653565
bool has_shared_timing = (!INSTR_TIME_IS_ZERO(usage->shared_blk_read_time) ||
35663566
!INSTR_TIME_IS_ZERO(usage->shared_blk_write_time));
3567+
bool has_local_timing = (!INSTR_TIME_IS_ZERO(usage->local_blk_read_time) ||
3568+
!INSTR_TIME_IS_ZERO(usage->local_blk_write_time));
35673569
bool has_temp_timing = (!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time) ||
35683570
!INSTR_TIME_IS_ZERO(usage->temp_blk_write_time));
35693571
bool show_planning = (planning && (has_shared ||
35703572
has_local || has_temp ||
35713573
has_shared_timing ||
3574+
has_local_timing ||
35723575
has_temp_timing));
35733576

35743577
if (show_planning)
@@ -3634,7 +3637,7 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
36343637
}
36353638

36363639
/* As above, show only positive counter values. */
3637-
if (has_shared_timing || has_temp_timing)
3640+
if (has_shared_timing || has_local_timing || has_temp_timing)
36383641
{
36393642
ExplainIndentText(es);
36403643
appendStringInfoString(es->str, "I/O Timings:");
@@ -3648,6 +3651,18 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
36483651
if (!INSTR_TIME_IS_ZERO(usage->shared_blk_write_time))
36493652
appendStringInfo(es->str, " write=%0.3f",
36503653
INSTR_TIME_GET_MILLISEC(usage->shared_blk_write_time));
3654+
if (has_local_timing || has_temp_timing)
3655+
appendStringInfoChar(es->str, ',');
3656+
}
3657+
if (has_local_timing)
3658+
{
3659+
appendStringInfoString(es->str, " local");
3660+
if (!INSTR_TIME_IS_ZERO(usage->local_blk_read_time))
3661+
appendStringInfo(es->str, " read=%0.3f",
3662+
INSTR_TIME_GET_MILLISEC(usage->local_blk_read_time));
3663+
if (!INSTR_TIME_IS_ZERO(usage->local_blk_write_time))
3664+
appendStringInfo(es->str, " write=%0.3f",
3665+
INSTR_TIME_GET_MILLISEC(usage->local_blk_write_time));
36513666
if (has_temp_timing)
36523667
appendStringInfoChar(es->str, ',');
36533668
}
@@ -3697,6 +3712,12 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
36973712
ExplainPropertyFloat("Shared I/O Write Time", "ms",
36983713
INSTR_TIME_GET_MILLISEC(usage->shared_blk_write_time),
36993714
3, es);
3715+
ExplainPropertyFloat("Local I/O Read Time", "ms",
3716+
INSTR_TIME_GET_MILLISEC(usage->local_blk_read_time),
3717+
3, es);
3718+
ExplainPropertyFloat("Local I/O Write Time", "ms",
3719+
INSTR_TIME_GET_MILLISEC(usage->local_blk_write_time),
3720+
3, es);
37003721
ExplainPropertyFloat("Temp I/O Read Time", "ms",
37013722
INSTR_TIME_GET_MILLISEC(usage->temp_blk_read_time),
37023723
3, es);

‎src/backend/executor/instrument.c

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -237,6 +237,8 @@ BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
237237
dst->temp_blks_written += add->temp_blks_written;
238238
INSTR_TIME_ADD(dst->shared_blk_read_time, add->shared_blk_read_time);
239239
INSTR_TIME_ADD(dst->shared_blk_write_time, add->shared_blk_write_time);
240+
INSTR_TIME_ADD(dst->local_blk_read_time, add->local_blk_read_time);
241+
INSTR_TIME_ADD(dst->local_blk_write_time, add->local_blk_write_time);
240242
INSTR_TIME_ADD(dst->temp_blk_read_time, add->temp_blk_read_time);
241243
INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time);
242244
}
@@ -261,6 +263,10 @@ BufferUsageAccumDiff(BufferUsage *dst,
261263
add->shared_blk_read_time, sub->shared_blk_read_time);
262264
INSTR_TIME_ACCUM_DIFF(dst->shared_blk_write_time,
263265
add->shared_blk_write_time, sub->shared_blk_write_time);
266+
INSTR_TIME_ACCUM_DIFF(dst->local_blk_read_time,
267+
add->local_blk_read_time, sub->local_blk_read_time);
268+
INSTR_TIME_ACCUM_DIFF(dst->local_blk_write_time,
269+
add->local_blk_write_time, sub->local_blk_write_time);
264270
INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time,
265271
add->temp_blk_read_time, sub->temp_blk_read_time);
266272
INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time,

‎src/backend/utils/activity/pgstat_io.c

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -124,12 +124,16 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
124124
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
125125
if (io_object == IOOBJECT_RELATION)
126126
INSTR_TIME_ADD(pgBufferUsage.shared_blk_write_time, io_time);
127+
else if (io_object == IOOBJECT_TEMP_RELATION)
128+
INSTR_TIME_ADD(pgBufferUsage.local_blk_write_time, io_time);
127129
}
128130
else if (io_op == IOOP_READ)
129131
{
130132
pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time));
131133
if (io_object == IOOBJECT_RELATION)
132134
INSTR_TIME_ADD(pgBufferUsage.shared_blk_read_time, io_time);
135+
else if (io_object == IOOBJECT_TEMP_RELATION)
136+
INSTR_TIME_ADD(pgBufferUsage.local_blk_read_time, io_time);
133137
}
134138

135139
INSTR_TIME_ADD(PendingIOStats.pending_times[io_object][io_context][io_op],

‎src/include/executor/instrument.h

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,8 @@ typedef struct BufferUsage
3535
int64 temp_blks_written; /* # of temp blocks written */
3636
instr_time shared_blk_read_time; /* time spent reading shared blocks */
3737
instr_time shared_blk_write_time; /* time spent writing shared blocks */
38+
instr_time local_blk_read_time; /* time spent reading local blocks */
39+
instr_time local_blk_write_time; /* time spent writing local blocks */
3840
instr_time temp_blk_read_time; /* time spent reading temp blocks */
3941
instr_time temp_blk_write_time; /* time spent writing temp blocks */
4042
} BufferUsage;

‎src/test/regress/expected/explain.out

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -260,6 +260,8 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
260260
"Temp Written Blocks": N, +
261261
"Shared I/O Read Time": N.N, +
262262
"Shared I/O Write Time": N.N,+
263+
"Local I/O Read Time": N.N, +
264+
"Local I/O Write Time": N.N, +
263265
"Temp I/O Read Time": N.N, +
264266
"Temp I/O Write Time": N.N +
265267
}, +
@@ -276,6 +278,8 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
276278
"Temp Written Blocks": N, +
277279
"Shared I/O Read Time": N.N, +
278280
"Shared I/O Write Time": N.N,+
281+
"Local I/O Read Time": N.N, +
282+
"Local I/O Write Time": N.N, +
279283
"Temp I/O Read Time": N.N, +
280284
"Temp I/O Write Time": N.N +
281285
}, +

0 commit comments

Comments
 (0)