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 <byavu...@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
From de0f429280b24c42c951d86a468118ed09183a6e Mon Sep 17 00:00:00 2001 From: Nazir Bilal Yavuz <byavu...@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