Use instr_time for pg_stat_database block read/write time counters

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.

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]
https://www.postgresql.org/message-id/CAGRkXqRHsZw3+aeNZgnBYduQSY7qg1O4MBdmyFjK-A+TU1-b-A@mail.gmail.com