pgBufferUsage.blk_{read|write}_time are zero although there are pgBufferUsage.local_blks_{read|written}

Nazir Bilal Yavuz <byavuz81@gmail.com>

From: Nazir Bilal Yavuz <byavuz81@gmail.com>
To: pgsql-hackers <pgsql-hackers@postgresql.org>
Date: 2023-09-15T09:46:56Z
Lists: pgsql-hackers

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →
  1. Fix description of I/O timing info for shared buffers in EXPLAIN (BUFFERS)

  2. pg_stat_statements: Add local_blk_{read|write}_time

  3. Add local_blk_{read|write}_time I/O timing statistics for local blocks

  4. Rename I/O timing statistics columns to shared_blk_{read|write}_time

  5. Count write times when extending relation files for shared buffers

  6. Add JIT deform_counter

Attachments

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