On Mon, Jan 26, 2026 at 4:08 PM Andres Freund <[email protected]> wrote: > > Hi, > > On 2026-01-26 10:40:52 +0100, Jakub Wartak wrote: > > I'm proposing that we add pg_stat_io_histogram that would track/show I/O > > latencies profile, so we could quickly identify I/O outliers. > > I think that's an interesting feature!
Hi Andres, thanks for kind words and review!
[..]
>
> For measuring particularly stuck things, I've been wondering about having
a
> regular timer that starts to collect more information if stuck in a place
for
> a while. That would probably end up being lower overhead than constantly
> measuring... But it would also be a lot more work.
Well if something is really stuck, I think the wait events are covering us
on that,
aren't they? One can argue if they carry enough information (for me they
mostly
do, but I'm trying to squeeze some more stuff into them in a nearby thread
[1],
BTW: it's kind of "blocked" due to that 56-bit relfilenode idea/question,
any thoughts on that?)
> > Right now the patch does not include per-backend/PID tracking,
hopefully if
> > there will be interest in this, I'll add it, but I would like to first
hear
> > if that's a good idea. The current implementation uses fast bucket
> > calculation to avoid overheads and tries to cover most useful range of
> > devices via buckets (128us..256ms, so that covers both NVMe/SSD/HDD and
> > abnormally high latency too as from time to time I'm try to help with
I/O
> > stuck for *seconds*, usually a sign of some I/O multipath issues, device
> > resetting, or hypervisor woes).
>
> Hm. Isn't 128us a pretty high floor for at least reads and writes? On a
good
> NVMe disk you'll get < 10us, after all.
I was blind and concentrated way too much on the bad-behaving I/O rather
than good
I/O - let's call it I/O negativity bias 8)
Now v2 contains the min bucket lowered to 8us (but max then is just ~131ms,
I
didn't want it to use more than 64b total, 16*4b (uint32)=64b and well
16*8b(uint64)=128b already, so that's why it's capped max at 131072us right
now).
> I see a few problems with the source of the latency measurements though:
>
> - The latency gathered is that it's quite heavily affected by scheduler
> noise. If your process isn't scheduled because other processes are busy
> doing stuff on the CPU, it's quite possible to get results many orders
of
> magnitude wrong.
>
> - With AIO, you're measuring wait time, and that time can be affected by
other
> IOs in the queue. That will often *drastically* overestimate IO latency
> measured this way.
>
> I don't see how we can do better absent cooperation from the kernel (by
> putting lower-level measurements into io_uring completions, for example)
> though. So maybe this is just how it has to be and we ought to just
document
> it.
Right, I think this is a complex topic on it's own, I've added a small
section into
the docs. I didn't want to start the thread with undermining my own
results, but
indeed I'm getting "bad" numbers. Bad in essence that perceived latency
numbers do not match with other stuff:
E.g.checkpointer's fsync/fdatasync latency is awful, although i've been
using
this to simulate latency (just 2ms!, but it ended up adding way more):
dd if=/dev/zero of=/fs bs=1M count=1024
losetup /dev/loop15 /fs
echo "0 $(blockdev --getsz /dev/loop15) delay /dev/loop15 0 2" | \
dmsetup create delay
mkfs.ext4 /dev/mapper/delay
mount /dev/mapper/delay /mnt
... and it has e.g. quite interesting effects:
- lack of "noatime" the impact is clearly visible on fsync
- even with noatime I'm was getting spikes of latenices above 131ms
(sic!) with this:
select pg_stat_reset_shared();
pgbench -i -s 10 -p 1234 -h /tmp postgres
checkpoint;
- I've created attached bpftrace to see the gap between kernel and uprobes,
but
it's not that high, sample of the view
backend | object | context | io_type | lat_us | lat_ms | count
----------+----------+---------+-----------+--------+---------+-------
checkpoi | relation | normal | fsync | 32768 | 32.768 | 42
checkpoi | relation | normal | fsync | 65536 | 65.536 | 3
checkpoi | relation | normal | fsync | 262144 | 262.144 | 1
vs eBPF, which does not seem to see that, worst case seem to be like
wasted
~20us (gap is between user and kernel)
[fdatasync] PID 54197 | Kernel: 12943 us | User: 12964 us | Lag: 21us
[..but usually it's just:]
[ fsync] PID 52266 | Kernel: 1711 us | User: 1714 us | Lag: 3us
[ fsync] PID 52266 | Kernel: 19913 us | User: 19916 us | Lag: 3us
[ fsync] PID 52266 | Kernel: 1993 us | User: 1996 us | Lag: 3us
[ fsync] PID 52266 | Kernel: 1994 us | User: 1995 us | Lag: 1us
[ fsync] PID 52266 | Kernel: 53734 us | User: 53736 us | Lag: 2us
[ fsync] PID 52266 | Kernel: 8066 us | User: 8072 us | Lag: 6us
[ fsync] PID 52266 | Kernel: 2107 us | User: 2109 us | Lag: 2us
[ fsync] PID 52266 | Kernel: 1972 us | User: 1974 us | Lag: 2us
(this is on 2ms delayed + noatime fs + with CONFIG_HZ=1000 + laptop's
NVMe
that's idle).
- in mdsyncfiletag() we seem to have pgstat_count_io_op_time() *after*
potential
FileClose(), but I haven't witnessed long close(), it's still
context-switch
- I've spotted that power mgmt might be influencing it even further (but
that's not
in the docs yet, dunno if I should add it there like the next item on the
list)
> > backend | object | context | io_type | lat_us | lat_ms | count
> > ----------+----------+-----------+-----------+--------+--------+-------
> > autovacu | relation | normal | read | 128 | 0.128 | 54
>
> Perhaps the latency should be represented as a range?
Cool idea, I haven't even thought about this one! From now v2 shows:
postgres=# select
substring(backend_type,1,8) as btype,
object, context, io_type, bucket_latency_us as lat_us, bucket_count as
cnt
from pg_stat_get_io_histogram()
where
bucket_count > 0
order by 1,2,3,4,5 ;
btype | object | context | io_type | lat_us | cnt
----------+----------+---------+-----------+-------------+-----
[..]
checkpoi | relation | normal | write | [0,9) | 33
checkpoi | relation | normal | write | [8,17) | 8
checkpoi | relation | normal | write | [16,33) | 1
> > Of course most of the I/O calls today are hitting page cache, so one
would
> > expect they'll be < 128us most of the time
>
> Have you measured whether overhead is measurable when hitting the page
cache?
> I'd hope that it doesn't, due to io combing amortizing the cost somewhat.
But
> it seems worth measuring.
Not yet, I first wanted to hear if I'm not sailing into some plain stupid
direction somewhere with this idea or implementation (e.g.
that INSTR_TIME_GET_MICROSEC() was a really stupid omission from my side).
I'll try to perform this test overhead measurement hopefully with v3 once
we settle on how to do that bit shifting/clz().
> I assume you made pgstat_get_io_op_name() return "hit?" because you don't
> expect that to ever be hit?
Yes, my patch seems to always return 0 for "hit?". I'll need to investigate
that
further.
> > +static inline int get_bucket_index(uint32_t val) {
> > +#define MIN_PG_STAT_IO_HIST_LATENCY 127
> > + const uint32_t max_index = PGSTAT_IO_HIST_BUCKETS - 1;
> > + /*
> > + * hopefully calculated to be 25 by the compiler:
> > + * clz(127) = clz(01111111b on uint32) = 25
> > + */
> > + const uint32_t min_latency_leading_zeros =
> > + pg_leading_zero_bits32(MIN_PG_STAT_IO_HIST_LATENCY);
> > +
> > + /*
> > + * make sure the tmp value at least 127 (our minimum bucket size)
> > + * as __builtin_clz might return undefined behavior when
operating on 0
> > + */
> > + uint32_t tmp = val | MIN_PG_STAT_IO_HIST_LATENCY;
>
> > + /* count leading zeros */
> > + int leading_zeros = pg_leading_zero_bits32(tmp);
> > +
> > + /* normalize the index */
> > + uint32_t index = min_latency_leading_zeros - leading_zeros;
> > +
> > + /* clamp it to the maximum */
> > + return (index > max_index) ? max_index : index;
> > +}
>
> Wouldn't it be easier to handle the minimum latency by shifting right?
What you seem to suggest seems to be equally width buckets {1,2,3,4..ms} and
not logarithmic buckets {1,2,4,8..ms} or am I missing something? The patch
as is
stands has two ways #ifdef implementations now, with bitwise shifting
working
now, but even in objdump on -O2 there's plenty of those jumps because of
current
code.
> I think we may also need to handle inputs that don't fit a uint32.
Fixed.
> [..] For things
> like a stopped VM or such we could see IOs that that don't fit into a
uint32
> when measured in microseconds. So perhaps I'd make the input to the
bucket
> calc 64 bits, then shift to the minimum precision and mask to implement
> clamping.
> > @@ -152,6 +189,10 @@ pgstat_count_io_op_time(IOObject io_object,
IOContext io_context, IOOp io_op,
> >
INSTR_TIME_ADD(PendingIOStats.pending_times[io_object][io_context][io_op],
> > io_time);
> >
> > + /* calculate the bucket_index based on latency in us */
> > + bucket_index =
get_bucket_index(INSTR_TIME_GET_MICROSEC(io_time));
> > +
PendingIOStats.pending_hist_time_buckets[io_object][io_context][io_op][bucket_index]++;
> > +
> > /* Add the per-backend count */
> > pgstat_count_backend_io_op_time(io_object, io_context,
io_op,
>
> It's annoying to have to convert to microseconds here, that's not free :(.
Oooops, fixed, get_bucket_index() now operates directly on nanos/int64.
[..]
> > + HIST_IO_COL_COUNT,
> > + HIST_IO_COL_RESET_TIME,
> > + HIST_IO_NUM_COLUMNS
> > +} history_get_history_state;
>
]> Think the IO_NUM_COLUMNS reference in the comment is a copy-pasto. I
don't
> think this should be introduced in the middle of the pg_stat_io
implementation.
Right, I've moved it to just before pg_stat_io_histogram_build_tuples().
>
> > +/*
> > + * pg_leading_zero_bits32
> > + * Returns the number of leading 0-bits in x, starting at
the most significant bit position.
> > + * Word must not be 0 (as it is undefined behavior).
> > + */
> > +static inline int
> > +pg_leading_zero_bits32(uint32 word)
>
> Do we really need this in addition to the already existing
> pg_leftmost_one_pos32()? Particularly because that already has an msvc
> implementation...
Well, I would be all in for removal , but please see above the
get_bucket_index() discussion.
I've tried to get rid of it (but maybe i misunderstood something), but in
the end I think it is more
elegant/faster to have it there so that code in get_bucket_index() stays
more readable, rather
than throw more bitwise voodoo there(?)
-J.
[1] -
https://www.postgresql.org/message-id/CAKZiRmyZzmOODYS6n8mns9zN4RcS3o9kfrdQDyeRupqaGp9PmQ%40mail.gmail.com
From 9ac0f319e8a94aee2c2d73e84f90138898cc3b6e Mon Sep 17 00:00:00 2001 From: Jakub Wartak <[email protected]> Date: Fri, 23 Jan 2026 08:10:09 +0100 Subject: [PATCH v2] Add pg_stat_io_histogram view to provide more detailed insight into IO profile pg_stat_io_histogram displays a histogram of IO latencies for specific backend_type, object, context and io_type. The histogram has buckets that allow faster identification of I/O latency outliers due to faulty hardware and/or misbehaving I/O stack. Such I/O outliers e.g. slow fsyncs could sometimes cause intermittent issues e.g. for COMMIT or affect the synchronous standbys performance. Author: Jakub Wartak <[email protected]> Reviewed-by: Andres Freund <[email protected]> Reviewed-by: Discussion: https://postgr.es/m/CAKZiRmwvE4uJLKTgPXeBA4m%2Bd4tTghayoefcaM9%3Dz3_S7i72GA%40mail.gmail.com --- doc/src/sgml/config.sgml | 12 +- doc/src/sgml/monitoring.sgml | 270 ++++++++++++++++++++++++- doc/src/sgml/wal.sgml | 5 +- src/backend/catalog/system_views.sql | 11 + src/backend/utils/activity/pgstat_io. | 0 src/backend/utils/activity/pgstat_io.c | 97 +++++++++ src/backend/utils/adt/pgstatfuncs.c | 146 +++++++++++++ src/include/catalog/pg_proc.dat | 9 + src/include/pgstat.h | 14 ++ src/include/port/pg_bitutils.h | 27 +++ src/test/regress/expected/rules.out | 8 + src/test/regress/expected/stats.out | 23 +++ src/test/regress/sql/stats.sql | 15 ++ 13 files changed, 630 insertions(+), 7 deletions(-) create mode 100644 src/backend/utils/activity/pgstat_io. diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 5560b95ee60..614af387ee5 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8729,9 +8729,11 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; displayed in <link linkend="monitoring-pg-stat-database-view"> <structname>pg_stat_database</structname></link>, <link linkend="monitoring-pg-stat-io-view"> - <structname>pg_stat_io</structname></link> (if <varname>object</varname> - is not <literal>wal</literal>), in the output of the - <link linkend="pg-stat-get-backend-io"> + <structname>pg_stat_io</structname></link> and + <link linkend="monitoring-pg-stat-io-histogram-view"> + <structname>pg_stat_io_histogram</structname></link> + (if <varname>object</varname> is not <literal>wal</literal>), + in the output of the <link linkend="pg-stat-get-backend-io"> <function>pg_stat_get_backend_io()</function></link> function (if <varname>object</varname> is not <literal>wal</literal>), in the output of <xref linkend="sql-explain"/> when the <literal>BUFFERS</literal> @@ -8761,7 +8763,9 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; measure the overhead of timing on your system. I/O timing information is displayed in <link linkend="monitoring-pg-stat-io-view"> - <structname>pg_stat_io</structname></link> for the + <structname>pg_stat_io</structname></link> and + <link linkend="monitoring-pg-stat-io-histogram-view"> + <structname>pg_stat_io_histogram</structname></link> for the <varname>object</varname> <literal>wal</literal> and in the output of the <link linkend="pg-stat-get-backend-io"> <function>pg_stat_get_backend_io()</function></link> function for the diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 88450facebd..f8ce9f91ba2 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -493,6 +493,17 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser </entry> </row> + <row> + <entry><structname>pg_stat_io_histogram</structname><indexterm><primary>pg_stat_io_histogram</primary></indexterm></entry> + <entry> + One row for each combination of backend type, context, target object, + IO operation type and latency bucket (in microseconds) containing + cluster-wide I/O statistics. + See <link linkend="monitoring-pg-stat-io-histogram-view"> + <structname>pg_stat_io_histogram</structname></link> for details. + </entry> + </row> + <row> <entry><structname>pg_stat_replication_slots</structname><indexterm><primary>pg_stat_replication_slots</primary></indexterm></entry> <entry>One row per replication slot, showing statistics about the @@ -690,7 +701,7 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser <para> The <structname>pg_stat_io</structname> and - <structname>pg_statio_</structname> set of views are useful for determining + <structname>pg_statio_histogram</structname> set of views are useful for determining the effectiveness of the buffer cache. They can be used to calculate a cache hit ratio. Note that while <productname>PostgreSQL</productname>'s I/O statistics capture most instances in which the kernel was invoked in order @@ -699,6 +710,8 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser Users are advised to use the <productname>PostgreSQL</productname> statistics views in combination with operating system utilities for a more complete picture of their database's I/O performance. + Furthermore the <structname>pg_stat_io_histogram</structname> view can be helpful + identifing latency outliers for specific I/O operations. </para> </sect2> @@ -3118,6 +3131,261 @@ description | Waiting for a newly initialized WAL file to reach durable storage </sect2> + <sect2 id="monitoring-pg-stat-io-histogram-view"> + <title><structname>pg_stat_io</structname></title> + + <indexterm> + <primary>pg_stat_io_histogram</primary> + </indexterm> + + <para> + The <structname>pg_stat_io_histogram</structname> view will contain one row for each + combination of backend type, target I/O object, and I/O context, IO operation + type, bucket latency cluster-wide I/O statistics. Combinations which do not make sense + are omitted. + </para> + + <para> + The view shows measured perceived I/O latency by the backend, not the kernel or device + one. This is important distinction when troubleshooting, as the I/O latency observed by + the backend might get affected by: + <itemizedlist> + <listitem> + <para>OS scheduler decisions and available CPU resources.</para> + <para>With AIO, it might include time to service other IOs from the queue. That will often inflate IO latency.</para> + <para>In case of writing, additional filesystem journaling operations.</para> + </listitem> + </itemizedlist> + </para> + + <para> + Currently, I/O on relations (e.g. tables, indexes) and WAL activity are + tracked. However, relation I/O which bypasses shared buffers + (e.g. when moving a table from one tablespace to another) is currently + not tracked. + </para> + + <table id="pg-stat-io-histogram-view" xreflabel="pg_stat_io"> + <title><structname>pg_stat_io_histogram</structname> View</title> + <tgroup cols="1"> + <thead> + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + Column Type + </para> + <para> + Description + </para> + </entry> + </row> + </thead> + <tbody> + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + <structfield>backend_type</structfield> <type>text</type> + </para> + <para> + Type of backend (e.g. background worker, autovacuum worker). See <link + linkend="monitoring-pg-stat-activity-view"> + <structname>pg_stat_activity</structname></link> for more information + on <varname>backend_type</varname>s. Some + <varname>backend_type</varname>s do not accumulate I/O operation + statistics and will not be included in the view. + </para> + </entry> + </row> + + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + <structfield>object</structfield> <type>text</type> + </para> + <para> + Target object of an I/O operation. Possible values are: + <itemizedlist> + <listitem> + <para> + <literal>relation</literal>: Permanent relations. + </para> + </listitem> + <listitem> + <para> + <literal>temp relation</literal>: Temporary relations. + </para> + </listitem> + <listitem> + <para> + <literal>wal</literal>: Write Ahead Logs. + </para> + </listitem> + </itemizedlist> + </para> + </entry> + </row> + + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + <structfield>context</structfield> <type>text</type> + </para> + <para> + The context of an I/O operation. Possible values are: + </para> + <itemizedlist> + <listitem> + <para> + <literal>normal</literal>: The default or standard + <varname>context</varname> for a type of I/O operation. For + example, by default, relation data is read into and written out from + shared buffers. Thus, reads and writes of relation data to and from + shared buffers are tracked in <varname>context</varname> + <literal>normal</literal>. + </para> + </listitem> + <listitem> + <para> + <literal>init</literal>: I/O operations performed while creating the + WAL segments are tracked in <varname>context</varname> + <literal>init</literal>. + </para> + </listitem> + <listitem> + <para> + <literal>vacuum</literal>: I/O operations performed outside of shared + buffers while vacuuming and analyzing permanent relations. Temporary + table vacuums use the same local buffer pool as other temporary table + I/O operations and are tracked in <varname>context</varname> + <literal>normal</literal>. + </para> + </listitem> + <listitem> + <para> + <literal>bulkread</literal>: Certain large read I/O operations + done outside of shared buffers, for example, a sequential scan of a + large table. + </para> + </listitem> + <listitem> + <para> + <literal>bulkwrite</literal>: Certain large write I/O operations + done outside of shared buffers, such as <command>COPY</command>. + </para> + </listitem> + </itemizedlist> + </entry> + </row> + + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + <structfield>io_type</structfield> <type>text</type> + </para> + <para> + Type of IO operation. Possible values are: FIXME! + </para> + </entry> + </row> + + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + <structfield>bucket_latency_us</structfield> <type>int4range</type> + </para> + <para> + The latency bucket (in microseconds). + </para> + </entry> + </row> + + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + <structfield>bucket_count</structfield> <type>bigint</type> + </para> + <para> + Numer of times latency of the I/O operation hit this specific bucket (with + up to <varname>bucket_latency_us</varname> microseconds). + </para> + </entry> + </row> + + <row> + <entry role="catalog_table_entry"> + <para role="column_definition"> + <structfield>stats_reset</structfield> <type>timestamp with time zone</type> + </para> + <para> + Time at which these statistics were last reset. + </para> + </entry> + </row> + </tbody> + </tgroup> + </table> + + <para> + Some backend types never perform I/O operations on some I/O objects and/or + in some I/O contexts. These rows are omitted from the view. For example, the + checkpointer does not checkpoint temporary tables, so there will be no rows + for <varname>backend_type</varname> <literal>checkpointer</literal> and + <varname>object</varname> <literal>temp relation</literal>. + </para> + + <para> + In addition, some I/O operations will never be performed either by certain + backend types or on certain I/O objects and/or in certain I/O contexts. + These cells will be NULL. For example, temporary tables are not + <literal>fsync</literal>ed, so <varname>fsyncs</varname> will be NULL for + <varname>object</varname> <literal>temp relation</literal>. Also, the + background writer does not perform reads, so <varname>reads</varname> will + be NULL in rows for <varname>backend_type</varname> <literal>background + writer</literal>. + </para> + + <para> + For the <varname>object</varname> <literal>wal</literal>, + <varname>fsyncs</varname> and <varname>fsync_time</varname> track the + fsync activity of WAL files done in <function>issue_xlog_fsync</function>. + <varname>writes</varname> and <varname>write_time</varname> + track the write activity of WAL files done in + <function>XLogWrite</function>. + See <xref linkend="wal-configuration"/> for more information. + </para> + + <para> + <structname>pg_stat_io_histogram</structname> can be used to identify + I/O storage issues + For example: + <itemizedlist> + <listitem> + <para> + Presence of abnormally high latency for <varname>fsyncs</varname> might + indicate I/O saturation, oversubscription or hardware connectivity issues. + </para> + </listitem> + <listitem> + <para> + Unusually high latency for <varname>fsyncs</varname> on standby's startup + backend type, might be responsible for high duration of commits in + synchronous replication setups. + </para> + </listitem> + </itemizedlist> + </para> + + <note> + <para> + Columns tracking I/O wait time will only be non-zero when + <xref linkend="guc-track-io-timing"/> is enabled. The user should be + careful when referencing these columns in combination with their + corresponding I/O operations in case <varname>track_io_timing</varname> + was not enabled for the entire time since the last stats reset. + </para> + </note> + </sect2> + <sect2 id="monitoring-pg-stat-bgwriter-view"> <title><structname>pg_stat_bgwriter</structname></title> diff --git a/doc/src/sgml/wal.sgml b/doc/src/sgml/wal.sgml index f3b86b26be9..8b8c407e69f 100644 --- a/doc/src/sgml/wal.sgml +++ b/doc/src/sgml/wal.sgml @@ -832,8 +832,9 @@ of times <function>XLogWrite</function> writes and <function>issue_xlog_fsync</function> syncs WAL data to disk are also counted as <varname>writes</varname> and <varname>fsyncs</varname> - in <structname>pg_stat_io</structname> for the <varname>object</varname> - <literal>wal</literal>, respectively. + in <structname>pg_stat_io</structname> and + <structname>pg_stat_io_histogram</structname> for the + <varname>object</varname> <literal>wal</literal>, respectively. </para> <para> diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 7553f31fef0..c44c4167646 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -1219,6 +1219,17 @@ SELECT b.stats_reset FROM pg_stat_get_io() b; +CREATE VIEW pg_stat_io_histogram AS +SELECT + b.backend_type, + b.object, + b.context, + b.io_type, + b.bucket_latency_us, + b.bucket_count, + b.stats_reset +FROM pg_stat_get_io_histogram() b; + CREATE VIEW pg_stat_wal AS SELECT w.wal_records, diff --git a/src/backend/utils/activity/pgstat_io. b/src/backend/utils/activity/pgstat_io. new file mode 100644 index 00000000000..e69de29bb2d diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c index 28de24538dc..c35124109a3 100644 --- a/src/backend/utils/activity/pgstat_io.c +++ b/src/backend/utils/activity/pgstat_io.c @@ -107,6 +107,66 @@ pgstat_prepare_io_time(bool track_io_guc) return io_start; } +#if 0 +static inline int get_bucket_index(uint32_t val) { +#define MIN_PG_STAT_IO_HIST_LATENCY 127 + const uint32_t max_index = PGSTAT_IO_HIST_BUCKETS - 1; + /* + * hopefully calculated to be 25 by the compiler: + * clz(127) = clz(01111111b on uint32) = 25 + */ + const uint32_t min_latency_leading_zeros = + pg_leading_zero_bits32(MIN_PG_STAT_IO_HIST_LATENCY); + + /* + * make sure the tmp value at least 127 (our minimum bucket size) + * as __builtin_clz might return undefined behavior when operating on 0 + */ + uint32_t tmp = val | MIN_PG_STAT_IO_HIST_LATENCY; + + /* count leading zeros */ + int leading_zeros = pg_leading_zero_bits32(tmp); + + /* normalize the index */ + uint32_t index = min_latency_leading_zeros - leading_zeros; + + /* clamp it to the maximum */ + return (index > max_index) ? max_index : index; +} +#else +/* + * Calculate bucket index based on value in microseconds. We have up to + * PGSTAT_IO_HIST_BUCKETS buckets. + * If < 8 (2^3) -> bucket 0 + * If < 16 (2^4) -> bucket 1 + * .. + */ +static inline int +get_bucket_index(uint64_t ns) { + uint8_t bucket = 0, result; + uint64_t temp = ns; + + /* Find Most Significant Bit (Log2) using manual shifts */ + if (temp >= 65536) { temp >>= 16; bucket += 16; } + if (temp >= 256) { temp >>= 8; bucket += 8; } + if (temp >= 16) { temp >>= 4; bucket += 4; } + if (temp >= 4) { temp >>= 2; bucket += 2; } + if (temp >= 2) { temp >>= 1; bucket += 1; } + +#define MIN_BUCKET_POW 12 + /* Clamp to our baseline of 8192ns = 2^13, so everything below should be + * put into bucket 0. + */ + if (bucket <= MIN_BUCKET_POW) + return 0; + else + result = bucket - MIN_BUCKET_POW; + + /* Finally ensure we are within proper 0-15 range */ + return (result > PGSTAT_IO_HIST_BUCKETS-1) ? PGSTAT_IO_HIST_BUCKETS-1 : result; +} +#endif + /* * Like pgstat_count_io_op() except it also accumulates time. * @@ -125,6 +185,7 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, if (!INSTR_TIME_IS_ZERO(start_time)) { instr_time io_time; + int bucket_index; INSTR_TIME_SET_CURRENT(io_time); INSTR_TIME_SUBTRACT(io_time, start_time); @@ -152,6 +213,10 @@ pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, INSTR_TIME_ADD(PendingIOStats.pending_times[io_object][io_context][io_op], io_time); + /* calculate the bucket_index based on latency in nanoseconds (uint64) */ + bucket_index = get_bucket_index(INSTR_TIME_GET_NANOSEC(io_time)); + PendingIOStats.pending_hist_time_buckets[io_object][io_context][io_op][bucket_index]++; + /* Add the per-backend count */ pgstat_count_backend_io_op_time(io_object, io_context, io_op, io_time); @@ -221,6 +286,10 @@ pgstat_io_flush_cb(bool nowait) bktype_shstats->times[io_object][io_context][io_op] += INSTR_TIME_GET_MICROSEC(time); + + for(int b = 0; b < PGSTAT_IO_HIST_BUCKETS; b++) + bktype_shstats->hist_time_buckets[io_object][io_context][io_op][b] += + PendingIOStats.pending_hist_time_buckets[io_object][io_context][io_op][b]; } } } @@ -274,6 +343,34 @@ pgstat_get_io_object_name(IOObject io_object) pg_unreachable(); } +const char * +pgstat_get_io_op_name(IOOp io_op) +{ + switch (io_op) + { + case IOOP_EVICT: + return "evict"; + case IOOP_FSYNC: + return "fsync"; + case IOOP_HIT: + /* TODO: investigate this! */ + return "hit?"; + case IOOP_REUSE: + return "reuse"; + case IOOP_WRITEBACK: + return "writeback"; + case IOOP_EXTEND: + return "extend"; + case IOOP_READ: + return "read"; + case IOOP_WRITE: + return "write"; + } + + elog(ERROR, "unrecognized IOOp value: %d", io_op); + pg_unreachable(); +} + void pgstat_io_init_shmem_cb(void *stats) { diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 73ca0bb0b7f..78efb78f5fb 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -18,9 +18,11 @@ #include "access/xlog.h" #include "access/xlogprefetcher.h" #include "catalog/catalog.h" +#include "catalog/namespace.h" #include "catalog/pg_authid.h" #include "catalog/pg_type.h" #include "common/ip.h" +//#include "fmgr.h" #include "funcapi.h" #include "miscadmin.h" #include "pgstat.h" @@ -30,6 +32,7 @@ #include "storage/procarray.h" #include "utils/acl.h" #include "utils/builtins.h" +#include "utils/rangetypes.h" #include "utils/timestamp.h" #define UINT32_ACCESS_ONCE(var) ((uint32)(*((volatile uint32 *)&(var)))) @@ -1627,6 +1630,149 @@ pg_stat_get_backend_io(PG_FUNCTION_ARGS) return (Datum) 0; } +/* +* When adding a new column to the pg_stat_io_histogram view and the +* pg_stat_get_backend_io() function, add a new enum value here above +* HIST_IO_NUM_COLUMNS. +*/ +typedef enum hist_io_stat_col +{ + HIST_IO_COL_INVALID = -1, + HIST_IO_COL_BACKEND_TYPE, + HIST_IO_COL_OBJECT, + HIST_IO_COL_CONTEXT, + HIST_IO_COL_IOTYPE, + HIST_IO_COL_BUCKET_US, + HIST_IO_COL_COUNT, + HIST_IO_COL_RESET_TIME, + HIST_IO_NUM_COLUMNS +} histogram_io_stat_col; + +/* + * pg_stat_io_histogram_build_tuples + * + * Helper routine for pg_stat_get_io_histogram() and pg_stat_get_backend_io()XXX + * filling a result tuplestore with one tuple for each object and each + * context supported by the caller, based on the contents of bktype_stats. + */ +static void +pg_stat_io_histogram_build_tuples(ReturnSetInfo *rsinfo, + PgStat_BktypeIO *bktype_stats, + BackendType bktype, + TimestampTz stat_reset_timestamp) +{ + /* Get OID for int4range type */ + Datum bktype_desc = CStringGetTextDatum(GetBackendTypeDesc(bktype)); + Oid range_typid = TypenameGetTypid("int4range"); + TypeCacheEntry *typcache = lookup_type_cache(range_typid, TYPECACHE_RANGE_INFO); + + for (int io_obj = 0; io_obj < IOOBJECT_NUM_TYPES; io_obj++) + { + const char *obj_name = pgstat_get_io_object_name(io_obj); + + for (int io_context = 0; io_context < IOCONTEXT_NUM_TYPES; io_context++) + { + const char *context_name = pgstat_get_io_context_name(io_context); + + /* + * Some combinations of BackendType, IOObject, and IOContext are + * not valid for any type of IOOp. In such cases, omit the entire + * row from the view. + */ + if (!pgstat_tracks_io_object(bktype, io_obj, io_context)) + continue; + + for (int io_op = 0; io_op < IOOP_NUM_TYPES; io_op++) + { + const char *op_name = pgstat_get_io_op_name(io_op); + + for(int bucket = 0; bucket < PGSTAT_IO_HIST_BUCKETS; bucket++) { + Datum values[HIST_IO_NUM_COLUMNS] = {0}; + bool nulls[HIST_IO_NUM_COLUMNS] = {0}; + RangeBound lower, upper; + RangeType *range; + + values[HIST_IO_COL_BACKEND_TYPE] = bktype_desc; + values[HIST_IO_COL_OBJECT] = CStringGetTextDatum(obj_name); + values[HIST_IO_COL_CONTEXT] = CStringGetTextDatum(context_name); + values[HIST_IO_COL_IOTYPE] = CStringGetTextDatum(op_name); + + /* this bucket's max latency: 2^2 = MIN_BUCKET_POW = (us) */ + if(bucket == 0) + lower.val = Int32GetDatum(0); + else + lower.val = Int32GetDatum(1 << (2 + bucket)); + lower.infinite = false; + lower.inclusive = true; + lower.lower = true; + + if(bucket == PGSTAT_IO_HIST_BUCKETS - 1) + upper.infinite = true; + else { + upper.val = Int32GetDatum(1 << (2 + bucket + 1)); + upper.infinite = false; + } + upper.inclusive = true; + upper.lower = false; + + range = make_range(typcache, &lower, &upper, false, NULL); + values[HIST_IO_COL_BUCKET_US] = RangeTypePGetDatum(range); + + /* bucket count */ + values[HIST_IO_COL_COUNT] = Int64GetDatum( + bktype_stats->hist_time_buckets[io_obj][io_context][io_op][bucket]); + + if (stat_reset_timestamp != 0) + values[HIST_IO_COL_RESET_TIME] = TimestampTzGetDatum(stat_reset_timestamp); + else + nulls[HIST_IO_COL_RESET_TIME] = true; + + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, + values, nulls); + } + } + } + } +} + +Datum +pg_stat_get_io_histogram(PG_FUNCTION_ARGS) +{ + ReturnSetInfo *rsinfo; + PgStat_IO *backends_io_stats; + + InitMaterializedSRF(fcinfo, 0); + rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + + backends_io_stats = pgstat_fetch_stat_io(); + + for (int bktype = 0; bktype < BACKEND_NUM_TYPES; bktype++) + { + PgStat_BktypeIO *bktype_stats = &backends_io_stats->stats[bktype]; + + /* + * In Assert builds, we can afford an extra loop through all of the + * counters (in pg_stat_io_build_tuples()), checking that only + * expected stats are non-zero, since it keeps the non-Assert code + * cleaner. + */ + Assert(pgstat_bktype_io_stats_valid(bktype_stats, bktype)); + + /* + * For those BackendTypes without IO Operation stats, skip + * representing them in the view altogether. + */ + if (!pgstat_tracks_io_bktype(bktype)) + continue; + + /* save tuples with data from this PgStat_BktypeIO */ + pg_stat_io_histogram_build_tuples(rsinfo, bktype_stats, bktype, + backends_io_stats->stat_reset_timestamp); + } + + return (Datum) 0; +} + /* * pg_stat_wal_build_tuple * diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 894b6a1b6d6..c2ff31049cf 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -6026,6 +6026,15 @@ proargnames => '{backend_type,object,context,reads,read_bytes,read_time,writes,write_bytes,write_time,writebacks,writeback_time,extends,extend_bytes,extend_time,hits,evictions,reuses,fsyncs,fsync_time,stats_reset}', prosrc => 'pg_stat_get_io' }, +{ oid => '6149', descr => 'statistics: per backend type IO latency histogram', + proname => 'pg_stat_get_io_histogram', prorows => '30', proretset => 't', + provolatile => 'v', proparallel => 'r', prorettype => 'record', + proargtypes => '', + proallargtypes => '{text,text,text,text,int4range,int8,timestamptz}', + proargmodes => '{o,o,o,o,o,o,o}', + proargnames => '{backend_type,object,context,io_type,bucket_latency_us,bucket_count,stats_reset}', + prosrc => 'pg_stat_get_io_histogram' }, + { oid => '6386', descr => 'statistics: backend IO statistics', proname => 'pg_stat_get_backend_io', prorows => '5', proretset => 't', provolatile => 'v', proparallel => 'r', prorettype => 'record', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index fff7ecc2533..90e5b08acb9 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -322,11 +322,23 @@ typedef enum IOOp (((unsigned int) (io_op)) < IOOP_NUM_TYPES && \ ((unsigned int) (io_op)) >= IOOP_EXTEND) +/* + * This should represent balance between being fast and providing value + * to the users: + * 1. We want to cover various fast and slow device types (0.01ms - 15ms) + * 2. We want to also cover sporadic long tail latencies (hardware issues, + * delayed fsyncs, stuck I/O) + * 3. We want to be aslow below cacheline size here probably: + * 16 * sizeof(uint64) = which should be less than two cachelines. + */ +#define PGSTAT_IO_HIST_BUCKETS 16 + typedef struct PgStat_BktypeIO { uint64 bytes[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES]; PgStat_Counter counts[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES]; PgStat_Counter times[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES]; + uint64 hist_time_buckets[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES][PGSTAT_IO_HIST_BUCKETS]; } PgStat_BktypeIO; typedef struct PgStat_PendingIO @@ -334,6 +346,7 @@ typedef struct PgStat_PendingIO uint64 bytes[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES]; PgStat_Counter counts[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES]; instr_time pending_times[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES]; + uint64 pending_hist_time_buckets[IOOBJECT_NUM_TYPES][IOCONTEXT_NUM_TYPES][IOOP_NUM_TYPES][PGSTAT_IO_HIST_BUCKETS]; } PgStat_PendingIO; typedef struct PgStat_IO @@ -606,6 +619,7 @@ extern void pgstat_count_io_op_time(IOObject io_object, IOContext io_context, extern PgStat_IO *pgstat_fetch_stat_io(void); extern const char *pgstat_get_io_context_name(IOContext io_context); extern const char *pgstat_get_io_object_name(IOObject io_object); +extern const char *pgstat_get_io_op_name(IOOp io_op); extern bool pgstat_tracks_io_bktype(BackendType bktype); extern bool pgstat_tracks_io_object(BackendType bktype, diff --git a/src/include/port/pg_bitutils.h b/src/include/port/pg_bitutils.h index 35761f509ec..f456bcef1bd 100644 --- a/src/include/port/pg_bitutils.h +++ b/src/include/port/pg_bitutils.h @@ -32,6 +32,33 @@ extern PGDLLIMPORT const uint8 pg_leftmost_one_pos[256]; extern PGDLLIMPORT const uint8 pg_rightmost_one_pos[256]; extern PGDLLIMPORT const uint8 pg_number_of_ones[256]; + +/* + * pg_leading_zero_bits32 + * Returns the number of leading 0-bits in x, starting at the most significant bit position. + * Word must not be 0 (as it is undefined behavior). + */ +static inline int +pg_leading_zero_bits32(uint32 word) +{ +#ifdef HAVE__BUILTIN_CLZ + Assert(word != 0); + + return __builtin_clz(word); +#else + int n = 32; + uint32 y; + if (word == 0) + return 32; + + y = word >> 16; if (y != 0) { n -= 16; word = y; } + y = word >> 8; if (y != 0) { n -= 8; word = y; } + y = word >> 4; if (y != 0) { n -= 4; word = y; } + y = word >> 2; if (y != 0) { n -= 2; word = y; } + y = word >> 1; if (y != 0) { return n - 2; } +#endif +} + /* * pg_leftmost_one_pos32 * Returns the position of the most significant set bit in "word", diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index f4ee2bd7459..88dc703bbde 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1951,6 +1951,14 @@ pg_stat_io| SELECT backend_type, fsync_time, stats_reset FROM pg_stat_get_io() b(backend_type, object, context, reads, read_bytes, read_time, writes, write_bytes, write_time, writebacks, writeback_time, extends, extend_bytes, extend_time, hits, evictions, reuses, fsyncs, fsync_time, stats_reset); +pg_stat_io_histogram| SELECT backend_type, + object, + context, + io_type, + bucket_latency_us, + bucket_count, + stats_reset + FROM pg_stat_get_io_histogram() b(backend_type, object, context, io_type, bucket_latency_us, bucket_count, stats_reset); pg_stat_progress_analyze| SELECT s.pid, s.datid, d.datname, diff --git a/src/test/regress/expected/stats.out b/src/test/regress/expected/stats.out index cd00f35bf7a..4c95f09d651 100644 --- a/src/test/regress/expected/stats.out +++ b/src/test/regress/expected/stats.out @@ -1765,6 +1765,29 @@ SELECT :my_io_stats_pre_reset > :my_io_stats_post_backend_reset; t (1 row) +-- Check that pg_stat_io_histograms sees some growing counts in buckets +-- We could also try with checkpointer, but it often runs with fsync=off +-- during test. +SET track_io_timing TO 'on'; +SELECT sum(bucket_count) AS hist_bucket_count_sum FROM pg_stat_get_io_histogram() +WHERE backend_type='client backend' AND object='relation' AND context='normal' \gset +CREATE TABLE test_io_hist(id bigint); +INSERT INTO test_io_hist SELECT generate_series(1, 100) s; +SELECT pg_stat_force_next_flush(); + pg_stat_force_next_flush +-------------------------- + +(1 row) + +SELECT sum(bucket_count) AS hist_bucket_count_sum2 FROM pg_stat_get_io_histogram() +WHERE backend_type='client backend' AND object='relation' AND context='normal' \gset +SELECT :hist_bucket_count_sum2 > :hist_bucket_count_sum; + ?column? +---------- + t +(1 row) + +RESET track_io_timing; -- Check invalid input for pg_stat_get_backend_io() SELECT pg_stat_get_backend_io(NULL); pg_stat_get_backend_io diff --git a/src/test/regress/sql/stats.sql b/src/test/regress/sql/stats.sql index 8768e0f27fd..063b1011d7e 100644 --- a/src/test/regress/sql/stats.sql +++ b/src/test/regress/sql/stats.sql @@ -841,6 +841,21 @@ SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + FROM pg_stat_get_backend_io(pg_backend_pid()) \gset SELECT :my_io_stats_pre_reset > :my_io_stats_post_backend_reset; + +-- Check that pg_stat_io_histograms sees some growing counts in buckets +-- We could also try with checkpointer, but it often runs with fsync=off +-- during test. +SET track_io_timing TO 'on'; +SELECT sum(bucket_count) AS hist_bucket_count_sum FROM pg_stat_get_io_histogram() +WHERE backend_type='client backend' AND object='relation' AND context='normal' \gset +CREATE TABLE test_io_hist(id bigint); +INSERT INTO test_io_hist SELECT generate_series(1, 100) s; +SELECT pg_stat_force_next_flush(); +SELECT sum(bucket_count) AS hist_bucket_count_sum2 FROM pg_stat_get_io_histogram() +WHERE backend_type='client backend' AND object='relation' AND context='normal' \gset +SELECT :hist_bucket_count_sum2 > :hist_bucket_count_sum; +RESET track_io_timing; + -- Check invalid input for pg_stat_get_backend_io() SELECT pg_stat_get_backend_io(NULL); SELECT pg_stat_get_backend_io(0); -- 2.43.0
fdatasync_latency_kernel_vs_user.bt
Description: Binary data
