Mime-Version: 1.0
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain; charset=UTF-8
Date: Thu, 14 Aug 2025 14:44:44 -0400
Message-Id: <DC2DFSYXBDSJ.2N7WXLD4JT05H@bowt.ie>
From: "Peter Geoghegan" <pg@bowt.ie>
To: "Peter Geoghegan" <pg@bowt.ie>, "Tomas Vondra" <tomas@vondra.me>,
 "Andres Freund" <andres@anarazel.de>
Cc: "Thomas Munro" <thomas.munro@gmail.com>, "Nazir Bilal Yavuz"
 <byavuz81@gmail.com>, "Robert Haas" <robertmhaas@gmail.com>, "Melanie
 Plageman" <melanieplageman@gmail.com>, "PostgreSQL Hackers"
 <pgsql-hackers@lists.postgresql.org>, "Georgios"
 <gkokolatos@protonmail.com>, "Konstantin Knizhnik" <knizhnik@garret.ru>,
 "Dilip Kumar" <dilipbalaut@gmail.com>
Subject: Re: index prefetching
References: <f516d66b-5bed-45af-8127-d09b684dad9e@vondra.me>
 <CAH2-WzmdiO4fHA1O06SYUjgMQZG7haysY7Tu5DS5z-CHsv5MLQ@mail.gmail.com>
 <d7bad36a-ac8d-4727-a52b-822621142d64@vondra.me>
 <CAH2-Wz=Y-PsC6_tZOPhHWvPx0geGnrh9VKjUZ-168ezUM_XM2Q@mail.gmail.com>
 <CA+hUKGKMaZLmNQHaa_DZMw9MJJKGegjrqnTY3KOZB-_nvFa3wQ@mail.gmail.com>
 <DC0RJDW1PEAX.NDGIXR6WPM94@bowt.ie>
 <51b5f71b-5f19-4453-91ff-2b9f2a840c58@vondra.me>
 <b739c179-25ca-4371-b528-cf80ea111d94@vondra.me>
 <CAH2-Wzko86NwiENCJGtakJ=fOhWpr-Yz-F+1oxgv2Ku1mvXwvA@mail.gmail.com>
 <6cb6109d-71d6-490c-8056-d8885081b008@vondra.me>
 <c7a77pcyc5eynme376wvyojryijtlieyxsu3bvxp4eiy6au6uf@caniulyi4jr5>
 <CAH2-Wz=L7h-koDKa3_NEg39Faw7MrOkSVOsodvQ4toSQahvWjQ@mail.gmail.com>
 <a9c0a5f9-cf5e-4ac9-abf6-683483161169@vondra.me>
 <DC1PBQW5HBEJ.3W4SMGI4LW3VI@bowt.ie>
 <7c308720-5cd4-4508-8cc0-6e55a6352731@vondra.me>
 <DC2B4TY023QP.2ZL331BPZCBSX@bowt.ie>
 <CAH2-WzmuGzTH-62EWTgQ4F66XEBJtJk25psF4GDuAGqeC4a34g@mail.gmail.com>
In-Reply-To: 
 <CAH2-WzmuGzTH-62EWTgQ4F66XEBJtJk25psF4GDuAGqeC4a34g@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/DC2DFSYXBDSJ.2N7WXLD4JT05H%40bowt.ie>
Precedence: bulk

On Thu Aug 14, 2025 at 1:57 PM EDT, Peter Geoghegan wrote:
> The only interesting thing about the flame graph is just how little
> difference there seems to be (at least for this particular perf event
> type).

I captured method_io_uring.c DEBUG output from running each query in the
server log, in the hope that it would shed some light on what's really goin=
g
on here.  I think that it just might.

I count a total of 12,401 distinct sleeps for the sequential/slow backwards
scan test case:

$ grep -E "wait_one with [1-9][0-9]* sleeps" sequential.txt | head
 2025-08-14 14:35:03.278 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.278 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.278 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.278 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.278 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.278 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.279 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.279 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.279 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
 2025-08-14 14:35:03.279 EDT [2516983][client backend] [[unknown]][0/1:0] D=
EBUG:  00000: wait_one with 1 sleeps
$ grep -E "wait_one with [1-9][0-9]* sleeps" sequential.txt | awk '{ total =
+=3D $11 } END { print total }'
12401

But there are only 3 such sleeps seen when the random backwards scan query =
is
run -- which might begin to explain the mystery of why it runs so much fast=
er:

$ grep -E "wait_one with [1-9][0-9]* sleeps" random.txt | awk '{ total +=3D=
 $11 } END { print total }'
104

--=20
Peter Geoghegan