Re: Use instr_time for pg_stat_database block read/write time counters

Hi Narayanan,

Thanks for the review.

> 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.

Nice catch!, fixed in the attached v2 patch.

> 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.

We didn't introduce this, our changes mirrored the same approach that is
currently used in the upstream code, so we can't be sure if this is
actually a bug or not, but *if it is* we believe its fix should go in
another patch.

Side note:
*if it is* actually a bug and we aren't missing something, then we think
that just switching track_io_timing to on mid-vacuum/analyze won't cause
any problems unless track_io_timing was previously on and
`pgStatBlock{Read|Write}Time` were non-zero then track_io_timing switched
to off then a vacuum/analyze started and mid-way track_io_timing was
swithced back to on with `pgStatBlock{Read|Write}Time` never getting
flushed during this, which is very very rare or even impossible to happen
in practice?

Best regards,
Ahmed Gouda and Bernd Reiß

On Wed, Sep 30, 2026 at 11:59 PM Narayanan Venkateswaran <
narayananvpostgres(at)gmail(dot)com> wrote:

> On Mon, Sep 28, 2026 at 5:55 PM Bernd Reiß <bd_reiss(at)gmx(dot)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
>