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

Hi,

On Thu, Oct 1, 2026 at 6:36 PM ahmed <gouda0x@gmail.com> wrote:
>
>
> 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.

Thank you very much for the work and addressing the comments. I don't
have any other comments on your code.

>
> > 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'tbe sure if this is actually a bug or not, but *if it is* we believe its fix should go in another patch. 

I see, Let us also wait to see other opinions here.

>
> 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/analyzewon't cause any problems unless track_io_timing was previously on and `pgStatBlock{Read|Write}Time`
werenon-zero then track_io_timing switched to off then a vacuum/analyze started and mid-way track_io_timing was
swithcedback to on with `pgStatBlock{Read|Write}Time` never getting flushed during this, which is very very rare or
evenimpossible to happen in practice? 
>
> Best regards,
> Ahmed Gouda and Bernd Reiß
>
> On Wed, Sep 30, 2026 at 11:59 PM Narayanan Venkateswaran <narayananvpostgres@gmail.com> wrote:
>>
>> 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