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
From 96f7b82e2ec5e8f68b509ea58131fba42deac7c0 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <[email protected]>
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
From de0f429280b24c42c951d86a468118ed09183a6e Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <[email protected]>
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
