pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Started by Nazir Bilal Yavuzover 2 years ago20 messages
Hi,
I found that pgBufferUsage.blk_{read|write}_time are zero although there
are pgBufferUsage.local_blks_{read|written}. For example, when you run
(track_io_timing should be on):
CREATE EXTENSION pg_stat_statements;
CREATE TEMP TABLE example_table (id serial PRIMARY KEY, data text);
INSERT INTO example_table (data) SELECT 'Some data'
FROM generate_series(1, 100000);
UPDATE example_table SET data = 'Updated data';
SELECT query, local_blks_read, local_blks_written,
blk_read_time, blk_write_time FROM pg_stat_statements
WHERE query like '%UPDATE%';
on master:
query | UPDATE example_table SET data = $1
local_blks_read | 467
local_blks_written | 2087
blk_read_time | 0
blk_write_time | 0
There are two reasons of that:
1- When local_blks_{read|written} are incremented,
pgstat_count_io_op_time() is called with IOOBJECT_TEMP_RELATION. But in
pgstat_count_io_op_time(), pgBufferUsage.blk_{read|write}_time increments
are called only when io_object is IOOBJECT_RELATION. The first patch
attached fixes that.
2- in ExtendBufferedRelLocal() and in ExtendBufferedRelShared(), extend
calls increment local_blks_written and shared_blks_written respectively.
But these extends are not counted while calculating the blk_write_time. If
there is no specific reason to not do that, I think these extends needs to
be counted in blk_write_time. The second patch attached does that.
Results after applying first patch:
query | UPDATE example_table SET data = $1
local_blks_read | 467
local_blks_written | 2087
blk_read_time | 0.30085
blk_write_time | 1.475123
Results after applying both patches:
query | UPDATE example_table SET data = $1
local_blks_read | 467
local_blks_written | 2087
blk_read_time | 0.329597
blk_write_time | 4.050305
Any kind of feedback would be appreciated.
Regards,
Nazir Bilal Yavuz
Microsoft
Attachments:
v1-0002-Include-IOOp-IOOP_EXTENDs-while-calculating-block.patchtext/x-diff; charset=US-ASCII; name=v1-0002-Include-IOOp-IOOP_EXTENDs-while-calculating-block.patchDownload
From 96f7b82e2ec5e8f68b509ea58131fba42deac7c0 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 15 Sep 2023 11:55:43 +0300
Subject: [PATCH v1 2/2] Include IOOp IOOP_EXTENDs while calculating block
write times
---
src/backend/utils/activity/pgstat_io.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index c8058b57962..56051fc6072 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -119,7 +119,7 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
INSTR_TIME_SET_CURRENT(io_time);
INSTR_TIME_SUBTRACT(io_time, start_time);
- if (io_op == IOOP_WRITE)
+ if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND)
{
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
if (io_object == IOOBJECT_RELATION
--
2.40.1
v1-0001-Increase-pgBufferUsage.blk_-read-write-_time-when.patchtext/x-diff; charset=US-ASCII; name=v1-0001-Increase-pgBufferUsage.blk_-read-write-_time-when.patchDownload
From de0f429280b24c42c951d86a468118ed09183a6e Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 15 Sep 2023 12:35:01 +0300
Subject: [PATCH v1 1/2] Increase pgBufferUsage.blk_{read|write}_time when
IOObject is IOOBJECT_TEMP_RELATION
---
src/backend/utils/activity/pgstat_io.c | 6 ++++--
1 file changed, 4 insertions(+), 2 deletions(-)
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index eb7d35d4225..c8058b57962 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -122,13 +122,15 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
if (io_op == IOOP_WRITE)
{
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
- if (io_object == IOOBJECT_RELATION)
+ if (io_object == IOOBJECT_RELATION
+ || io_object == IOOBJECT_TEMP_RELATION)
INSTR_TIME_ADD(pgBufferUsage.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)
+ if (io_object == IOOBJECT_RELATION
+ || io_object == IOOBJECT_TEMP_RELATION)
INSTR_TIME_ADD(pgBufferUsage.blk_read_time, io_time);
}
--
2.40.1
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Fri, Sep 15, 2023 at 9:24 AM Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:
I found that pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Yes, good catch. This is a bug. I will note that at least in 15 and
likely before, pgBufferUsage.local_blks_written is incremented for
local buffers but pgBufferUsage.blk_write_time is only added to for
shared buffers (in FlushBuffer()). I think it makes sense to propose a
bug fix to stable branches counting blk_write_time for local buffers
as well.
- Melanie
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Hi,
On Fri, 15 Sept 2023 at 16:30, Melanie Plageman
<melanieplageman@gmail.com> wrote:
Yes, good catch. This is a bug. I will note that at least in 15 and
likely before, pgBufferUsage.local_blks_written is incremented for
local buffers but pgBufferUsage.blk_write_time is only added to for
shared buffers (in FlushBuffer()). I think it makes sense to propose a
bug fix to stable branches counting blk_write_time for local buffers
as well.
I attached the PG16+ (after pg_stat_io) and PG15- (before pg_stat_io)
versions of the same patch.
Regards,
Nazir Bilal Yavuz
Microsoft
Attachments:
v2-0002-PG16-Add-pgBufferUsage.blk_write_time-to-for-IOOp.patchapplication/x-patch; name=v2-0002-PG16-Add-pgBufferUsage.blk_write_time-to-for-IOOp.patchDownload
From b4ea504497708b1017e8cfda5f1ac366a9e34386 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 15 Sep 2023 11:55:43 +0300
Subject: [PATCH v2 2/2] [PG16+] Add pgBufferUsage.blk_write_time to for IOOp
IOOP_EXTENDs
---
src/backend/utils/activity/pgstat_io.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index c8058b57962..56051fc6072 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -119,7 +119,7 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
INSTR_TIME_SET_CURRENT(io_time);
INSTR_TIME_SUBTRACT(io_time, start_time);
- if (io_op == IOOP_WRITE)
+ if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND)
{
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
if (io_object == IOOBJECT_RELATION
--
2.42.0
v2-0001-PG16-Increase-pgBufferUsage.blk_-read-write-_time.patchapplication/x-patch; name=v2-0001-PG16-Increase-pgBufferUsage.blk_-read-write-_time.patchDownload
From 46aaa1f76f02f7697f520e6509a3aeb970a862ae Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 15 Sep 2023 12:35:01 +0300
Subject: [PATCH v2 1/2] [PG16+] Increase pgBufferUsage.blk_{read|write}_time
when IOObject is IOOBJECT_TEMP_RELATION
---
src/backend/utils/activity/pgstat_io.c | 6 ++++--
1 file changed, 4 insertions(+), 2 deletions(-)
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index eb7d35d4225..c8058b57962 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -122,13 +122,15 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
if (io_op == IOOP_WRITE)
{
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
- if (io_object == IOOBJECT_RELATION)
+ if (io_object == IOOBJECT_RELATION
+ || io_object == IOOBJECT_TEMP_RELATION)
INSTR_TIME_ADD(pgBufferUsage.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)
+ if (io_object == IOOBJECT_RELATION
+ || io_object == IOOBJECT_TEMP_RELATION)
INSTR_TIME_ADD(pgBufferUsage.blk_read_time, io_time);
}
--
2.42.0
v2-0002-PG15-Add-pgBufferUsage.blk_write_time-to-for-exte.patchtext/x-diff; charset=US-ASCII; name=v2-0002-PG15-Add-pgBufferUsage.blk_write_time-to-for-exte.patchDownload
From 1e3af6e9466924713488b374b5d7bfb2c3bd5983 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Mon, 2 Oct 2023 16:31:46 +0300
Subject: [PATCH v2 2/2] [PG15-] Add pgBufferUsage.blk_write_time to for
extends
---
src/backend/storage/buffer/bufmgr.c | 17 ++++++++++++++---
1 file changed, 14 insertions(+), 3 deletions(-)
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index 9fcb3d6e194..a4e9fd3317b 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -825,6 +825,8 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum,
bool found;
bool isExtend;
bool isLocalBuf = SmgrIsTemp(smgr);
+ instr_time io_start,
+ io_time;
*hit = false;
@@ -992,9 +994,21 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum,
{
/* new buffers are zero-filled */
MemSet((char *) bufBlock, 0, BLCKSZ);
+
+ if (track_io_timing)
+ INSTR_TIME_SET_CURRENT(io_start);
+
/* don't set checksum for all-zero page */
smgrextend(smgr, forkNum, blockNum, (char *) bufBlock, false);
+ if (track_io_timing)
+ {
+ INSTR_TIME_SET_CURRENT(io_time);
+ INSTR_TIME_SUBTRACT(io_time, io_start);
+ pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time));
+ INSTR_TIME_ADD(pgBufferUsage.blk_write_time, io_time);
+ }
+
/*
* NB: we're *not* doing a ScheduleBufferTagForWriteback here;
* although we're essentially performing a write. At least on linux
@@ -1012,9 +1026,6 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum,
MemSet((char *) bufBlock, 0, BLCKSZ);
else
{
- instr_time io_start,
- io_time;
-
if (track_io_timing)
INSTR_TIME_SET_CURRENT(io_start);
--
2.42.0
v2-0001-PG15-Add-pgBufferUsage.blk_write_time-to-for-loca.patchtext/x-diff; charset=US-ASCII; name=v2-0001-PG15-Add-pgBufferUsage.blk_write_time-to-for-loca.patchDownload
From c7fdf1fa2a1f878a96a71b04e9fc65b1f2a0a402 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Mon, 2 Oct 2023 16:29:16 +0300
Subject: [PATCH v2 1/2] [PG15-] Add pgBufferUsage.blk_write_time to for local
buffers
---
src/backend/storage/buffer/localbuf.c | 14 ++++++++++++++
1 file changed, 14 insertions(+)
diff --git a/src/backend/storage/buffer/localbuf.c b/src/backend/storage/buffer/localbuf.c
index e71f95ac1ff..b86c0a8f64f 100644
--- a/src/backend/storage/buffer/localbuf.c
+++ b/src/backend/storage/buffer/localbuf.c
@@ -18,6 +18,7 @@
#include "access/parallel.h"
#include "catalog/catalog.h"
#include "executor/instrument.h"
+#include "pgstat.h"
#include "storage/buf_internals.h"
#include "storage/bufmgr.h"
#include "utils/guc.h"
@@ -116,6 +117,8 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum, BlockNumber blockNum,
int trycounter;
bool found;
uint32 buf_state;
+ instr_time io_start,
+ io_time;
INIT_BUFFERTAG(newTag, smgr->smgr_rnode.node, forkNum, blockNum);
@@ -219,6 +222,9 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum, BlockNumber blockNum,
PageSetChecksumInplace(localpage, bufHdr->tag.blockNum);
+ if (track_io_timing)
+ INSTR_TIME_SET_CURRENT(io_start);
+
/* And write... */
smgrwrite(oreln,
bufHdr->tag.forkNum,
@@ -226,6 +232,14 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum, BlockNumber blockNum,
localpage,
false);
+ if (track_io_timing)
+ {
+ INSTR_TIME_SET_CURRENT(io_time);
+ INSTR_TIME_SUBTRACT(io_time, io_start);
+ pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time));
+ INSTR_TIME_ADD(pgBufferUsage.blk_write_time, io_time);
+ }
+
/* Mark not-dirty now in case we error out below */
buf_state &= ~BM_DIRTY;
pg_atomic_unlocked_write_u32(&bufHdr->state, buf_state);
--
2.42.0
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Fri, Sep 15, 2023 at 12:34 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
On Fri, Sep 15, 2023 at 9:24 AM Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:
I found that pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Yes, good catch. This is a bug. I will note that at least in 15 and
likely before, pgBufferUsage.local_blks_written is incremented for
local buffers but pgBufferUsage.blk_write_time is only added to for
shared buffers (in FlushBuffer()). I think it makes sense to propose a
bug fix to stable branches counting blk_write_time for local buffers
as well.
My first thought was to wonder whether this was even a bug. I
remembered that EXPLAIN treats shared, local, and temp buffers as
three separate categories of things. But it seems that someone decided
to conflate two of them for I/O timing purposes:
if (has_timing)
{
appendStringInfoString(es->str, "
shared/local");
^^^^ Notice this bit in particular.
if (!INSTR_TIME_IS_ZERO(usage->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))
appendStringInfo(es->str, "
write=%0.3f",
INSTR_TIME_GET_MILLISEC(usage->blk_write_time));
if (has_temp_timing)
appendStringInfoChar(es->str, ',');
}
if (has_temp_timing)
{
appendStringInfoString(es->str, " temp");
if
(!INSTR_TIME_IS_ZERO(usage->temp_blk_read_time))
appendStringInfo(es->str, " read=%0.3f",
INSTR_TIME_GET_MILLISEC(usage->temp_blk_read_time));
if
(!INSTR_TIME_IS_ZERO(usage->temp_blk_write_time))
appendStringInfo(es->str, "
write=%0.3f",
INSTR_TIME_GET_MILLISEC(usage->temp_blk_write_time));
}
Given that, I'm inclined to agree that this is a bug. But we might
need to go through and make sure all of the code that deals with these
counters is on the same page about what the values represent. Maybe
there is code lurking somewhere that thinks these counters are only
supposed to include "shared" rather than, as the fragment above
suggests, "shared/local".
--
Robert Haas
EDB: http://www.enterprisedb.com
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Hi,
On Tue, 3 Oct 2023 at 19:44, Robert Haas <robertmhaas@gmail.com> wrote:
Given that, I'm inclined to agree that this is a bug. But we might
need to go through and make sure all of the code that deals with these
counters is on the same page about what the values represent. Maybe
there is code lurking somewhere that thinks these counters are only
supposed to include "shared" rather than, as the fragment above
suggests, "shared/local".
Thank you for the guidance.
What do you think about the second patch, counting extend calls'
timings in blk_write_time? In my opinion if something increments
{shared|local}_blks_written, then it needs to be counted in
blk_write_time too. I am not sure why it is decided like that.
Regards,
Nazir Bilal Yavuz
Microsoft
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Thu, Oct 5, 2023 at 6:25 AM Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:
What do you think about the second patch, counting extend calls'
timings in blk_write_time? In my opinion if something increments
{shared|local}_blks_written, then it needs to be counted in
blk_write_time too. I am not sure why it is decided like that.
I agree that an extend should be counted the same way as a write. But
I'm suspicious that here too we have confusion about whether
blk_write_time is supposed to be covering shared buffers and local
buffers or just shared buffers.
--
Robert Haas
EDB: http://www.enterprisedb.com
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Thu, Oct 05, 2023 at 08:51:40AM -0400, Robert Haas wrote:
On Thu, Oct 5, 2023 at 6:25 AM Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:
What do you think about the second patch, counting extend calls'
timings in blk_write_time? In my opinion if something increments
{shared|local}_blks_written, then it needs to be counted in
blk_write_time too. I am not sure why it is decided like that.I agree that an extend should be counted the same way as a write. But
I'm suspicious that here too we have confusion about whether
blk_write_time is supposed to be covering shared buffers and local
buffers or just shared buffers.
Agreed.
In ~14, as far as I can see blk_write_time is only incremented for
shared buffers. FWIW, I agree that we should improve these stats for
local buffers but I am not on board with a solution where we'd use the
same counter for local and shared buffers while we've historically
only counted the former, because that could confuse existing
monitoring queries. It seems to me that the right solution is to do
the same separation as temp blocks with two separate counters, without
a backpatch. I'd like to go as far as renaming blk_read_time and
blk_write_time to respectively shared_blk_read_time and
shared_blk_write_time to know exactly what the type of block dealt
with is when querying this data, particularly for pg_stat_statements's
sake.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Hi,
On Tue, 10 Oct 2023 at 03:54, Michael Paquier <michael@paquier.xyz> wrote:
In ~14, as far as I can see blk_write_time is only incremented for
shared buffers. FWIW, I agree that we should improve these stats for
local buffers but I am not on board with a solution where we'd use the
same counter for local and shared buffers while we've historically
only counted the former, because that could confuse existing
monitoring queries. It seems to me that the right solution is to do
the same separation as temp blocks with two separate counters, without
a backpatch. I'd like to go as far as renaming blk_read_time and
blk_write_time to respectively shared_blk_read_time and
shared_blk_write_time to know exactly what the type of block dealt
with is when querying this data, particularly for pg_stat_statements's
sake.
Yes, that could be a better solution. Also, having more detailed stats
for shared and local buffers is helpful. I updated patches in line
with that:
0001: Counts extends same way as a write.
0002: Rename blk_{read|write}_time as shared_blk_{read|write}_time.
0003: Add new local_blk_{read|write}_time variables.
Regards,
Nazir Bilal Yavuz
Microsoft
Attachments:
v3-0001-Include-IOOp-IOOP_EXTENDs-while-calculating-block.patchtext/x-diff; charset=US-ASCII; name=v3-0001-Include-IOOp-IOOP_EXTENDs-while-calculating-block.patchDownload
From acf5a2781760f284aef770da0f64acf8685b6445 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 13 Oct 2023 17:35:00 +0300
Subject: [PATCH v3 1/3] Include IOOp IOOP_EXTENDs while calculating block
write times
Extends are counted as writes in block context, so include IOOP_EXTENDs
while calculating block write times.
---
src/backend/utils/activity/pgstat_io.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index eb7d35d422..8ec8670199 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -119,7 +119,7 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
INSTR_TIME_SET_CURRENT(io_time);
INSTR_TIME_SUBTRACT(io_time, start_time);
- if (io_op == IOOP_WRITE)
+ if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND)
{
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
if (io_object == IOOBJECT_RELATION)
--
2.42.0
v3-0003-Add-local_blk_-read-write-_time-I-O-timing-statis.patchtext/x-diff; charset=US-ASCII; name=v3-0003-Add-local_blk_-read-write-_time-I-O-timing-statis.patchDownload
From 1f0933c7057e20c074f6b9355f6d91a9277a8c09 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Thu, 12 Oct 2023 14:40:23 +0300
Subject: [PATCH v3 3/3] Add local_blk_{read|write}_time I/O timing statistics
There was no I/O timing statistics for counting local blocks' timings.
So, add local_blk_{read|write}_time variables for counting these. These
counters are exposed in EXPLAIN and pg_stat_statements.
pg_stat_statements is bumped to 1.12.
---
contrib/pg_stat_statements/Makefile | 1 +
.../expected/oldextversions.out | 60 ++++++++++++++++
contrib/pg_stat_statements/meson.build | 1 +
.../pg_stat_statements--1.11--1.12.sql | 71 +++++++++++++++++++
.../pg_stat_statements/pg_stat_statements.c | 33 ++++++++-
.../pg_stat_statements.control | 2 +-
.../pg_stat_statements/sql/oldextversions.sql | 5 ++
doc/src/sgml/pgstatstatements.sgml | 20 ++++++
src/backend/commands/explain.c | 23 +++++-
src/backend/executor/instrument.c | 6 ++
src/backend/utils/activity/pgstat_io.c | 4 ++
src/include/executor/instrument.h | 2 +
src/test/regress/expected/explain.out | 4 ++
13 files changed, 228 insertions(+), 4 deletions(-)
create mode 100644 contrib/pg_stat_statements/pg_stat_statements--1.11--1.12.sql
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index eba4a95d91..b7d12bc7fb 100644
--- a/contrib/pg_stat_statements/Makefile
+++ b/contrib/pg_stat_statements/Makefile
@@ -7,6 +7,7 @@ OBJS = \
EXTENSION = pg_stat_statements
DATA = pg_stat_statements--1.4.sql \
+ pg_stat_statements--1.11--1.12.sql \
pg_stat_statements--1.10--1.11.sql \
pg_stat_statements--1.9--1.10.sql pg_stat_statements--1.8--1.9.sql \
pg_stat_statements--1.7--1.8.sql pg_stat_statements--1.6--1.7.sql \
diff --git a/contrib/pg_stat_statements/expected/oldextversions.out b/contrib/pg_stat_statements/expected/oldextversions.out
index 9e18fe2e47..b84e0c8484 100644
--- a/contrib/pg_stat_statements/expected/oldextversions.out
+++ b/contrib/pg_stat_statements/expected/oldextversions.out
@@ -308,4 +308,64 @@ SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
t
(1 row)
+-- New views for pg_stat_statements in 1.12
+AlTER EXTENSION pg_stat_statements UPDATE TO '1.12';
+\d pg_stat_statements
+ View "public.pg_stat_statements"
+ Column | Type | Collation | Nullable | Default
+------------------------+------------------+-----------+----------+---------
+ userid | oid | | |
+ dbid | oid | | |
+ toplevel | boolean | | |
+ queryid | bigint | | |
+ query | text | | |
+ plans | bigint | | |
+ total_plan_time | double precision | | |
+ min_plan_time | double precision | | |
+ max_plan_time | double precision | | |
+ mean_plan_time | double precision | | |
+ stddev_plan_time | double precision | | |
+ calls | bigint | | |
+ total_exec_time | double precision | | |
+ min_exec_time | double precision | | |
+ max_exec_time | double precision | | |
+ mean_exec_time | double precision | | |
+ stddev_exec_time | double precision | | |
+ rows | bigint | | |
+ shared_blks_hit | bigint | | |
+ shared_blks_read | bigint | | |
+ shared_blks_dirtied | bigint | | |
+ shared_blks_written | bigint | | |
+ local_blks_hit | bigint | | |
+ local_blks_read | bigint | | |
+ local_blks_dirtied | bigint | | |
+ local_blks_written | bigint | | |
+ temp_blks_read | bigint | | |
+ temp_blks_written | bigint | | |
+ shared_blk_read_time | double precision | | |
+ shared_blk_write_time | double precision | | |
+ local_blk_read_time | double precision | | |
+ local_blk_write_time | double precision | | |
+ temp_blk_read_time | double precision | | |
+ temp_blk_write_time | double precision | | |
+ wal_records | bigint | | |
+ wal_fpi | bigint | | |
+ wal_bytes | numeric | | |
+ jit_functions | bigint | | |
+ jit_generation_time | double precision | | |
+ jit_inlining_count | bigint | | |
+ jit_inlining_time | double precision | | |
+ jit_optimization_count | bigint | | |
+ jit_optimization_time | double precision | | |
+ jit_emission_count | bigint | | |
+ jit_emission_time | double precision | | |
+ jit_deform_count | bigint | | |
+ jit_deform_time | double precision | | |
+
+SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
+ has_data
+----------
+ t
+(1 row)
+
DROP EXTENSION pg_stat_statements;
diff --git a/contrib/pg_stat_statements/meson.build b/contrib/pg_stat_statements/meson.build
index 15b7c7f2b0..017b926bf8 100644
--- a/contrib/pg_stat_statements/meson.build
+++ b/contrib/pg_stat_statements/meson.build
@@ -21,6 +21,7 @@ contrib_targets += pg_stat_statements
install_data(
'pg_stat_statements.control',
'pg_stat_statements--1.4.sql',
+ 'pg_stat_statements--1.11--1.12.sql',
'pg_stat_statements--1.10--1.11.sql',
'pg_stat_statements--1.9--1.10.sql',
'pg_stat_statements--1.8--1.9.sql',
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.11--1.12.sql b/contrib/pg_stat_statements/pg_stat_statements--1.11--1.12.sql
new file mode 100644
index 0000000000..f5259358e9
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.11--1.12.sql
@@ -0,0 +1,71 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.11--1.12.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.12'" to load this file. \quit
+
+/* First we have to remove them from the extension */
+ALTER EXTENSION pg_stat_statements DROP VIEW pg_stat_statements;
+ALTER EXTENSION pg_stat_statements DROP FUNCTION pg_stat_statements(boolean);
+
+/* Then we can drop them */
+DROP VIEW pg_stat_statements;
+DROP FUNCTION pg_stat_statements(boolean);
+
+/* Now redefine */
+CREATE FUNCTION pg_stat_statements(IN showtext boolean,
+ OUT userid oid,
+ OUT dbid oid,
+ OUT toplevel bool,
+ OUT queryid bigint,
+ OUT query text,
+ OUT plans int8,
+ OUT total_plan_time float8,
+ OUT min_plan_time float8,
+ OUT max_plan_time float8,
+ OUT mean_plan_time float8,
+ OUT stddev_plan_time float8,
+ OUT calls int8,
+ OUT total_exec_time float8,
+ OUT min_exec_time float8,
+ OUT max_exec_time float8,
+ OUT mean_exec_time float8,
+ OUT stddev_exec_time float8,
+ OUT rows int8,
+ OUT shared_blks_hit int8,
+ OUT shared_blks_read int8,
+ OUT shared_blks_dirtied int8,
+ OUT shared_blks_written int8,
+ OUT local_blks_hit int8,
+ OUT local_blks_read int8,
+ OUT local_blks_dirtied int8,
+ OUT local_blks_written int8,
+ OUT temp_blks_read int8,
+ OUT temp_blks_written int8,
+ OUT shared_blk_read_time float8,
+ OUT shared_blk_write_time float8,
+ OUT local_blk_read_time float8,
+ OUT local_blk_write_time float8,
+ OUT temp_blk_read_time float8,
+ OUT temp_blk_write_time float8,
+ OUT wal_records int8,
+ OUT wal_fpi int8,
+ OUT wal_bytes numeric,
+ OUT jit_functions int8,
+ OUT jit_generation_time float8,
+ OUT jit_inlining_count int8,
+ OUT jit_inlining_time float8,
+ OUT jit_optimization_count int8,
+ OUT jit_optimization_time float8,
+ OUT jit_emission_count int8,
+ OUT jit_emission_time float8,
+ OUT jit_deform_count int8,
+ OUT jit_deform_time float8
+)
+RETURNS SETOF record
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_12'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+CREATE VIEW pg_stat_statements AS
+ SELECT * FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 9fd886596c..323164db5b 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -118,7 +118,8 @@ typedef enum pgssVersion
PGSS_V1_8,
PGSS_V1_9,
PGSS_V1_10,
- PGSS_V1_11
+ PGSS_V1_11,
+ PGSS_V1_12
} pgssVersion;
typedef enum pgssStoreKind
@@ -184,6 +185,10 @@ typedef struct Counters
* msec */
double shared_blk_write_time; /* time spent writing shared blocks, in
* msec */
+ double local_blk_read_time; /* time spent reading local blocks, in
+ * msec */
+ double local_blk_write_time; /* time spent writing local 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 */
@@ -320,6 +325,7 @@ PG_FUNCTION_INFO_V1(pg_stat_statements_1_8);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_9);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_10);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_11);
+PG_FUNCTION_INFO_V1(pg_stat_statements_1_12);
PG_FUNCTION_INFO_V1(pg_stat_statements);
PG_FUNCTION_INFO_V1(pg_stat_statements_info);
@@ -1395,6 +1401,8 @@ pgss_store(const char *query, uint64 queryId,
e->counters.temp_blks_written += bufusage->temp_blks_written;
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.local_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->local_blk_read_time);
+ e->counters.local_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->local_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);
@@ -1473,7 +1481,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_9 33
#define PG_STAT_STATEMENTS_COLS_V1_10 43
#define PG_STAT_STATEMENTS_COLS_V1_11 45
-#define PG_STAT_STATEMENTS_COLS 45 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_12 47
+#define PG_STAT_STATEMENTS_COLS 47 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1485,6 +1494,16 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
* expected API version is identified by embedding it in the C name of the
* function. Unfortunately we weren't bright enough to do that for 1.1.
*/
+Datum
+pg_stat_statements_1_12(PG_FUNCTION_ARGS)
+{
+ bool showtext = PG_GETARG_BOOL(0);
+
+ pg_stat_statements_internal(fcinfo, PGSS_V1_12, showtext);
+
+ return (Datum) 0;
+}
+
Datum
pg_stat_statements_1_11(PG_FUNCTION_ARGS)
{
@@ -1629,6 +1648,10 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (api_version != PGSS_V1_11)
elog(ERROR, "incorrect number of output arguments");
break;
+ case PG_STAT_STATEMENTS_COLS_V1_12:
+ if (api_version != PGSS_V1_12)
+ elog(ERROR, "incorrect number of output arguments");
+ break;
default:
elog(ERROR, "incorrect number of output arguments");
}
@@ -1828,6 +1851,11 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
values[i++] = Float8GetDatumFast(tmp.shared_blk_read_time);
values[i++] = Float8GetDatumFast(tmp.shared_blk_write_time);
}
+ if (api_version >= PGSS_V1_12)
+ {
+ values[i++] = Float8GetDatumFast(tmp.local_blk_read_time);
+ values[i++] = Float8GetDatumFast(tmp.local_blk_write_time);
+ }
if (api_version >= PGSS_V1_10)
{
values[i++] = Float8GetDatumFast(tmp.temp_blk_read_time);
@@ -1875,6 +1903,7 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
api_version == PGSS_V1_9 ? PG_STAT_STATEMENTS_COLS_V1_9 :
api_version == PGSS_V1_10 ? PG_STAT_STATEMENTS_COLS_V1_10 :
api_version == PGSS_V1_11 ? PG_STAT_STATEMENTS_COLS_V1_11 :
+ api_version == PGSS_V1_12 ? PG_STAT_STATEMENTS_COLS_V1_12 :
-1 /* fail if you forget to update this assert */ ));
tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls);
diff --git a/contrib/pg_stat_statements/pg_stat_statements.control b/contrib/pg_stat_statements/pg_stat_statements.control
index 8a76106ec6..d45ebc12e3 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.control
+++ b/contrib/pg_stat_statements/pg_stat_statements.control
@@ -1,5 +1,5 @@
# pg_stat_statements extension
comment = 'track planning and execution statistics of all SQL statements executed'
-default_version = '1.11'
+default_version = '1.12'
module_pathname = '$libdir/pg_stat_statements'
relocatable = true
diff --git a/contrib/pg_stat_statements/sql/oldextversions.sql b/contrib/pg_stat_statements/sql/oldextversions.sql
index 2435c0c576..d72cd823aa 100644
--- a/contrib/pg_stat_statements/sql/oldextversions.sql
+++ b/contrib/pg_stat_statements/sql/oldextversions.sql
@@ -53,4 +53,9 @@ AlTER EXTENSION pg_stat_statements UPDATE TO '1.11';
\d pg_stat_statements
SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
+-- New views for pg_stat_statements in 1.12
+AlTER EXTENSION pg_stat_statements UPDATE TO '1.12';
+\d pg_stat_statements
+SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
+
DROP EXTENSION pg_stat_statements;
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index ac8e6935b7..4eca7d01f4 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -353,6 +353,26 @@
</para></entry>
</row>
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>local_blk_read_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total time the statement spent reading local data file blocks, in milliseconds
+ (if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>local_blk_write_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total time the statement spent writing local data file blocks, in milliseconds
+ (if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
+ </para></entry>
+ </row>
+
<row>
<entry role="catalog_table_entry"><para role="column_definition">
<structfield>temp_blk_read_time</structfield> <type>double precision</type>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 45cd22b299..40ad0f6b30 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -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:");
@@ -3651,6 +3654,18 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
if (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, ',');
+ }
if (has_temp_timing)
{
appendStringInfoString(es->str, " temp");
@@ -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);
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index ef2a24b7cf..c383f34c06 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -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,
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index 297cfc15fb..490d5a9ab7 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -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],
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 8c3e5184fd..9233c25739 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -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;
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index a101886299..809655e16e 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -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 +
}, +
--
2.42.0
v3-0002-Rename-I-O-timing-statistics-columns-to-shared_bl.patchtext/x-diff; charset=US-ASCII; name=v3-0002-Rename-I-O-timing-statistics-columns-to-shared_bl.patchDownload
From 4b14f54c94f8c3692fd55f712dbe0d67c7587812 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 13 Oct 2023 16:28:03 +0300
Subject: [PATCH v3 2/3] Rename I/O timing statistics columns to
shared_blk_{read|write}_time
Since only shared blocks' timings are counted in blk_{read|write}_time,
rename them as shared_blk_{read|write}_time
---
.../expected/oldextversions.out | 202 +++++++++---------
.../pg_stat_statements--1.0--1.1.sql | 4 +-
.../pg_stat_statements--1.1--1.2.sql | 4 +-
.../pg_stat_statements--1.10--1.11.sql | 4 +-
.../pg_stat_statements--1.2--1.3.sql | 4 +-
.../pg_stat_statements--1.4.sql | 4 +-
.../pg_stat_statements--1.7--1.8.sql | 4 +-
.../pg_stat_statements--1.8--1.9.sql | 4 +-
.../pg_stat_statements--1.9--1.10.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 +++++-----
16 files changed, 208 insertions(+), 205 deletions(-)
diff --git a/contrib/pg_stat_statements/expected/oldextversions.out b/contrib/pg_stat_statements/expected/oldextversions.out
index 64982aad60..9e18fe2e47 100644
--- a/contrib/pg_stat_statements/expected/oldextversions.out
+++ b/contrib/pg_stat_statements/expected/oldextversions.out
@@ -53,32 +53,32 @@ SELECT pg_get_functiondef('pg_stat_statements_reset'::regproc);
(1 row)
\d pg_stat_statements
- View "public.pg_stat_statements"
- Column | Type | Collation | Nullable | Default
----------------------+------------------+-----------+----------+---------
- userid | oid | | |
- dbid | oid | | |
- queryid | bigint | | |
- query | text | | |
- calls | bigint | | |
- total_time | double precision | | |
- min_time | double precision | | |
- max_time | double precision | | |
- mean_time | double precision | | |
- stddev_time | double precision | | |
- rows | bigint | | |
- shared_blks_hit | bigint | | |
- shared_blks_read | bigint | | |
- shared_blks_dirtied | bigint | | |
- shared_blks_written | bigint | | |
- local_blks_hit | bigint | | |
- local_blks_read | bigint | | |
- local_blks_dirtied | bigint | | |
- local_blks_written | bigint | | |
- temp_blks_read | bigint | | |
- temp_blks_written | bigint | | |
- blk_read_time | double precision | | |
- blk_write_time | double precision | | |
+ View "public.pg_stat_statements"
+ Column | Type | Collation | Nullable | Default
+-----------------------+------------------+-----------+----------+---------
+ userid | oid | | |
+ dbid | oid | | |
+ queryid | bigint | | |
+ query | text | | |
+ calls | bigint | | |
+ total_time | double precision | | |
+ min_time | double precision | | |
+ max_time | double precision | | |
+ mean_time | double precision | | |
+ stddev_time | double precision | | |
+ rows | bigint | | |
+ shared_blks_hit | bigint | | |
+ shared_blks_read | bigint | | |
+ shared_blks_dirtied | bigint | | |
+ shared_blks_written | bigint | | |
+ local_blks_hit | bigint | | |
+ local_blks_read | bigint | | |
+ local_blks_dirtied | bigint | | |
+ local_blks_written | bigint | | |
+ temp_blks_read | bigint | | |
+ temp_blks_written | bigint | | |
+ shared_blk_read_time | double precision | | |
+ shared_blk_write_time | double precision | | |
SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
has_data
@@ -89,41 +89,41 @@ SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
-- New functions and views for pg_stat_statements in 1.8
AlTER EXTENSION pg_stat_statements UPDATE TO '1.8';
\d pg_stat_statements
- View "public.pg_stat_statements"
- Column | Type | Collation | Nullable | Default
----------------------+------------------+-----------+----------+---------
- userid | oid | | |
- dbid | oid | | |
- queryid | bigint | | |
- query | text | | |
- plans | bigint | | |
- total_plan_time | double precision | | |
- min_plan_time | double precision | | |
- max_plan_time | double precision | | |
- mean_plan_time | double precision | | |
- stddev_plan_time | double precision | | |
- calls | bigint | | |
- total_exec_time | double precision | | |
- min_exec_time | double precision | | |
- max_exec_time | double precision | | |
- mean_exec_time | double precision | | |
- stddev_exec_time | double precision | | |
- rows | bigint | | |
- shared_blks_hit | bigint | | |
- shared_blks_read | bigint | | |
- shared_blks_dirtied | bigint | | |
- shared_blks_written | bigint | | |
- local_blks_hit | bigint | | |
- local_blks_read | bigint | | |
- local_blks_dirtied | bigint | | |
- local_blks_written | bigint | | |
- temp_blks_read | bigint | | |
- temp_blks_written | bigint | | |
- blk_read_time | double precision | | |
- blk_write_time | double precision | | |
- wal_records | bigint | | |
- wal_fpi | bigint | | |
- wal_bytes | numeric | | |
+ View "public.pg_stat_statements"
+ Column | Type | Collation | Nullable | Default
+-----------------------+------------------+-----------+----------+---------
+ userid | oid | | |
+ dbid | oid | | |
+ queryid | bigint | | |
+ query | text | | |
+ plans | bigint | | |
+ total_plan_time | double precision | | |
+ min_plan_time | double precision | | |
+ max_plan_time | double precision | | |
+ mean_plan_time | double precision | | |
+ stddev_plan_time | double precision | | |
+ calls | bigint | | |
+ total_exec_time | double precision | | |
+ min_exec_time | double precision | | |
+ max_exec_time | double precision | | |
+ mean_exec_time | double precision | | |
+ stddev_exec_time | double precision | | |
+ rows | bigint | | |
+ shared_blks_hit | bigint | | |
+ shared_blks_read | bigint | | |
+ shared_blks_dirtied | bigint | | |
+ shared_blks_written | bigint | | |
+ local_blks_hit | bigint | | |
+ local_blks_read | bigint | | |
+ local_blks_dirtied | bigint | | |
+ local_blks_written | bigint | | |
+ temp_blks_read | bigint | | |
+ temp_blks_written | bigint | | |
+ shared_blk_read_time | double precision | | |
+ shared_blk_write_time | double precision | | |
+ wal_records | bigint | | |
+ wal_fpi | bigint | | |
+ wal_bytes | numeric | | |
SELECT pg_get_functiondef('pg_stat_statements_reset'::regproc);
pg_get_functiondef
@@ -151,42 +151,42 @@ SELECT pg_get_functiondef('pg_stat_statements_info'::regproc);
(1 row)
\d pg_stat_statements
- View "public.pg_stat_statements"
- Column | Type | Collation | Nullable | Default
----------------------+------------------+-----------+----------+---------
- userid | oid | | |
- dbid | oid | | |
- toplevel | boolean | | |
- queryid | bigint | | |
- query | text | | |
- plans | bigint | | |
- total_plan_time | double precision | | |
- min_plan_time | double precision | | |
- max_plan_time | double precision | | |
- mean_plan_time | double precision | | |
- stddev_plan_time | double precision | | |
- calls | bigint | | |
- total_exec_time | double precision | | |
- min_exec_time | double precision | | |
- max_exec_time | double precision | | |
- mean_exec_time | double precision | | |
- stddev_exec_time | double precision | | |
- rows | bigint | | |
- shared_blks_hit | bigint | | |
- shared_blks_read | bigint | | |
- shared_blks_dirtied | bigint | | |
- shared_blks_written | bigint | | |
- local_blks_hit | bigint | | |
- local_blks_read | bigint | | |
- local_blks_dirtied | bigint | | |
- local_blks_written | bigint | | |
- temp_blks_read | bigint | | |
- temp_blks_written | bigint | | |
- blk_read_time | double precision | | |
- blk_write_time | double precision | | |
- wal_records | bigint | | |
- wal_fpi | bigint | | |
- wal_bytes | numeric | | |
+ View "public.pg_stat_statements"
+ Column | Type | Collation | Nullable | Default
+-----------------------+------------------+-----------+----------+---------
+ userid | oid | | |
+ dbid | oid | | |
+ toplevel | boolean | | |
+ queryid | bigint | | |
+ query | text | | |
+ plans | bigint | | |
+ total_plan_time | double precision | | |
+ min_plan_time | double precision | | |
+ max_plan_time | double precision | | |
+ mean_plan_time | double precision | | |
+ stddev_plan_time | double precision | | |
+ calls | bigint | | |
+ total_exec_time | double precision | | |
+ min_exec_time | double precision | | |
+ max_exec_time | double precision | | |
+ mean_exec_time | double precision | | |
+ stddev_exec_time | double precision | | |
+ rows | bigint | | |
+ shared_blks_hit | bigint | | |
+ shared_blks_read | bigint | | |
+ shared_blks_dirtied | bigint | | |
+ shared_blks_written | bigint | | |
+ local_blks_hit | bigint | | |
+ local_blks_read | bigint | | |
+ local_blks_dirtied | bigint | | |
+ local_blks_written | bigint | | |
+ temp_blks_read | bigint | | |
+ temp_blks_written | bigint | | |
+ shared_blk_read_time | double precision | | |
+ shared_blk_write_time | double precision | | |
+ wal_records | bigint | | |
+ wal_fpi | bigint | | |
+ wal_bytes | numeric | | |
SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
has_data
@@ -228,8 +228,8 @@ AlTER EXTENSION pg_stat_statements UPDATE TO '1.10';
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 | | |
@@ -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.0--1.1.sql b/contrib/pg_stat_statements/pg_stat_statements--1.0--1.1.sql
index 5be281ea47..749f0ecbc0 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.0--1.1.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.0--1.1.sql
@@ -29,8 +29,8 @@ CREATE FUNCTION pg_stat_statements(
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
)
RETURNS SETOF record
AS 'MODULE_PATHNAME'
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql b/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql
index 74ae43868d..9a20aca158 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql
@@ -30,8 +30,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
)
RETURNS SETOF record
AS 'MODULE_PATHNAME', 'pg_stat_statements_1_2'
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--1.2--1.3.sql b/contrib/pg_stat_statements/pg_stat_statements--1.2--1.3.sql
index a56f151b99..4737671938 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.2--1.3.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.2--1.3.sql
@@ -34,8 +34,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
)
RETURNS SETOF record
AS 'MODULE_PATHNAME', 'pg_stat_statements_1_3'
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.4.sql b/contrib/pg_stat_statements/pg_stat_statements--1.4.sql
index 58cdf600fc..d124669126 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.4.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.4.sql
@@ -31,8 +31,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
)
RETURNS SETOF record
AS 'MODULE_PATHNAME', 'pg_stat_statements_1_3'
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql b/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql
index 0f63f08f7e..dbb1844f79 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql
@@ -40,8 +40,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 wal_records int8,
OUT wal_fpi int8,
OUT wal_bytes numeric
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.8--1.9.sql b/contrib/pg_stat_statements/pg_stat_statements--1.8--1.9.sql
index c45223f888..5f7404d0b9 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.8--1.9.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.8--1.9.sql
@@ -55,8 +55,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 wal_records int8,
OUT wal_fpi int8,
OUT wal_bytes numeric
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
index 811813c491..f5985145c3 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.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..9fd886596c 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..ac8e6935b7 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -335,20 +335,20 @@
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>blk_read_time</structfield> <type>double precision</type>
+ <structfield>shared_blk_read_time</structfield> <type>double precision</type>
</para>
<para>
- Total time the statement spent reading data file blocks, in milliseconds
+ Total time the statement spent reading shared data file blocks, in milliseconds
(if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
</para></entry>
</row>
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>blk_write_time</structfield> <type>double precision</type>
+ <structfield>shared_blk_write_time</structfield> <type>double precision</type>
</para>
<para>
- Total time the statement spent writing data file blocks, in milliseconds
+ Total time the statement spent writing shared data file blocks, in milliseconds
(if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
</para></entry>
</row>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 13217807ee..45cd22b299 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..8c3e5184fd 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)
--
2.42.0
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Mon, Oct 16, 2023 at 01:07:07PM +0300, Nazir Bilal Yavuz wrote:
Yes, that could be a better solution. Also, having more detailed stats
for shared and local buffers is helpful. I updated patches in line
with that:0001: Counts extends same way as a write.
It can change existing query results on an already-released branch,
but we already count the number of blocks when doing a relation
extension, so counting the write time is something I'd rather fix in
v16. If you have any objections, let me know.
0002: Rename blk_{read|write}_time as shared_blk_{read|write}_time.
Note that `git diff --check` complains here.
--- a/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql
@@ -30,8 +30,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 float8Doing that in an extension upgrade script is incorrect. These should
not be touched.
- Total time the statement spent reading data file blocks, in milliseconds
+ Total time the statement spent reading shared data file blocks, in millisecondsOr just shared blocks? That's what we use elsewhere for
pg_stat_statements. "shared data file blocks" sounds a bit confusing
for relation file blocks read/written from/to shared buffers.
0003: Add new local_blk_{read|write}_time variables.
DATA = pg_stat_statements--1.4.sql \
+ pg_stat_statements--1.11--1.12.sql \
pg_stat_statements--1.10--1.11.sql \
There is no need to bump again pg_stat_statements, as it has already
been bumped to 1.11 on HEAD per the recent commit 5a3423ad8ee1 from
Daniel. So the new changes can just be added to 1.11.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Hi,
Thanks for the review!
On Tue, 17 Oct 2023 at 11:40, Michael Paquier <michael@paquier.xyz> wrote:
On Mon, Oct 16, 2023 at 01:07:07PM +0300, Nazir Bilal Yavuz wrote:
Yes, that could be a better solution. Also, having more detailed stats
for shared and local buffers is helpful. I updated patches in line
with that:0001: Counts extends same way as a write.
It can change existing query results on an already-released branch,
but we already count the number of blocks when doing a relation
extension, so counting the write time is something I'd rather fix in
v16. If you have any objections, let me know.
I agree.
0002: Rename blk_{read|write}_time as shared_blk_{read|write}_time.
Note that `git diff --check` complains here.
--- a/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql +++ b/contrib/pg_stat_statements/pg_stat_statements--1.1--1.2.sql @@ -30,8 +30,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 float8Doing that in an extension upgrade script is incorrect. These should
not be touched.- Total time the statement spent reading data file blocks, in milliseconds + Total time the statement spent reading shared data file blocks, in millisecondsOr just shared blocks? That's what we use elsewhere for
pg_stat_statements. "shared data file blocks" sounds a bit confusing
for relation file blocks read/written from/to shared buffers.0003: Add new local_blk_{read|write}_time variables.
DATA = pg_stat_statements--1.4.sql \
+ pg_stat_statements--1.11--1.12.sql \
pg_stat_statements--1.10--1.11.sql \There is no need to bump again pg_stat_statements, as it has already
been bumped to 1.11 on HEAD per the recent commit 5a3423ad8ee1 from
Daniel. So the new changes can just be added to 1.11.
I updated patches based on your comments. v4 is attached.
Regards,
Nazir Bilal Yavuz
Microsoft
Attachments:
v4-0001-Include-IOOp-IOOP_EXTENDs-while-calculating-block.patchtext/x-diff; charset=US-ASCII; name=v4-0001-Include-IOOp-IOOP_EXTENDs-while-calculating-block.patchDownload
From 4b744c0b4e2cfdee4e95779ee19ac214b85aa150 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 13 Oct 2023 17:35:00 +0300
Subject: [PATCH v4 1/3] Include IOOp IOOP_EXTENDs while calculating block
write times
Extends are counted as writes in block context, so include IOOP_EXTENDs
while calculating block write times.
---
src/backend/utils/activity/pgstat_io.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index eb7d35d422..8ec8670199 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -119,7 +119,7 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
INSTR_TIME_SET_CURRENT(io_time);
INSTR_TIME_SUBTRACT(io_time, start_time);
- if (io_op == IOOP_WRITE)
+ if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND)
{
pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
if (io_object == IOOBJECT_RELATION)
--
2.42.0
v4-0002-Rename-I-O-timing-statistics-columns-to-shared_bl.patchtext/x-diff; charset=US-ASCII; name=v4-0002-Rename-I-O-timing-statistics-columns-to-shared_bl.patchDownload
From 5f299ee59d443a53bf6f3a8e18467270f5ee8318 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Fri, 13 Oct 2023 16:28:03 +0300
Subject: [PATCH v4 2/3] Rename I/O timing statistics columns to
shared_blk_{read|write}_time
Since only shared blocks' timings are counted in blk_{read|write}_time,
rename them as shared_blk_{read|write}_time
---
.../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..9fd886596c 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 @@
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>blk_read_time</structfield> <type>double precision</type>
+ <structfield>shared_blk_read_time</structfield> <type>double precision</type>
</para>
<para>
- Total time the statement spent reading data file blocks, in milliseconds
+ Total time the statement spent reading shared blocks, in milliseconds
(if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
</para></entry>
</row>
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>blk_write_time</structfield> <type>double precision</type>
+ <structfield>shared_blk_write_time</structfield> <type>double precision</type>
</para>
<para>
- Total time the statement spent writing data file blocks, in milliseconds
+ Total time the statement spent writing shared blocks, in milliseconds
(if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
</para></entry>
</row>
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..8c3e5184fd 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)
--
2.42.0
v4-0003-Add-local_blk_-read-write-_time-I-O-timing-statis.patchtext/x-diff; charset=US-ASCII; name=v4-0003-Add-local_blk_-read-write-_time-I-O-timing-statis.patchDownload
From d99998efc5b4fa5e6a0998ac326d263d899c3afe Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Tue, 17 Oct 2023 12:45:47 +0300
Subject: [PATCH v4 3/3] Add local_blk_{read|write}_time I/O timing statistics
There was no I/O timing statistics for counting local blocks' timings.
So, add local_blk_{read|write}_time variables for counting these. These
counters are exposed in EXPLAIN and pg_stat_statements.
pg_stat_statements is bumped to 1.12.
---
.../expected/oldextversions.out | 2 ++
.../pg_stat_statements--1.10--1.11.sql | 2 ++
.../pg_stat_statements/pg_stat_statements.c | 15 ++++++++++--
doc/src/sgml/pgstatstatements.sgml | 20 ++++++++++++++++
src/backend/commands/explain.c | 23 ++++++++++++++++++-
src/backend/executor/instrument.c | 6 +++++
src/backend/utils/activity/pgstat_io.c | 4 ++++
src/include/executor/instrument.h | 2 ++
src/test/regress/expected/explain.out | 4 ++++
9 files changed, 75 insertions(+), 3 deletions(-)
diff --git a/contrib/pg_stat_statements/expected/oldextversions.out b/contrib/pg_stat_statements/expected/oldextversions.out
index c2e0140a47..5a5404bbd5 100644
--- a/contrib/pg_stat_statements/expected/oldextversions.out
+++ b/contrib/pg_stat_statements/expected/oldextversions.out
@@ -286,6 +286,8 @@ AlTER EXTENSION pg_stat_statements UPDATE TO '1.11';
temp_blks_written | bigint | | |
shared_blk_read_time | double precision | | |
shared_blk_write_time | double precision | | |
+ local_blk_read_time | double precision | | |
+ local_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 448ef3682f..5fe211184b 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
@@ -43,6 +43,8 @@ CREATE FUNCTION pg_stat_statements(IN showtext boolean,
OUT temp_blks_written int8,
OUT shared_blk_read_time float8,
OUT shared_blk_write_time float8,
+ OUT local_blk_read_time float8,
+ OUT local_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 9fd886596c..28c090606c 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -184,6 +184,10 @@ typedef struct Counters
* msec */
double shared_blk_write_time; /* time spent writing shared blocks, in
* msec */
+ double local_blk_read_time; /* time spent reading local blocks, in
+ * msec */
+ double local_blk_write_time; /* time spent writing local 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 */
@@ -1395,6 +1399,8 @@ pgss_store(const char *query, uint64 queryId,
e->counters.temp_blks_written += bufusage->temp_blks_written;
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.local_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->local_blk_read_time);
+ e->counters.local_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->local_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);
@@ -1472,8 +1478,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_8 32
#define PG_STAT_STATEMENTS_COLS_V1_9 33
#define PG_STAT_STATEMENTS_COLS_V1_10 43
-#define PG_STAT_STATEMENTS_COLS_V1_11 45
-#define PG_STAT_STATEMENTS_COLS 45 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_11 47
+#define PG_STAT_STATEMENTS_COLS 47 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1828,6 +1834,11 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
values[i++] = Float8GetDatumFast(tmp.shared_blk_read_time);
values[i++] = Float8GetDatumFast(tmp.shared_blk_write_time);
}
+ if (api_version >= PGSS_V1_11)
+ {
+ values[i++] = Float8GetDatumFast(tmp.local_blk_read_time);
+ values[i++] = Float8GetDatumFast(tmp.local_blk_write_time);
+ }
if (api_version >= PGSS_V1_10)
{
values[i++] = Float8GetDatumFast(tmp.temp_blk_read_time);
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index 2c4e3655ff..6c7ca962f8 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -353,6 +353,26 @@
</para></entry>
</row>
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>local_blk_read_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total time the statement spent reading local blocks, in milliseconds
+ (if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>local_blk_write_time</structfield> <type>double precision</type>
+ </para>
+ <para>
+ Total time the statement spent writing local blocks, in milliseconds
+ (if <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero)
+ </para></entry>
+ </row>
+
<row>
<entry role="catalog_table_entry"><para role="column_definition">
<structfield>temp_blk_read_time</structfield> <type>double precision</type>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index d6cf948f38..83f46ed9d7 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -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:");
@@ -3651,6 +3654,18 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage, bool planning)
if (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, ',');
+ }
if (has_temp_timing)
{
appendStringInfoString(es->str, " temp");
@@ -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);
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index ef2a24b7cf..c383f34c06 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -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,
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index 297cfc15fb..490d5a9ab7 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -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],
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 8c3e5184fd..9233c25739 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -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;
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index a101886299..809655e16e 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -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 +
}, +
--
2.42.0
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Tue, Oct 17, 2023 at 04:44:25PM +0300, Nazir Bilal Yavuz wrote:
I updated patches based on your comments. v4 is attached.
Thanks for the new versions. I have applied 0001 and backpatched it
for now. 0002 and 0003 look in much cleaner shape than previously.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Tue, Oct 03, 2023 at 12:44:36PM -0400, Robert Haas wrote:
My first thought was to wonder whether this was even a bug. I
remembered that EXPLAIN treats shared, local, and temp buffers as
three separate categories of things. But it seems that someone decided
to conflate two of them for I/O timing purposes:if (has_timing)
{
appendStringInfoString(es->str, "
shared/local");^^^^ Notice this bit in particular.
I was reviewing the whole, and this is an oversight specific to
efb0ef909f60, because we've never incremented the write/read counters
for local buffers, even with this commit applied, for both the EXPLAIN
reports and anything stored in pg_stat_statement. It seems to me that
the origin of the confusion comes down to pg_stat_database where
blk_{read|write}_time increments on both local and shared blocks, but
on EXPLAIN this stuff only reflects data about shared buffers. So the
"shared" part of the string is right, but the "local" part is not in
v15 and v16.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Wed, Oct 18, 2023 at 02:56:42PM +0900, Michael Paquier wrote:
Thanks for the new versions. I have applied 0001 and backpatched it
for now. 0002 and 0003 look in much cleaner shape than previously.
0002 and 0003 have now been applied. I have split 0003 into two parts
at the end, mainly on clarity grounds: one for the counters with
EXPLAIN and a second for pg_stat_statements.
There were a few things in the patch set. Per my notes:
- Some incorrect indentation.
- The additions of show_buffer_usage() did not handle correctly the
addition of a comma before/after the local timing block. The code
area for has_local_timing needs to check for has_temp_timing, while
the area of has_shared_timing needs to check for (has_local_timing ||
has_temp_timing).
- explain.sgml was missing an update for the information related to
the read/write timings of the local blocks.
Remains what we should do about the "shared/local" string in
show_buffer_usage() for v16 and v15, as "local" is unrelated to that.
Perhaps we should just switch to "shared" in this case or just remove
the string entirely? Still that implies changing the output of
EXPLAIN on a stable branch in this case, so there could be an argument
for leaving this stuff alone.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Hi,
On Thu, 19 Oct 2023 at 08:26, Michael Paquier <michael@paquier.xyz> wrote:
On Wed, Oct 18, 2023 at 02:56:42PM +0900, Michael Paquier wrote:
Thanks for the new versions. I have applied 0001 and backpatched it
for now. 0002 and 0003 look in much cleaner shape than previously.0002 and 0003 have now been applied. I have split 0003 into two parts
at the end, mainly on clarity grounds: one for the counters with
EXPLAIN and a second for pg_stat_statements.There were a few things in the patch set. Per my notes:
- Some incorrect indentation.
- The additions of show_buffer_usage() did not handle correctly the
addition of a comma before/after the local timing block. The code
area for has_local_timing needs to check for has_temp_timing, while
the area of has_shared_timing needs to check for (has_local_timing ||
has_temp_timing).
- explain.sgml was missing an update for the information related to
the read/write timings of the local blocks.
Thanks for the changes, push and feedback!
Remains what we should do about the "shared/local" string in
show_buffer_usage() for v16 and v15, as "local" is unrelated to that.
Perhaps we should just switch to "shared" in this case or just remove
the string entirely? Still that implies changing the output of
EXPLAIN on a stable branch in this case, so there could be an argument
for leaving this stuff alone.
I think switching it to 'shared' makes sense. That shouldn't confuse
existing monitoring queries much as the numbers won't change, right?
Also, if we keep 'shared/local' there could be similar complaints to
this thread in the future; so, at least adding comments can be
helpful.
Regards,
Nazir Bilal Yavuz
Microsoft
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Fri, Oct 27, 2023 at 04:58:20PM +0300, Nazir Bilal Yavuz wrote:
I think switching it to 'shared' makes sense. That shouldn't confuse
existing monitoring queries much as the numbers won't change, right?
Also, if we keep 'shared/local' there could be similar complaints to
this thread in the future; so, at least adding comments can be
helpful.
The problem is that it may impact existing tools that do explain
output deparsing. One of them is https://explain.depesz.com/ that
Hubert Depesz Lubaczewski has implemented, and it would be sad to
break anything related to it.
I am adding Hubert in CC for comments about changing this
"shared/local" to "shared" on a released branch. Knowing that
"shared" and "local" will need to be handled as separate terms in 17~
anyway, perhaps that's not a big deal, but let's be sure.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Mon, Oct 30, 2023 at 10:45:05AM +0900, Michael Paquier wrote:
On Fri, Oct 27, 2023 at 04:58:20PM +0300, Nazir Bilal Yavuz wrote:
I think switching it to 'shared' makes sense. That shouldn't confuse
existing monitoring queries much as the numbers won't change, right?
Also, if we keep 'shared/local' there could be similar complaints to
this thread in the future; so, at least adding comments can be
helpful.The problem is that it may impact existing tools that do explain
output deparsing. One of them is https://explain.depesz.com/ that
Hubert Depesz Lubaczewski has implemented, and it would be sad to
break anything related to it.I am adding Hubert in CC for comments about changing this
"shared/local" to "shared" on a released branch. Knowing that
"shared" and "local" will need to be handled as separate terms in 17~
anyway, perhaps that's not a big deal, but let's be sure.
Hi,
some things will definitely break, but that's 100% OK. The change seems
needed, and I can update my parser to deal with it :)
Best regards,
depesz
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Mon, Oct 30, 2023 at 03:14:16PM +0100, hubert depesz lubaczewski wrote:
some things will definitely break, but that's 100% OK. The change seems
needed, and I can update my parser to deal with it :)
Thanks for the input. I was looking yesterday if this code was
available somewhere, but couldn't find it.. Until this morning:
https://gitlab.com/depesz/explain.depesz.com.git
And.. It looks like things would become better if we change
"shared/local" to "shared", because the parsing code seems to have an
issue once you add a '/'. All the fields in I/O Timings are
considered as part of a Node, and they're just included in the output.
Now, pasting a plan that includes "shared/local" drops entirely the
string from the output result, so some information is lost. In short,
imagine that we have the following string in a node:
I/O Timings: shared/local write=23.77
This would show up like that, meaning that the context where the
write/read timings happened is lost:
I/O Timings: write=23.77
If we switch back to "shared", the context would be kept around. Of
course, this does not count for all the parsers that may be out
there, but at least that's something.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Tue, Oct 31, 2023 at 08:17:52AM +0900, Michael Paquier wrote:
Thanks for the input. I was looking yesterday if this code was
available somewhere, but couldn't find it.. Until this morning:
https://gitlab.com/depesz/explain.depesz.com.git
Well, the parser itself is https://gitlab.com/depesz/Pg--Explain/ :)
And.. It looks like things would become better if we change
"shared/local" to "shared", because the parsing code seems to have an
issue once you add a '/'. All the fields in I/O Timings are
considered as part of a Node, and they're just included in the output.
Now, pasting a plan that includes "shared/local" drops entirely the
string from the output result, so some information is lost. In short,
imagine that we have the following string in a node:
I/O Timings: shared/local write=23.77This would show up like that, meaning that the context where the
write/read timings happened is lost:
I/O Timings: write=23.77If we switch back to "shared", the context would be kept around. Of
course, this does not count for all the parsers that may be out
there, but at least that's something.
Well, if it's possible to deduce what is the meaning in given line,
I can add the logic to do the deduction to parser.
Also, I want to say that I appreciate being looped in the discussion.
Best regards,
depesz
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
On Tue, Oct 31, 2023 at 03:11:03PM +0100, hubert depesz lubaczewski wrote:
On Tue, Oct 31, 2023 at 08:17:52AM +0900, Michael Paquier wrote:
Thanks for the input. I was looking yesterday if this code was
available somewhere, but couldn't find it.. Until this morning:
https://gitlab.com/depesz/explain.depesz.com.gitWell, the parser itself is https://gitlab.com/depesz/Pg--Explain/ :)
That was close enough ;)
Well, if it's possible to deduce what is the meaning in given line,
I can add the logic to do the deduction to parser.Also, I want to say that I appreciate being looped in the discussion.
I lost sight of this thread, so my apologies for the delay. The patch
to fix the description of the EXPLAIN field has now been applied to
v15 and v16.
--
Michael
Re: pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}
Well, if it's possible to deduce what is the meaning in given line,
I can add the logic to do the deduction to parser.
Also, I want to say that I appreciate being looped in the discussion.I lost sight of this thread, so my apologies for the delay. The patch
to fix the description of the EXPLAIN field has now been applied to
v15 and v16.
Thanks. Will do my best to update the parser soon.
Best regards,
depesz