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 <
[email protected]> wrote:
> On Mon, Sep 28, 2026 at 5:55 PM Bernd Reiß <[email protected]> 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-...@mail.gmail.com
>
From a1124c805e26a3685741136ac00a0c330642e794 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Bernd=20Rei=C3=9F?= <[email protected]>
Date: Mon, 28 Sep 2026 13:29:57 +0300
Subject: [PATCH v2] Use instr_time for pg_stat_database block read/write time
counters
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
The write and read times reported by pg_stat_database are imprecise due
to pg_stat_database truncating the time to microseconds and adding them
to a PgStat_Counter on accumulation.
This patch increases the precision by changing the data type of
pgStatBlockReadTime and pgStatBlockWriteTime from PgStat_Counter to
instr_time, therefore using ticks to accumulate time and only
truncating at flush time.
The patch also removes the pgstat_count_buffer_{write|read}_time(n)
macros, since pgstat_count_io_op_time() was their only call site and
they have therefore become obsolete. The data type of the local
variables startreadtime and startwritetime in heap_vacuum_rel()
(vacuumlazy.c) and do_analyze_rel() (analyze.c) is changed to
instr_time as well, since the variables 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.
Author: Bernd Reiß <[email protected]>
Author: Ahmed Gouda <[email protected]>
---
src/backend/access/heap/vacuumlazy.c | 18 +++++++++++++-----
src/backend/commands/analyze.c | 17 ++++++++++++-----
src/backend/utils/activity/pgstat_database.c | 12 ++++++------
src/backend/utils/activity/pgstat_io.c | 10 +++++-----
src/include/pgstat.h | 10 +++-------
5 files changed, 39 insertions(+), 28 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8e1f660bc2f..9b00395549d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -636,8 +636,8 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
new_rel_allfrozen;
PGRUsage ru0;
TimestampTz starttime = 0;
- PgStat_Counter startreadtime = 0,
- startwritetime = 0;
+ instr_time startreadtime,
+ startwritetime;
WalUsage startwalusage = pgWalUsage;
BufferUsage startbufferusage = pgBufferUsage;
ErrorContextCallback errcallback;
@@ -647,6 +647,10 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
verbose = (params->options & VACOPT_VERBOSE) != 0;
instrument = (verbose || (AmAutoVacuumWorkerProcess() &&
params->log_vacuum_min_duration >= 0));
+
+ INSTR_TIME_SET_ZERO(startreadtime);
+ INSTR_TIME_SET_ZERO(startwritetime);
+
if (instrument)
{
pg_rusage_init(&ru0);
@@ -1176,11 +1180,15 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params,
}
if (track_io_timing)
{
- double read_ms = (double) (pgStatBlockReadTime - startreadtime) / 1000;
- double write_ms = (double) (pgStatBlockWriteTime - startwritetime) / 1000;
+ instr_time read_time = pgStatBlockReadTime;
+ instr_time write_time = pgStatBlockWriteTime;
+
+ INSTR_TIME_SUBTRACT(read_time, startreadtime);
+ INSTR_TIME_SUBTRACT(write_time, startwritetime);
appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"),
- read_ms, write_ms);
+ INSTR_TIME_GET_MILLISEC(read_time),
+ INSTR_TIME_GET_MILLISEC(write_time));
}
if (secs_dur > 0 || usecs_dur > 0)
{
diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c
index c05f9f50e43..3d1ecceeb07 100644
--- a/src/backend/commands/analyze.c
+++ b/src/backend/commands/analyze.c
@@ -335,8 +335,8 @@ do_analyze_rel(Relation onerel, const VacuumParams *params,
WalUsage startwalusage = pgWalUsage;
BufferUsage startbufferusage = pgBufferUsage;
BufferUsage bufferusage;
- PgStat_Counter startreadtime = 0;
- PgStat_Counter startwritetime = 0;
+ instr_time startreadtime;
+ instr_time startwritetime;
verbose = (params->options & VACOPT_VERBOSE) != 0;
instrument = (verbose || (AmAutoVacuumWorkerProcess() &&
@@ -352,6 +352,9 @@ do_analyze_rel(Relation onerel, const VacuumParams *params,
get_namespace_name(RelationGetNamespace(onerel)),
RelationGetRelationName(onerel))));
+ INSTR_TIME_SET_ZERO(startreadtime);
+ INSTR_TIME_SET_ZERO(startwritetime);
+
/*
* Set up a working context so that we can easily free whatever junk gets
* created.
@@ -829,11 +832,15 @@ do_analyze_rel(Relation onerel, const VacuumParams *params,
}
if (track_io_timing)
{
- double read_ms = (double) (pgStatBlockReadTime - startreadtime) / 1000;
- double write_ms = (double) (pgStatBlockWriteTime - startwritetime) / 1000;
+ instr_time read_time = pgStatBlockReadTime;
+ instr_time write_time = pgStatBlockWriteTime;
+
+ INSTR_TIME_SUBTRACT(read_time, startreadtime);
+ INSTR_TIME_SUBTRACT(write_time, startwritetime);
appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"),
- read_ms, write_ms);
+ INSTR_TIME_GET_MILLISEC(read_time),
+ INSTR_TIME_GET_MILLISEC(write_time));
}
appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
read_rate, write_rate);
diff --git a/src/backend/utils/activity/pgstat_database.c b/src/backend/utils/activity/pgstat_database.c
index 7f3bc016593..58981602f7b 100644
--- a/src/backend/utils/activity/pgstat_database.c
+++ b/src/backend/utils/activity/pgstat_database.c
@@ -25,8 +25,8 @@
static bool pgstat_should_report_connstat(void);
-PgStat_Counter pgStatBlockReadTime = 0;
-PgStat_Counter pgStatBlockWriteTime = 0;
+instr_time pgStatBlockReadTime;
+instr_time pgStatBlockWriteTime;
PgStat_Counter pgStatActiveTime = 0;
PgStat_Counter pgStatTransactionIdleTime = 0;
SessionEndType pgStatSessionEndCause = DISCONNECT_NORMAL;
@@ -349,8 +349,8 @@ pgstat_update_dbstats(TimestampTz ts)
*/
dbentry->xact_commit += pgStatXactCommit;
dbentry->xact_rollback += pgStatXactRollback;
- dbentry->blk_read_time += pgStatBlockReadTime;
- dbentry->blk_write_time += pgStatBlockWriteTime;
+ dbentry->blk_read_time += INSTR_TIME_GET_MICROSEC(pgStatBlockReadTime);
+ dbentry->blk_write_time += INSTR_TIME_GET_MICROSEC(pgStatBlockWriteTime);
if (pgstat_should_report_connstat())
{
@@ -370,8 +370,8 @@ pgstat_update_dbstats(TimestampTz ts)
pgStatXactCommit = 0;
pgStatXactRollback = 0;
- pgStatBlockReadTime = 0;
- pgStatBlockWriteTime = 0;
+ INSTR_TIME_SET_ZERO(pgStatBlockReadTime);
+ INSTR_TIME_SET_ZERO(pgStatBlockWriteTime);
pgStatActiveTime = 0;
pgStatTransactionIdleTime = 0;
}
diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c
index 8ec1aad5078..1ce9bb52e1d 100644
--- a/src/backend/utils/activity/pgstat_io.c
+++ b/src/backend/utils/activity/pgstat_io.c
@@ -102,9 +102,9 @@ pgstat_prepare_io_time(bool track_io_guc)
/*
* Like pgstat_count_io_op() except it also accumulates time.
*
- * The calls related to pgstat_count_buffer_*() are for pgstat_database. As
- * pg_stat_database only counts block read and write times, these are done for
- * IOOP_READ, IOOP_WRITE and IOOP_EXTEND.
+ * The increments to pgStatBlockWriteTime and pgStatBlockReadTime are for
+ * pg_stat_database. As pg_stat_database only counts block read and write
+ * times, these are done for IOOP_READ, IOOP_WRITE and IOOP_EXTEND.
*
* pgBufferUsage is used for EXPLAIN. pgBufferUsage has write and read stats
* for shared, local and temporary blocks. pg_stat_io does not track the
@@ -125,7 +125,7 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
{
if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND)
{
- pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time));
+ INSTR_TIME_ADD(pgStatBlockWriteTime, io_time);
if (io_object == IOOBJECT_RELATION)
INSTR_TIME_ADD(pgBufferUsage.shared_blk_write_time, io_time);
else if (io_object == IOOBJECT_TEMP_RELATION)
@@ -133,7 +133,7 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op,
}
else if (io_op == IOOP_READ)
{
- pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time));
+ INSTR_TIME_ADD(pgStatBlockReadTime, io_time);
if (io_object == IOOBJECT_RELATION)
INSTR_TIME_ADD(pgBufferUsage.shared_blk_read_time, io_time);
else if (io_object == IOOBJECT_TEMP_RELATION)
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 187d82c96fe..eeb70321ebf 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -739,10 +739,6 @@ extern void pgstat_report_connect(Oid dboid);
extern void pgstat_update_parallel_workers_stats(PgStat_Counter workers_to_launch,
PgStat_Counter workers_launched);
-#define pgstat_count_buffer_read_time(n) \
- (pgStatBlockReadTime += (n))
-#define pgstat_count_buffer_write_time(n) \
- (pgStatBlockWriteTime += (n))
#define pgstat_count_conn_active_time(n) \
(pgStatActiveTime += (n))
#define pgstat_count_conn_txn_idle_time(n) \
@@ -981,9 +977,9 @@ extern PGDLLIMPORT PgStat_CheckpointerStats PendingCheckpointerStats;
* Variables in pgstat_database.c
*/
-/* Updated by pgstat_count_buffer_*_time macros */
-extern PGDLLIMPORT PgStat_Counter pgStatBlockReadTime;
-extern PGDLLIMPORT PgStat_Counter pgStatBlockWriteTime;
+/* Updated by pgstat_count_io_op_time() */
+extern PGDLLIMPORT instr_time pgStatBlockReadTime;
+extern PGDLLIMPORT instr_time pgStatBlockWriteTime;
/*
* Updated by pgstat_count_conn_*_time macros, called by
--
2.43.0
