Use instr_time for pg_stat_database block read/write time counters
Hackorum builds and tests every patch posted to the lists, not only commitfest submissions. This is Hackorum's own CI rather than the PostgreSQL project's, and it is still under testing - please report anything that looks wrong.
You can run a PostgreSQL built from this patch straight from Docker, with no checkout and no build:
docker run --rm -p 5432:5432 ghcr.io/hackorum-dev/postgres-patch:t253968psql -h localhost -U postgresBuilt from patchset v10 (message #10), October 22, 2026 at 05:10 AM.
Every patchset is also pushed to a branch of our PostgreSQL fork, so you can check out the same tree CI built. Without a PostgreSQL checkout:
git clone --branch t253968_10 https://github.com/hackorum-dev/postgres.gitIn a checkout you already have, add the fork once:
git remote add hackorum https://github.com/hackorum-dev/postgres.gitthen, for this patchset and every later one:
git fetch hackorum t253968_10 && git checkout t253968_10Patchset v10 (message #10) is on t253968_10
Dear hackers,
While working on a review for another patch (see [1]/messages/by-id/CAGRkXqRHsZw3+aeNZgnBYduQSY7qg1O4MBdmyFjK-A+TU1-b-A@mail.gmail.com) Ahmed Gouda and I
noticed time skew in write and read times between the pg_stat_database
and pg_stat_io views.
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):
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).
Best regards,
Ahmed Gouda and Bernd Reiß
[1]: /messages/by-id/CAGRkXqRHsZw3+aeNZgnBYduQSY7qg1O4MBdmyFjK-A+TU1-b-A@mail.gmail.com
/messages/by-id/CAGRkXqRHsZw3+aeNZgnBYduQSY7qg1O4MBdmyFjK-A+TU1-b-A@mail.gmail.com
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
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@gmail.com> wrote:
Show quoted text
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]
/messages/by-id/CAGRkXqRHsZw3+aeNZgnBYduQSY7qg1O4MBdmyFjK-A+TU1-b-A@mail.gmail.com
On Mon, Sep 28, 2026 at 02:24:52PM +0200, Bernd Reiß wrote:
@@ -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)
Hmm. This part of the patch touches a performance-sensitive area.
This is exchanging one addition for another, which I doubt really
matters, but who knows.. Andres, any thoughts perhaps?
--
Michael
Hi,
On 2026-10-02 07:57:38 +0900, Michael Paquier wrote:
On Mon, Sep 28, 2026 at 02:24:52PM +0200, Bernd Reiß wrote:
@@ -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)Hmm. This part of the patch touches a performance-sensitive area.
This is exchanging one addition for another, which I doubt really
matters, but who knows.. Andres, any thoughts perhaps?
I think it should actually be a measurable win, due to getting rid of
INSTR_TIME_GET_MICROSEC(). That's a nontrivial conversion removed from the hot
path.
Doing the conversion from instr_time ticks once per stats flush, instead of
once per measurement, is a lot better.
Of course it'd be even better if would be to stop counting the same stuff in
pgBufferUsage.{shared,local}_blk_{read,write}_time and
pgStatBlock{Read,Write}Time. That's pretty darn silly.
pgstat_update_dbstats() should just keep a pgBufferUsage snapshot from the
last report and add up the relevant pgBufferUsage fields. And vacuum & analyze
already diff, so they just would need to add the fields to get the same
results.
Greetings,
Andres Freund
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't be 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.
Show quoted text
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@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]
/messages/by-id/CAGRkXqRHsZw3+aeNZgnBYduQSY7qg1O4MBdmyFjK-A+TU1-b-A@mail.gmail.com
Show quoted text
Hi Andres,
Thanks a lot for the review.
Of course it'd be even better if would be to stop counting the same
stuff in
pgBufferUsage.{shared,local}_blk_{read,write}_time and
pgStatBlock{Read,Write}Time. That's pretty darn silly.pgstat_update_dbstats() should just keep a pgBufferUsage snapshot from
the
last report and add up the relevant pgBufferUsage fields. And vacuum &
analyze
already diff, so they just would need to add the fields to get the same
results.We tried to implement this and directly use `pgBufferUsage` in
`pgstat_update_dbstats()` but we came across some issues that caused
pg_stat_database to overcount, specifically when having parallel workers in
the plan, each worker will acuumulate its own statistics in its own
`pgBufferUsage` and will report them at the end and update the db stats
entry, but the problem is after that the parent backend will also
acuumulate all the statistics from its parallel workers and add them to its
`pgBufferUsage` and update the db stats entry again hence causing each
worker's I/O write/read times to be counted twice.Meanwhile using `pgStatBlock{Read,Write}Time` in
`pg_stat_count_io_op_time()` will count every I/O timing a single time,
without having to introduce changes in the parallel worker infrasturcture
to handle the above case? Maybe thats why `pgStatBlock{Read,Write}Time` was
introduced in the beginning?Or else, would it be the right approach to look into changing the existing
infastructure for I/O time counting in the context of parallel workers in
your opinion?What do you think? Are we missing something?
Best Regards,
Ahmed Gouda and Bernd Reiß
Hi Andres,
Thanks a lot for the review, and first, please ignore the previous email;
it has bad formatting = Gmail tricked me :(.
Of course it'd be even better if would be to stop counting the same stuff
in
pgBufferUsage.{shared,local}_blk_{read,write}_time and
pgStatBlock{Read,Write}Time. That's pretty darn silly.pgstat_update_dbstats() should just keep a pgBufferUsage snapshot from the
last report and add up the relevant pgBufferUsage fields. And vacuum &
analyze
already diff, so they just would need to add the fields to get the same
results.
We tried to implement this and directly use `pgBufferUsage` in
`pgstat_update_dbstats()` but we came across some issues that caused
pg_stat_database to overcount, specifically when having parallel workers in
the plan, each worker will acuumulate its own statistics in its own
`pgBufferUsage` and will report them at the end and update the db stats
entry, but the problem is after that the parent backend will also acuumulate
all the statistics from its parallel workers and add them to its
`pgBufferUsage` and update the db stats entry again hence causing each
worker's I/O write/read times to be counted twice.
Meanwhile using `pgStatBlock{Read,Write}Time` in
`pg_stat_count_io_op_time()` will count every I/O timing a single time,
without having to introduce changes in the parallel worker infrasturcture
to handle the above case? Maybe thats why `pgStatBlock{Read,Write}Time` was
introduced in the beginning?
Or else, would it be the right approach to look into changing the existing
infastructure for I/O time counting in the context of parallel workers in
your opinion?
What do you think? Are we missing something?
Best Regards,
Ahmed Gouda and Bernd Reiß
Hi,
On 2026-10-02 20:03:24 +0300, ahmed wrote:
Thanks a lot for the review, and first, please ignore the previous email;
it has bad formatting = Gmail tricked me :(.Of course it'd be even better if would be to stop counting the same stuff
in
pgBufferUsage.{shared,local}_blk_{read,write}_time and
pgStatBlock{Read,Write}Time. That's pretty darn silly.pgstat_update_dbstats() should just keep a pgBufferUsage snapshot from the
last report and add up the relevant pgBufferUsage fields. And vacuum &analyze
already diff, so they just would need to add the fields to get the same
results.
Just to be clear, I don't think that should be done in the same commit, that'd
be separate work imo.
We tried to implement this and directly use `pgBufferUsage` in
`pgstat_update_dbstats()` but we came across some issues that caused
pg_stat_database to overcount, specifically when having parallel workers in
the plan, each worker will acuumulate its own statistics in its own
`pgBufferUsage` and will report them at the end and update the db stats
entry, but the problem is after that the parent backend will also acuumulate
all the statistics from its parallel workers and add them to its
`pgBufferUsage` and update the db stats entry again hence causing each
worker's I/O write/read times to be counted twice.
I really really dislike a lot of how the parallel worker stats stuff is done
:(. The whole idea of just mixing it into the client backends stats is just
bonkers IMO. We do it inconsistently, sometimes we then have to back out the
worker numbers again during explain. Just a bad idea overall.
I think Lukas had some WIP patches to change some of that? He might also have
some opinions independent of parallel workers, as he has pending work to
refactor things so that the explain stuff is not diff based anymore (the
diffing makes it rather expensive atm).
So maybe this is all moot - I'll let him chime in on that.
Greetings,
Andres Freund
Hi,
Rebased on master.
Best Regards,
Ahmed Gouda and Bernd Reiß
Attachments:
t253968_10v3-0001-use-instr_time-for-pg_stat_database-io-time-counters.patchtext/x-patch; charset=UTF-8; name=v3-0001-use-instr_time-for-pg_stat_database-io-time-counters.patchDownload+26-24
Hi hackers,
On 02/10/2026 01:16, Andres Freund wrote:
I think it should actually be a measurable win, due to getting rid of
INSTR_TIME_GET_MICROSEC(). That's a nontrivial conversion removed from the hot
path.
We tried to benchmark the patch vs master, using the following script:
#! /bin/bash
function bench() {
printenv PG;
pkill -9 postgres
rm -fr temp_db
$PG/initdb temp_db
$PG/pg_ctl -D temp_db -o "-c shared_buffers=128kB -c
track_io_timing=on" start
$PG/pgbench -i -s 100 postgres
$PG/pgbench -S -T 4800 postgres
}
for i in {1..5}; do
PG=base_bin bench
PG=patch_bin bench
done
We used pgbench with a single connection, a single core and tried to get
PG to do as much I/O as possible by having shared_buffers=128kB and
around 1.5GB of data.
And the results we got showed a consistent increase in tps for the
patched version of the binaries:
base_bin: tps = 13304.583036 (without initial connection time)
patch_bin: tps = 13402.525290 (without initial connection time)
base_bin: tps = 13369.510071 (without initial connection time)
patch_bin: tps = 13393.105787 (without initial connection time)
base_bin: tps = 13309.703092 (without initial connection time)
patch_bin: tps = 13440.319286 (without initial connection time)
base_bin: tps = 13363.819694 (without initial connection time)
patch_bin: tps = 13457.270677 (without initial connection time)
base_bin: tps = 13335.492459 (without initial connection time)
patch_bin: tps = 13364.938596 (without initial connection time)
MEDIAN BASE: 13335.492459 tps
MEDIAN PATCHED: 13402.525290 tps
MEAN BASE: 13336.621670 tps
MEAN PATCHED: 13411.631927 tps
Note: we tried the benchmark on different machines with different cpus
and depending on how powerful the cpu is we needed to increase the
runtime duration accordingly, i.e. -T in pgbench, to start noticing a
difference.
Best Regards,
Ahmed Gouda and Bernd Reiß
On Fri, Oct 2, 2026 at 11:40 AM Andres Freund <andres@anarazel.de> wrote:
We tried to implement this and directly use `pgBufferUsage` in
`pgstat_update_dbstats()` but we came across some issues that caused
pg_stat_database to overcount, specifically when having parallel workers in
the plan, each worker will acuumulate its own statistics in its own
`pgBufferUsage` and will report them at the end and update the db stats
entry, but the problem is after that the parent backend will also acuumulate
all the statistics from its parallel workers and add them to its
`pgBufferUsage` and update the db stats entry again hence causing each
worker's I/O write/read times to be counted twice.I really really dislike a lot of how the parallel worker stats stuff is done
:(. The whole idea of just mixing it into the client backends stats is just
bonkers IMO. We do it inconsistently, sometimes we then have to back out the
worker numbers again during explain. Just a bad idea overall.
Mhm. The way that parallel worker instrumentation is done is very
complex and brittle. It's easy to get any changes there wrong,
introducing double counting/etc.
I think Lukas had some WIP patches to change some of that? He might also have
some opinions independent of parallel workers, as he has pending work to
refactor things so that the explain stuff is not diff based anymore (the
diffing makes it rather expensive atm).So maybe this is all moot - I'll let him chime in on that.
Yeah, the stack-based instrumentation patch works some related code,
but notably I didn't touch that call to pgStatBlock(Write|Read)Time in
analyze.c/vacuumlazy.c on prior iterations.
Looking at it again, if I read this right, if we were to sum up local
and shared I/O timings (pgstat_count_io_op_time already ignores
IOOBJECT_WAL for pgstat_count_buffer_...), we should indeed get the
same measurements via the instrumentation buffer usage data, avoiding
the need to do separate diffing. I have a draft of that locally and
hoping to share this in the next few days on the existing thread for
stack-based instrumentation.
Whilst looking at this last week I also noticed a related bug with
parallel VACUUM not reporting I/O times correctly, but coincidentally
that was fixed with the independently discussed
abf5fec634f6aac98e80e2ef6c3f3dbf0133dfaa - so the remaining user of
pgStatBlock(Read|Write)Time is only ANALYZE and pg_stat_database, both
of which could switch to the stack-based approach.
Thanks,
Lukas
--
Lukas Fittl