Re: Use instr_time for pg_stat_database block read/write time counters - Mailing list pgsql-hackers

On Mon, Sep 28, 2026 at 5:55 PM Bernd Reiß <bd_reiss@gmx.at> wrote:
>
> Dear hackers,
>
> While working on a review for another patch (see [1]) Ahmed Gouda and I
> noticed time skew in write and read times between the pg_stat_database
> and pg_stat_io views.

Hi Bernd, Ahmed,

Thanks for the patch. I reviewed the changes and used the help of AI
to analyze the broader architectural and operational impacts across
the database.

The patch applies cleanly, compiled without warnings and tests pass,

make -C src/test/regress check
.
.
.
.
1..239
# All 239 tests passed.

Please find more analysis below,

>
> Running the following script on a test server with a single database and
> track_io_timing=on illustrates the difference:
>
> drop table if exists test; create table test (id bigint);
> create or replace view stat_comparison as select
>      'pg_stat_database' as source,
>      round(sum(blk_write_time)::numeric,3) ms_write,
>      round(sum(blk_read_time)::numeric, 3) ms_read
> from
>      pg_stat_database
> union all
> select
>      'pg_stat_io',
>      round(sum(coalesce(write_time,0) + coalesce(extend_time,
> 0))::numeric, 3),
>      round(sum(coalesce(read_time,0))::numeric, 3)
> from
>      pg_stat_io
> where
>      backend_type not in ('checkpointer', 'background writer',
> 'autovacuum launcher') and object in ('relation', 'temp relation');
> -- reset the numbers twice to make sure all stats are set to 0
> select pg_stat_reset();select pg_stat_reset_shared();
> \c template1
> select pg_stat_reset();select pg_stat_reset_shared();
> \c postgres
> select pg_stat_reset();select pg_stat_reset_shared();
> \c template1
> select pg_stat_reset();select pg_stat_reset_shared();
> \c postgres
> select * from stat_comparison;
> insert into test select generate_series(1,1e8);
> select count(id) from test;
> checkpoint; -- write dirty buffers to make the script reproducible
> select pg_sleep(3);
> select * from stat_comparison;
> DROP TABLE
> CREATE TABLE
> CREATE VIEW
>   pg_stat_reset
> ---------------
>
> (1 row)
>
>   pg_stat_reset_shared
> ----------------------
>
> (1 row)
>
> You are now connected to database "template1" as user "postgres".
>   pg_stat_reset
> ---------------
>
> (1 row)
>
>   pg_stat_reset_shared
> ----------------------
>
> (1 row)
>
> You are now connected to database "postgres" as user "postgres".
>   pg_stat_reset
> ---------------
>
> (1 row)
>
>   pg_stat_reset_shared
> ----------------------
>
> (1 row)
>
> You are now connected to database "template1" as user "postgres".
>   pg_stat_reset
> ---------------
>
> (1 row)
>
>   pg_stat_reset_shared
> ----------------------
>
> (1 row)
>
> You are now connected to database "postgres" as user "postgres".
>        source      | ms_write | ms_read
> ------------------+----------+---------
>   pg_stat_database |    0.000 |   0.000
>   pg_stat_io       |    0.000 |   0.000
> (2 rows)
>
> INSERT 0 100000000
>     count
> -----------
>   100000000
> (1 row)
>
> CHECKPOINT
>   pg_sleep
> ----------
>
> (1 row)
>
>        source      | ms_write | ms_read
> ------------------+----------+----------
>   pg_stat_database | 4279.430 | 1354.911
>   pg_stat_io       | 4899.788 | 1381.406
> (2 rows)
>
> Inspecting pgstat_count_io_op_time() in pgstat_io.c, we found that for
> pg_stat_database the io_time is first truncated to microseconds before
> being added to the pgStatBlockReadTime and pgStatBlockWriteTime counters
> using
> pgstat_count_buffer_{write|read}_time(INSTR_TIME_GET_MICROSEC(io_time)),
> while for pg_stat_io the timing is added to a native instr_time counter
> using ticks directly. The truncation to microseconds happens only at
> flush time, making the count more precise.
>
> Therefore, we propose changing the data type of the pg_stat_database
> counters from PgStat_Counter to instr_time. PFA a patch with the
> implementation. We decided to remove the
> pgstat_count_buffer_{write|read}_time macros since
> pgstat_count_io_op_time() was their only call site and they have
> therefore become obsolete. We also changed the data type of the local
> variables startreadtime and startwritetime to instr_time in
> heap_vacuum_rel() (vacuumlazy.c) and do_analyze_rel() (analyze.c), since
> they hold snapshots of pgStatBlockReadTime and pgStatBlockWriteTime.
> This makes the code style more consistent, and the elapsed time is
> converted directly from instr_time to milliseconds without first
> truncating it to microseconds.
>
> With the patch applied, the gap almost vanishes (separate run, so the
> absolute numbers differ):

Summary
--------------

- instr_time.h mentions that : "When summing multiple measurements,
it's recommended to leave the running sum in instr_time form (ie, use
INSTR_TIME_ADD or INSTR_TIME_ACCUM_DIFF) and convert to a result
format only at the end."
- pg_stat_io, pgBufferUsage and pgstat_function already keeps local
totals in instr_time before flushing. pg_stat_database was the odd one
out by converting to microseconds on every single 8kB block I/O.
Moving to instr_time eliminates that inconsistency.
- In pgstat_count_io_op_time(), converting each I/O duration to
microseconds via INSTR_TIME_GET_MICROSEC(io_time) required
tick-to-nanosecond scaling and integer division on every read, write,
and extend. Replacing that with INSTR_TIME_ADD() turns the per-block
accumulation into a fast 64-bit integer addition on ticks. Deferring
the microsecond conversion to pgstat_update_dbstats() (which only
fires at commit/idle or rate-limited every ~500ms) is a nice
micro-optimization for high-IOPS workloads.
- The changes in vacuumlazy.c and analyze.c also makes sense,
converting elapsed ticks directly to milliseconds with
INSTR_TIME_GET_MILLISEC().

Impact on Metrics & Upgrades
-----------------------------------------

- Catalogs and storage layouts: No changes.
PgStat_StatDBEntry.blk_read_time remains PgStat_Counter (microseconds)
in shared memory and on disk. pg_upgrade, dump/restore, and query
planning are completely unaffected.
- External log parsers: The autovacuum/vacuum log format ("I/O
timings: read: %.3f ms, write: %.3f ms") remains identical.
- Metric values for users: On modern storage (NVMe SSDs, cloud storage
with read caches), single-block I/O frequently takes sub-microsecond
or fractional microsecond times. Previously, any read under 1 µs
truncated to 0, and fractional parts were dropped on every single
read. After this patch, pg_stat_database.blk_read_time and
blk_write_time will report higher, more accurate totals.
- This also resolves the discrepancies users previously saw when
comparing pg_stat_database against pg_stat_io or pg_stat_statements.
It would be worth noting this in the release notes.



>
>        source      | ms_write | ms_read
> ------------------+----------+---------
>   pg_stat_database | 4976.780 |  35.190
>   pg_stat_io       | 4976.777 |  35.187
> (2 rows)
>
> We attribute the remaining difference to pg_stat_io truncating the time
> for every object while pg_stat_database truncates them as a sum
> (therefore cutting off less).

Comments on Patch
---------------------------

Please find some minor nits below, please consider fixing them,

1. In src/backend/utils/activity/pgstat_io.c the following comment
line is greater than 80,

* The increments to pgStatBlockWriteTime and pgStatBlockReadTime are
for pgstat_database.

2. In vacuumlazy.c (and identically in analyze.c):
// Beginning of the function
INSTR_TIME_SET_ZERO(startreadtime);
INSTR_TIME_SET_ZERO(startwritetime);

if (instrument)
{
pg_rusage_init(&ru0);
if (track_io_timing)
{
startreadtime = pgStatBlockReadTime;
startwritetime = pgStatBlockWriteTime;
}
}
.
.
.
.
.
.
.
if (track_io_timing)
{
instr_time read_time = pgStatBlockReadTime;
instr_time write_time = pgStatBlockWriteTime;

INSTR_TIME_SUBTRACT(read_time, startreadtime);
INSTR_TIME_SUBTRACT(write_time, startwritetime);

This would cause a problem if, Mid-vacuum: The DBA turns track_io_timing = on.

AI suggests following the pattern of,

WalUsage startwalusage = pgWalUsage;
BufferUsage startbufferusage = pgBufferUsage;

as a better pattern.


>
> Best regards,
> Ahmed Gouda and Bernd Reiß

Thank you,
Narayanan

>
> [1]
> https://www.postgresql.org/message-id/CAGRkXqRHsZw3+aeNZgnBYduQSY7qg1O4MBdmyFjK-A+TU1-b-A@mail.gmail.com