Message-ID: <a9c0a5f9-cf5e-4ac9-abf6-683483161169@vondra.me>
Date: Wed, 13 Aug 2025 23:19:29 +0200
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: index prefetching
To: Peter Geoghegan <pg@bowt.ie>, 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>
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>
Content-Language: en-US
From: Tomas Vondra <tomas@vondra.me>
In-Reply-To: 
 <CAH2-Wz=L7h-koDKa3_NEg39Faw7MrOkSVOsodvQ4toSQahvWjQ@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
Archived-At: 
 <https://www.postgresql.org/message-id/a9c0a5f9-cf5e-4ac9-abf6-683483161169%40vondra.me>
Precedence: bulk


On 8/13/25 18:01, Peter Geoghegan wrote:
> On Wed, Aug 13, 2025 at 11:28 AM Andres Freund <andres@anarazel.de> wrote:
>>> With "sync" I always get this (after a restart):
>>>
>>>    Buffers: shared hit=7435 read=52801
>>>
>>> while with "worker" I get this:
>>>
>>>    Buffers: shared hit=4879 read=52801
>>>    Buffers: shared hit=5151 read=52801
>>>    Buffers: shared hit=4978 read=52801
>>>
>>> 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 that
>> 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 and
>> io_method != 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.
> 

I did investigate this, and I don't think there's anything broken in
read_stream. It happens because ReadStream has a concept of "ungetting"
a block, which can happen after hitting some I/O limits.

In that case we "remember" the last block (in read_stream_look_ahead
calls read_stream_unget_block), and we return it again. It may seem as
if read_stream_get_block() produced the same block twice, but it's
really just the block from the last round.

All duplicates produced by read_stream_look_ahead were caused by this. I
suspected it's a bug in lastBlock optimization, but that's not the case,
it happens entirely within read_stream. And it's expected.

It's also not very surprising this happens with backwards scans more.
The I/O is apparently much slower (due to missing OS prefetch), so we're
much more likely to hit the I/O limits (max_ios and various other limits
in read_stream_start_pending_read).


regards

-- 
Tomas Vondra