Re: pg_stat_io_histogram - Mailing list pgsql-hackers

On Mon, Jan 26, 2026 at 4:08 PM Andres Freund <andres@anarazel.de> 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.


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...


-J.

[1] - https://www.postgresql.org/message-id/CAKZiRmyZzmOODYS6n8mns9zN4RcS3o9kfrdQDyeRupqaGp9PmQ%40mail.gmail.com