From 13d00729d422c84b1764c24251abcc785ea4adb1 Mon Sep 17 00:00:00 2001 From: Michael Paquier Date: Thu, 19 Oct 2023 11:26:40 +0900 Subject: [PATCH] Rename I/O timing statistics columns to shared_blk_{read|write}_time These two counters, defined in BufferUsage to track respectively the time spent while reading and writing blocks have historically only tracked data related to shared buffers, when track_io_timing is enabled. An upcoming patch to add specific counters for local buffers will take advantage of this rename as it has come up that no data is currently tracked for local buffers, and tracking local and shared buffers using the same fields would be inconsistent with the treatment done for temp buffers. Renaming the existing fields clarifies what the block type of each stats field is. pg_stat_statement is updated to reflect the rename. No extension version bump is required as 5a3423ad8ee17 has done one, affecting v17~. Author: Nazir Bilal Yavuz Reviewed-by: Robert Haas, Melanie Plageman Discussion: https://postgr.es/m/CAN55FZ19Ss279mZuqGbuUNxka0iPbLgYuOQXqAKewrjNrp27VA@mail.gmail.com --- .../expected/oldextversions.out | 4 +- .../pg_stat_statements--1.10--1.11.sql | 4 +- .../pg_stat_statements/pg_stat_statements.c | 14 ++- doc/src/sgml/pgstatstatements.sgml | 8 +- src/backend/commands/explain.c | 29 ++--- src/backend/executor/instrument.c | 12 +- src/backend/utils/activity/pgstat_io.c | 4 +- src/include/executor/instrument.h | 4 +- src/test/regress/expected/explain.out | 108 +++++++++--------- 9 files changed, 95 insertions(+), 92 deletions(-) diff --git a/contrib/pg_stat_statements/expected/oldextversions.out b/contrib/pg_stat_statements/expected/oldextversions.out index 64982aad60..c2e0140a47 100644 --- a/contrib/pg_stat_statements/expected/oldextversions.out +++ b/contrib/pg_stat_statements/expected/oldextversions.out @@ -284,8 +284,8 @@ AlTER EXTENSION pg_stat_statements UPDATE TO '1.11'; local_blks_written | bigint | | | temp_blks_read | bigint | | | temp_blks_written | bigint | | | - blk_read_time | double precision | | | - blk_write_time | double precision | | | + shared_blk_read_time | double precision | | | + shared_blk_write_time | double precision | | | temp_blk_read_time | double precision | | | temp_blk_write_time | double precision | | | wal_records | bigint | | | diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql b/contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql index 20bae80458..448ef3682f 100644 --- a/contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql +++ b/contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql @@ -41,8 +41,8 @@ CREATE FUNCTION pg_stat_statements(IN showtext boolean, OUT local_blks_written int8, OUT temp_blks_read int8, OUT temp_blks_written int8, - OUT blk_read_time float8, - OUT blk_write_time float8, + OUT shared_blk_read_time float8, + OUT shared_blk_write_time float8, OUT temp_blk_read_time float8, OUT temp_blk_write_time float8, OUT wal_records int8, diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index a46f2db352..11e6f25b75 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -180,8 +180,10 @@ typedef struct Counters int64 local_blks_written; /* # of local disk blocks written */ int64 temp_blks_read; /* # of temp blocks read */ int64 temp_blks_written; /* # of temp blocks written */ - double blk_read_time; /* time spent reading blocks, in msec */ - double blk_write_time; /* time spent writing blocks, in msec */ + double shared_blk_read_time; /* time spent reading shared blocks, + * in msec */ + double shared_blk_write_time; /* time spent writing shared blocks, + * in msec */ double temp_blk_read_time; /* time spent reading temp blocks, in msec */ double temp_blk_write_time; /* time spent writing temp blocks, in * msec */ @@ -1391,8 +1393,8 @@ pgss_store(const char *query, uint64 queryId, e->counters.local_blks_written += bufusage->local_blks_written; e->counters.temp_blks_read += bufusage->temp_blks_read; e->counters.temp_blks_written += bufusage->temp_blks_written; - e->counters.blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_read_time); - e->counters.blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_write_time); + e->counters.shared_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->shared_blk_read_time); + e->counters.shared_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->shared_blk_write_time); e->counters.temp_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->temp_blk_read_time); e->counters.temp_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->temp_blk_write_time); e->counters.usage += USAGE_EXEC(total_time); @@ -1823,8 +1825,8 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, values[i++] = Int64GetDatumFast(tmp.temp_blks_written); if (api_version >= PGSS_V1_1) { - values[i++] = Float8GetDatumFast(tmp.blk_read_time); - values[i++] = Float8GetDatumFast(tmp.blk_write_time); + values[i++] = Float8GetDatumFast(tmp.shared_blk_read_time); + values[i++] = Float8GetDatumFast(tmp.shared_blk_write_time); } if (api_version >= PGSS_V1_10) { diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml index 7e7c5c9ff8..2c4e3655ff 100644 --- a/doc/src/sgml/pgstatstatements.sgml +++ b/doc/src/sgml/pgstatstatements.sgml @@ -335,20 +335,20 @@ - blk_read_time double precision + shared_blk_read_time double precision - Total time the statement spent reading data file blocks, in milliseconds + Total time the statement spent reading shared blocks, in milliseconds (if is enabled, otherwise zero) - blk_write_time double precision + shared_blk_write_time double precision - Total time the statement spent writing data file blocks, in milliseconds + Total time the statement spent writing shared blocks, in milliseconds (if is enabled, otherwise zero) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 13217807ee..d6cf948f38 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -3562,12 +3562,13 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning) usage->local_blks_written > 0); bool has_temp = (usage->temp_blks_read > 0 || usage->temp_blks_written > 0); - bool has_timing = (!INSTR_TIME_IS_ZERO(usage->blk_read_time) || - !INSTR_TIME_IS_ZERO(usage->blk_write_time)); + bool has_shared_timing = (!INSTR_TIME_IS_ZERO(usage->shared_blk_read_time) || + !INSTR_TIME_IS_ZERO(usage->shared_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_timing || + has_local || has_temp || + has_shared_timing || has_temp_timing)); if (show_planning) @@ -3633,20 +3634,20 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning) } /* As above, show only positive counter values. */ - if (has_timing || has_temp_timing) + if (has_shared_timing || has_temp_timing) { ExplainIndentText(es); appendStringInfoString(es->str, "I/O Timings:"); - if (has_timing) + if (has_shared_timing) { - appendStringInfoString(es->str, " shared/local"); - if (!INSTR_TIME_IS_ZERO(usage->blk_read_time)) + appendStringInfoString(es->str, " shared"); + if (!INSTR_TIME_IS_ZERO(usage->shared_blk_read_time)) appendStringInfo(es->str, " read=%0.3f", - INSTR_TIME_GET_MILLISEC(usage->blk_read_time)); - if (!INSTR_TIME_IS_ZERO(usage->blk_write_time)) + INSTR_TIME_GET_MILLISEC(usage->shared_blk_read_time)); + if (!INSTR_TIME_IS_ZERO(usage->shared_blk_write_time)) appendStringInfo(es->str, " write=%0.3f", - INSTR_TIME_GET_MILLISEC(usage->blk_write_time)); + INSTR_TIME_GET_MILLISEC(usage->shared_blk_write_time)); if (has_temp_timing) appendStringInfoChar(es->str, ','); } @@ -3690,11 +3691,11 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning) usage->temp_blks_written, es); if (track_io_timing) { - ExplainPropertyFloat("I/O Read Time", "ms", - INSTR_TIME_GET_MILLISEC(usage->blk_read_time), + ExplainPropertyFloat("Shared I/O Read Time", "ms", + INSTR_TIME_GET_MILLISEC(usage->shared_blk_read_time), 3, es); - ExplainPropertyFloat("I/O Write Time", "ms", - INSTR_TIME_GET_MILLISEC(usage->blk_write_time), + ExplainPropertyFloat("Shared I/O Write Time", "ms", + INSTR_TIME_GET_MILLISEC(usage->shared_blk_write_time), 3, es); ExplainPropertyFloat("Temp I/O Read Time", "ms", INSTR_TIME_GET_MILLISEC(usage->temp_blk_read_time), diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index ee78a5749d..ef2a24b7cf 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -235,8 +235,8 @@ BufferUsageAdd(BufferUsage *dst, const BufferUsage *add) dst->local_blks_written += add->local_blks_written; dst->temp_blks_read += add->temp_blks_read; dst->temp_blks_written += add->temp_blks_written; - INSTR_TIME_ADD(dst->blk_read_time, add->blk_read_time); - INSTR_TIME_ADD(dst->blk_write_time, add->blk_write_time); + 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->temp_blk_read_time, add->temp_blk_read_time); INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time); } @@ -257,10 +257,10 @@ BufferUsageAccumDiff(BufferUsage *dst, dst->local_blks_written += add->local_blks_written - sub->local_blks_written; dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read; dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written; - INSTR_TIME_ACCUM_DIFF(dst->blk_read_time, - add->blk_read_time, sub->blk_read_time); - INSTR_TIME_ACCUM_DIFF(dst->blk_write_time, - add->blk_write_time, sub->blk_write_time); + INSTR_TIME_ACCUM_DIFF(dst->shared_blk_read_time, + 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->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 8ec8670199..297cfc15fb 100644 --- a/src/backend/utils/activity/pgstat_io.c +++ b/src/backend/utils/activity/pgstat_io.c @@ -123,13 +123,13 @@ 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.blk_write_time, io_time); + INSTR_TIME_ADD(pgBufferUsage.shared_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.blk_read_time, io_time); + INSTR_TIME_ADD(pgBufferUsage.shared_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 87e5e2183b..14c3e3f656 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -33,8 +33,8 @@ typedef struct BufferUsage int64 local_blks_written; /* # of local disk blocks written */ int64 temp_blks_read; /* # of temp blocks read */ int64 temp_blks_written; /* # of temp blocks written */ - instr_time blk_read_time; /* time spent reading blocks */ - instr_time blk_write_time; /* time spent writing blocks */ + instr_time shared_blk_read_time; /* time spent reading shared blocks */ + instr_time shared_blk_write_time; /* time spent writing shared 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 1aca77491b..a101886299 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -230,60 +230,60 @@ select explain_filter('explain (buffers, format json) select * from int8_tbl i8' -- but always set in JSON format, so check them only in this case. set track_io_timing = on; select explain_filter('explain (analyze, buffers, format json) select * from int8_tbl i8'); - explain_filter ------------------------------------- - [ + - { + - "Plan": { + - "Node Type": "Seq Scan", + - "Parallel Aware": false, + - "Async Capable": false, + - "Relation Name": "int8_tbl",+ - "Alias": "i8", + - "Startup Cost": N.N, + - "Total Cost": N.N, + - "Plan Rows": N, + - "Plan Width": N, + - "Actual Startup Time": N.N, + - "Actual Total Time": N.N, + - "Actual Rows": N, + - "Actual Loops": N, + - "Shared Hit Blocks": N, + - "Shared Read Blocks": N, + - "Shared Dirtied Blocks": N, + - "Shared Written Blocks": N, + - "Local Hit Blocks": N, + - "Local Read Blocks": N, + - "Local Dirtied Blocks": N, + - "Local Written Blocks": N, + - "Temp Read Blocks": N, + - "Temp Written Blocks": N, + - "I/O Read Time": N.N, + - "I/O Write Time": N.N, + - "Temp I/O Read Time": N.N, + - "Temp I/O Write Time": N.N + - }, + - "Planning": { + - "Shared Hit Blocks": N, + - "Shared Read Blocks": N, + - "Shared Dirtied Blocks": N, + - "Shared Written Blocks": N, + - "Local Hit Blocks": N, + - "Local Read Blocks": N, + - "Local Dirtied Blocks": N, + - "Local Written Blocks": N, + - "Temp Read Blocks": N, + - "Temp Written Blocks": N, + - "I/O Read Time": N.N, + - "I/O Write Time": N.N, + - "Temp I/O Read Time": N.N, + - "Temp I/O Write Time": N.N + - }, + - "Planning Time": N.N, + - "Triggers": [ + - ], + - "Execution Time": N.N + - } + + explain_filter +------------------------------------- + [ + + { + + "Plan": { + + "Node Type": "Seq Scan", + + "Parallel Aware": false, + + "Async Capable": false, + + "Relation Name": "int8_tbl", + + "Alias": "i8", + + "Startup Cost": N.N, + + "Total Cost": N.N, + + "Plan Rows": N, + + "Plan Width": N, + + "Actual Startup Time": N.N, + + "Actual Total Time": N.N, + + "Actual Rows": N, + + "Actual Loops": N, + + "Shared Hit Blocks": N, + + "Shared Read Blocks": N, + + "Shared Dirtied Blocks": N, + + "Shared Written Blocks": N, + + "Local Hit Blocks": N, + + "Local Read Blocks": N, + + "Local Dirtied Blocks": N, + + "Local Written Blocks": N, + + "Temp Read Blocks": N, + + "Temp Written Blocks": N, + + "Shared I/O Read Time": N.N, + + "Shared I/O Write Time": N.N,+ + "Temp I/O Read Time": N.N, + + "Temp I/O Write Time": N.N + + }, + + "Planning": { + + "Shared Hit Blocks": N, + + "Shared Read Blocks": N, + + "Shared Dirtied Blocks": N, + + "Shared Written Blocks": N, + + "Local Hit Blocks": N, + + "Local Read Blocks": N, + + "Local Dirtied Blocks": N, + + "Local Written Blocks": N, + + "Temp Read Blocks": N, + + "Temp Written Blocks": N, + + "Shared I/O Read Time": N.N, + + "Shared I/O Write Time": N.N,+ + "Temp I/O Read Time": N.N, + + "Temp I/O Write Time": N.N + + }, + + "Planning Time": N.N, + + "Triggers": [ + + ], + + "Execution Time": N.N + + } + ] (1 row)