MIME-Version: 1.0
References: <CAKZiRmwvE4uJLKTgPXeBA4m+d4tTghayoefcaM9=z3_S7i72GA@mail.gmail.com>
 <vhzkeogzrrfzjwo3xrnq4xsjh6i37ou6xsbz7yby3lbb3rnxzz@6fpysnkjyldi> <CAKZiRmxNVMOV7x5c_Amqk=2mmYJOqsfHgE8N8O9jGjgfBYa8kQ@mail.gmail.com>
In-Reply-To: <CAKZiRmxNVMOV7x5c_Amqk=2mmYJOqsfHgE8N8O9jGjgfBYa8kQ@mail.gmail.com>
From: Jakub Wartak <jakub.wartak@enterprisedb.com>
Date: Wed, 28 Jan 2026 12:12:10 +0100
Message-ID: <CAKZiRmw7-vkmYKo6Z64jUHpA-7Z71S_dM6GCV+X2jL_xL5t7Aw@mail.gmail.com>
Subject: Re: pg_stat_io_histogram
To: Andres Freund <andres@anarazel.de>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Content-Type: multipart/alternative; boundary="0000000000006ab441064970d0d1"
Archived-At: <https://www.postgresql.org/message-id/CAKZiRmw7-vkmYKo6Z64jUHpA-7Z71S_dM6GCV%2BX2jL_xL5t7Aw%40mail.gmail.com>
Precedence: bulk

--0000000000006ab441064970d0d1
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

On Tue, Jan 27, 2026 at 1:06=E2=80=AFPM Jakub Wartak <jakub.wartak@enterpri=
sedb.com>
wrote:

> [..]
> > > 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().
>

[..]
Here's the answer: on properly isolated perf test run (my
old&legacy&predictiable
4s32c64t NUMA box, s_b=3D8GB, DB size 16GB, hugepages, no turboboost, prope=
r
warmup,
no THP, cpupower D0, no physical I/O, ~22k pread64() calls/sec combined to
VFS
cache)
    and started on just using single NUMA: numactl --membind=3D0
--cpunodebind=3D0
    measured using: pgbench -M prepared -c 4 -j 4 postgres -T 20 -P 1 -S

master+track_io_timings=3Don, 60s warmup and then 3x runs
    tps =3D 44615.603668
    tps =3D 44556.191492
    tps =3D 44813.793981
    avg =3D 44662

master+track_io_timings=3Don+patch, , 60s warmup and then 3x runs
    tps =3D 44441.879384
    tps =3D 44403.101737
    tps =3D 45036.747418
    avg =3D 44627

so that's like 99.921% (so literally no overhead) and yields picture like:

postgres=3D# select bucket_latency_us, bucket_count
from pg_stat_io_histogram
where
    bucket_count > 0 and
    backend_type =3D 'client backend' and
    io_type =3D 'read' and
    context =3D 'normal'
order by bucket_latency_us;
 bucket_latency_us | bucket_count
-------------------+--------------
 [0,9)             |       273455
 [8,17)            |      3820379
 [16,33)           |        29359
 [32,65)           |          585
 [64,129)          |          467
 [128,257)         |          419
 [256,513)         |        15828
 [512,1025)        |           89

So one can also see 0.25..0.5ms bucket being larger there (initial reading
of the data from physical device) and that's hardware RAID-1 with 2x
Intel D3-S4510. And if I do pg_buffercache_evict_all()+vm drop_cache+
pg_stat_reset_shared(), I get this picture (note for bulkreads):

postgres=3D# select bucket_latency_us, bucket_count
from pg_stat_io_histogram
where
    bucket_count > 0 and
    backend_type =3D 'client backend' and context=3D'bulkread';
 bucket_latency_us | bucket_count
-------------------+--------------
 [0,9)             |       102555
 [8,17)            |           70
 [16,33)           |         3938
 [32,65)           |         6763
 [64,129)          |         5206
 [128,257)         |         9392
 [256,513)         |        10959
 [512,1025)        |        21372
 [1024,2049)       |          502
 [2048,4097)       |           34
 [4096,8193)       |            2
 [8192,16385)      |            2
 [16384,32769)     |            7

So clearly there's a distinction between reading the VFS cache and hitting
physical I/O.

Now we'll just probably settle on the proper get_bucket_index() impl.

-J.

--0000000000006ab441064970d0d1
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div dir=3D"ltr"></div><div class=3D"gmail_quote gmail_quo=
te_container"><div dir=3D"ltr" class=3D"gmail_attr">On Tue, Jan 27, 2026 at=
 1:06=E2=80=AFPM Jakub Wartak &lt;<a href=3D"mailto:jakub.wartak@enterprise=
db.com">jakub.wartak@enterprisedb.com</a>&gt; wrote:<br></div><blockquote c=
lass=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;border-left:1px soli=
d rgb(204,204,204);padding-left:1ex"><div dir=3D"ltr">[..]<br>&gt; &gt; Of =
course most of the I/O calls today are hitting page cache, so one would<br>=
&gt; &gt; expect they&#39;ll be &lt; 128us most of the time<br>&gt;<br>&gt;=
 Have you measured whether overhead is measurable when hitting the page cac=
he?<br>&gt; I&#39;d hope that it doesn&#39;t, due to io combing amortizing =
the cost somewhat. But<br>&gt; it seems worth measuring.<br><br>Not yet, I =
first wanted to hear if I&#39;m not sailing into some plain stupid<br>direc=
tion somewhere with this idea or implementation (e.g.<br>that INSTR_TIME_GE=
T_MICROSEC() was a really stupid omission from my side).<br><br>I&#39;ll tr=
y to perform this test overhead measurement hopefully with v3 once<br>we se=
ttle on how to do that bit shifting/clz().</div></blockquote><div><br></div=
><div>[..]</div><div>Here&#39;s the answer: on properly isolated perf test =
run (my old&amp;legacy&amp;predictiable <br>4s32c64t NUMA box, s_b=3D8GB, D=
B size 16GB, hugepages, no turboboost, proper warmup, <br>no THP, cpupower =
D0, no physical I/O, ~22k pread64() calls/sec combined to VFS <br>cache)<br=
>=C2=A0 =C2=A0 and started on just using single NUMA: numactl --membind=3D0=
 --cpunodebind=3D0<br>=C2=A0 =C2=A0 measured using: pgbench -M prepared -c =
4 -j 4 postgres -T 20 -P 1 -S<br><br>master+track_io_timings=3Don, 60s warm=
up and then 3x runs<br>=C2=A0 =C2=A0 tps =3D 44615.603668 <br>=C2=A0 =C2=A0=
 tps =3D 44556.191492 <br>=C2=A0 =C2=A0 tps =3D 44813.793981 <br>=C2=A0 =C2=
=A0 avg =3D 44662<br><br>master+track_io_timings=3Don+patch, , 60s warmup a=
nd then 3x runs<br>=C2=A0 =C2=A0 tps =3D 44441.879384 =C2=A0<br>=C2=A0 =C2=
=A0 tps =3D 44403.101737 <br>=C2=A0 =C2=A0 tps =3D 45036.747418 <br>=C2=A0 =
=C2=A0 avg =3D 44627<br><br>so that&#39;s like 99.921% (so literally no ove=
rhead) and yields picture like:</div><div><br></div><div>postgres=3D# selec=
t bucket_latency_us, bucket_count <br>from pg_stat_io_histogram =C2=A0<br>w=
here <br>=C2=A0 =C2=A0 bucket_count &gt; 0 and <br>=C2=A0 =C2=A0 backend_ty=
pe =3D &#39;client backend&#39; and <br>=C2=A0 =C2=A0 io_type =3D &#39;read=
&#39; and <br>=C2=A0 =C2=A0 context =3D &#39;normal&#39; <br>order by bucke=
t_latency_us;<br>=C2=A0bucket_latency_us | bucket_count <br>---------------=
----+--------------<br>=C2=A0[0,9) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 | =C2=A0 =C2=A0 =C2=A0 273455<br>=C2=A0[8,17) =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A03820379<br>=C2=A0[16,33) =C2=A0 =C2=
=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A029359<br>=C2=A0[32,65=
) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A058=
5<br>=C2=A0[64,129) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0467<br>=C2=A0[128,257) =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=
=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0419<br>=C2=A0[256,513) =C2=A0 =C2=A0 =C2=A0 =
=C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A015828<br>=C2=A0[512,1025) =C2=A0 =C2=A0=
 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 89=C2=A0<br><br>So one c=
an also see 0.25..0.5ms bucket being larger there (initial reading <br>of t=
he data from physical device) and that&#39;s hardware RAID-1 with 2x <br>In=
tel D3-S4510. And if I do pg_buffercache_evict_all()+vm drop_cache+</div><d=
iv>pg_stat_reset_shared(), I get this picture (note for bulkreads): <br><br=
>postgres=3D# select bucket_latency_us, bucket_count</div><div>from pg_stat=
_io_histogram =C2=A0<br>where <br>=C2=A0 =C2=A0 bucket_count &gt; 0 and <br=
>=C2=A0 =C2=A0 backend_type =3D &#39;client backend&#39; and context=3D&#39=
;bulkread&#39;;<br>=C2=A0bucket_latency_us | bucket_count <br>-------------=
------+--------------<br>=C2=A0[0,9) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 | =C2=A0 =C2=A0 =C2=A0 102555<br>=C2=A0[8,17) =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 70<br>=C2=A0[16,33) =
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 3938<br>=
=C2=A0[32,65) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 6763<br>=C2=A0[64,129) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=
=A0 =C2=A0 =C2=A0 5206<br>=C2=A0[128,257) =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=
=A0 =C2=A0 =C2=A0 =C2=A0 9392<br>=C2=A0[256,513) =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A010959<br>=C2=A0[512,1025) =C2=A0 =C2=A0 =
=C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A021372<br>=C2=A0[1024,2049) =C2=A0=
 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0502<br>=C2=A0[2048,4097)=
 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 34<br>=C2=A0[409=
6,8193) =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A02<b=
r>=C2=A0[8192,16385) =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A02<br>=C2=A0[16384,32769) =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A07</div><div><br></div><div>So clearly there&#39;s a distin=
ction between reading the VFS cache and hitting physical I/O.</div><div><br=
></div><div>Now we&#39;ll just probably settle on the proper get_bucket_ind=
ex() impl.</div><div><br></div><div>-J.</div></div></div>

--0000000000006ab441064970d0d1--