MIME-Version: 1.0
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>
In-Reply-To: <c7a77pcyc5eynme376wvyojryijtlieyxsu3bvxp4eiy6au6uf@caniulyi4jr5>
From: Peter Geoghegan <pg@bowt.ie>
Date: Wed, 13 Aug 2025 12:01:52 -0400
Message-ID: 
 <CAH2-Wz=L7h-koDKa3_NEg39Faw7MrOkSVOsodvQ4toSQahvWjQ@mail.gmail.com>
Subject: Re: index prefetching
To: Andres Freund <andres@anarazel.de>
Cc: Tomas Vondra <tomas@vondra.me>, 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>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: 
 <https://www.postgresql.org/message-id/CAH2-Wz%3DL7h-koDKa3_NEg39Faw7MrOkSVOsodvQ4toSQahvWjQ%40mail.gmail.com>
Precedence: bulk

On Wed, Aug 13, 2025 at 11:28=E2=80=AFAM Andres Freund <andres@anarazel.de>=
 wrote:
> > With "sync" I always get this (after a restart):
> >
> >    Buffers: shared hit=3D7435 read=3D52801
> >
> > while with "worker" I get this:
> >
> >    Buffers: shared hit=3D4879 read=3D52801
> >    Buffers: shared hit=3D5151 read=3D52801
> >    Buffers: shared hit=3D4978 read=3D52801
> >
> > So not only it changes run to tun, it also does not add up to 60236.
>
> This is reproducible on master? If so, how?

AFAIK it is *not* reproducible on master.

> If this happens only with the prefetching patch applied, is is possible t=
hat
> what happens here is that we occasionally re-request buffers that already=
 in
> the process of being read in? That would only happen with a read stream a=
nd
> io_method !=3D sync (since with sync we won't read ahead). If we have to =
start
> reading in a buffer that's already undergoing IO we wait for the IO to
> complete and count that access as a hit:

This theory seems quite plausible to me. Though it is a bit surprising
that I see incorrect buffer hit counts on the "good" forwards scan
case, rather than on the "bad" backwards scan case.

Here's what I mean by things being broken on the read stream side (at
least with certain backwards scan cases):

When I add instrumentation to the read stream side, by adding elog
debug calls that show the blocknum seen by read_stream_get_block, I
see out-of-order and repeated blocknums with the "bad" backwards scan
case ("SELECT * FROM t WHERE a BETWEEN 16336 AND 49103 ORDER BY a
desc"):

...
NOTICE:  index_scan_stream_read_next: index 1163 TID (25052,21)
WARNING:  prior lastBlock is 25053 for batchno 2856, new one: 25052
WARNING:  blocknum: 25052, 0x55614810efb0
WARNING:  blocknum: 25052, 0x55614810efb0
NOTICE:  index_scan_stream_read_next: index 1161 TID (25053,3)
WARNING:  prior lastBlock is 25052 for batchno 2856, new one: 25053
WARNING:  blocknum: 25053, 0x55614810efb0
NOTICE:  index_scan_stream_read_next: index 1160 TID (25052,19)
WARNING:  prior lastBlock is 25053 for batchno 2856, new one: 25052
WARNING:  blocknum: 25052, 0x55614810efb0
WARNING:  blocknum: 25052, 0x55614810efb0
NOTICE:  index_scan_stream_read_next: index 1141 TID (25051,21)
WARNING:  prior lastBlock is 25052 for batchno 2856, new one: 25051
WARNING:  blocknum: 25051, 0x55614810efb0
...

Notice that we see the same blocknum twice in close succession. Also
notice that we're passed 25052 and then subsequently passed 25053,
only to be passed 25053 once more.

OTOH, when I run the equivalent "good" backwards scan ("SELECT * FROM
t WHERE a BETWEEN 16336 AND 49103 ORDER BY a"), the output looks just
about perfect. I have to look around quite a bit longer before I can
find repeated blocknum within successive read_stream_get_block calls:

...
NOTICE:  index_scan_stream_read_next: index 303 TID (74783,1)
WARNING:  prior lastBlock is 74782 for batchno 2862, new one: 74783
WARNING:  blocknum: 74783, 0x55614810efb0
NOTICE:  index_scan_stream_read_next: index 323 TID (74784,1)
WARNING:  prior lastBlock is 74783 for batchno 2862, new one: 74784
WARNING:  blocknum: 74784, 0x55614810efb0
NOTICE:  index_scan_stream_read_next: index 324 TID (74783,21)
WARNING:  prior lastBlock is 74784 for batchno 2862, new one: 74783
WARNING:  blocknum: 74783, 0x55614810efb0
NOTICE:  index_scan_stream_read_next: index 325 TID (74784,2)
WARNING:  prior lastBlock is 74783 for batchno 2862, new one: 74784
WARNING:  blocknum: 74784, 0x55614810efb0
...

These out-of-order repeat requests are much rarer. And I *never* see
identical requests in *immediate* succession, whereas those are common
with the backwards scan case.

I believe that the out-of-order repeat requests shown here are a
legitimate consequence of the TIDs being slightly out of order in
relatively few places (so the forwards scan case may well already be
behaving exactly as I expect):

pg@regression:5432 [2470184]=3D# select ctid, a from t where ctid
between '(74783,1)' and '(74784,1)';
=E2=94=8C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=
=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=AC=E2=94=80=E2=94=80=E2=94=
=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=90
=E2=94=82    ctid    =E2=94=82   a    =E2=94=82
=E2=94=9C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=
=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=BC=E2=94=80=E2=94=80=E2=94=
=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=A4
=E2=94=82 (74783,1)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,2)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,3)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,4)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,5)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,6)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,7)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,8)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,9)  =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,10) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,11) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,12) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,13) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,14) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,15) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,16) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,17) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,18) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,19) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,20) =E2=94=82 49,077 =E2=94=82
=E2=94=82 (74783,21) =E2=94=82 49,078 =E2=94=82
=E2=94=82 (74784,1)  =E2=94=82 49,077 =E2=94=82
=E2=94=94=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=
=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=B4=E2=94=80=E2=94=80=E2=94=
=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=98
(22 rows)

Bear in mind that EXPLAIN ANALYZE shows *identical* "Buffers:" details
for each query on master. So I believe that I am completely justified
in expecting the calls to read_stream_get_block for the backwards scan
to use identical blocknums to the ones for the equivalent/good
forwards scan (except that they should be in the exact opposite
order). And yet that's not what I see.

Maybe this is something to do with the read position and the stream
position becoming mixed up? I find it odd that the relevant readstream
callback,  index_scan_stream_read_next, says "If the stream position
is undefined, just use the read position". That's just a guess,
though. This issue is tricky to debug. I'm not yet used to debugging
problems such as these (though I'll probably become an expert on it in
the months ahead).

--=20
Peter Geoghegan