Hi,
On 2026-02-15 14:34:07 -0500, Andres Freund wrote:
> debug_io_direct=data, enable_indexscan_prefetch=1, w/ stream->distance * 2 + 1
> ┌─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
> │
> QUERY PLAN
> │
> ├─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
> │ Index Scan using idx_periodic_100000 on prefetch_test_data_100000
> (cost=0.29..15351.09 rows=100000 width=8) (actual time=0.316..176.703
> rows=100000.00 loops=1) │
> │ Index Searches: 1
>
> │
> │ Prefetch: distance=707.476 count=11158 stalls=88503 skipped=0 resets=0
> pauses=26 ungets=0 forwarded=0
> │
> │ histogram [2,4) => 5, [4,8) => 11, [8,16) => 26, [16,32) => 30,
> [32,64) => 54, [64,128) => 109, [128,256) => 221, [256,512) => 428,
> [512,1024) => 10274 │
> │ Buffers: shared hit=96875 read=3400
>
> │
> │ I/O Timings: shared read=33.874
>
> │
> │ Planning:
>
> │
> │ Buffers: shared hit=78 read=21
>
> │
> │ I/O Timings: shared read=2.772
>
> │
> │ Planning Time: 3.065 ms
>
> │
> │ Execution Time: 182.959 ms
>
> │
> └─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
>
> The stall stats are bogus, because they get increased even when we correctly
> are not prefetching due to everything being in shared buffers. I think the
> if (distance == 1) stats.nstalls++
> would need to be just before the WaitReadBuffers().
The histogram and distance are also somewhat misleading: They measure what the
distance is at the time the next block is determined, but that's not really
informative, as the distance can be much bigger than what we are actually
doing IO wise (to allow for IO combining etc). The limit for the number of
in-flight IOs will be the limiting factor in a case with random-ish IOs and
it's also really what matters for performance.
For a query with lots of random prefetching, run with
effective_io_concurrency=8, compare:
stats using stream->distance:
Limit (cost=0.43..150968.68 rows=1000000 width=8) (actual
time=0.138..5425.851 rows=1000000.00 loops=1)
Buffers: shared hit=701118 read=301757
I/O Timings: shared read=3919.597
-> Index Scan using idx_random_10000000 on prefetch_test_data_10000000
(cost=0.43..1509682.87 rows=10000000 width=8) (actual time=0.137..5331.243
rows=1000000.00 loops=1)
Index Searches: 1
Prefetch: distance=143.999 count=1297237 stalls=6 skipped=3 resets=0
pauses=0 ungets=297462 forwarded=2
histogram [16,32) => 9, [32,64) => 2, [64,128) => 2,
[128,256) => 1297224
Buffers: shared hit=701118 read=301757
I/O Timings: shared read=3919.597
Planning:
Buffers: shared hit=96 read=7
I/O Timings: shared read=0.812
Planning Time: 1.310 ms
Execution Time: 5496.622 ms
stats using stream->ios_in_progress:
Limit (cost=0.43..150968.68 rows=1000000 width=8) (actual
time=0.157..5427.138 rows=1000000.00 loops=1)
Buffers: shared hit=701118 read=301757
I/O Timings: shared read=3919.857
-> Index Scan using idx_random_10000000 on prefetch_test_data_10000000
(cost=0.43..1509682.87 rows=10000000 width=8) (actual time=0.156..5332.607
rows=1000000.00 loops=1)
Index Searches: 1
Prefetch: distance=6.864 count=1297237 stalls=6 skipped=3 resets=0
pauses=0 ungets=297462 forwarded=106
histogram [1,2) => 1164, [2,4) => 12634, [4,8) => 1283335
Buffers: shared hit=701118 read=301757
I/O Timings: shared read=3919.857
Planning:
Buffers: shared hit=96 read=7
I/O Timings: shared read=0.809
Planning Time: 1.305 ms
Execution Time: 5502.332 ms
The former sure makes it look like that the bottleneck isn't the number of IOs
in flight, after all the distance is quite deep. Yet, if you increase
effective_io_concurrency:
stats using stream->distance:
Limit (cost=0.43..150968.68 rows=1000000 width=8) (actual
time=0.138..2769.847 rows=1000000.00 loops=1)
Buffers: shared hit=701960 read=301786
I/O Timings: shared read=1100.819
-> Index Scan using idx_random_10000000 on prefetch_test_data_10000000
(cost=0.43..1509682.87 rows=10000000 width=8) (actual time=0.137..2667.780
rows=1000000.00 loops=1)
Index Searches: 1
Prefetch: distance=1038.301 count=1293137 stalls=0 skipped=3 resets=0
pauses=694 ungets=291801 forwarded=2
histogram [16,32) => 16, [32,64) => 18, [64,128) => 33,
[128,256) => 2, [256,512) => 3, [512,1024) => 125045, [1024,2048) => 1168020
Buffers: shared hit=701960 read=301786
I/O Timings: shared read=1100.819
Planning:
Buffers: shared hit=96 read=7
I/O Timings: shared read=0.819
Planning Time: 1.346 ms
Execution Time: 2845.891 ms
(14 rows)
stats using stream->ios_in_progress:
Limit (cost=0.43..150968.68 rows=1000000 width=8) (actual
time=0.136..2767.839 rows=1000000.00 loops=1)
Buffers: shared hit=701960 read=301786
I/O Timings: shared read=1102.115
-> Index Scan using idx_random_10000000 on prefetch_test_data_10000000
(cost=0.43..1509682.87 rows=10000000 width=8) (actual time=0.135..2665.838
rows=1000000.00 loops=1)
Index Searches: 1
Prefetch: distance=61.054 count=1293134 stalls=0 skipped=3 resets=0
pauses=694 ungets=291798 forwarded=4
histogram [1,2) => 1, [2,4) => 2, [4,8) => 4, [8,16) => 9,
[16,32) => 8737, [32,64) => 1284379
Buffers: shared hit=701960 read=301786
I/O Timings: shared read=1102.115
Planning:
Buffers: shared hit=96 read=7
I/O Timings: shared read=0.819
Planning Time: 1.334 ms
Execution Time: 2846.017 ms
If you want to measure in the domain of blocks, rather than, I'd suggest at
least using the number of currently pinned buffers, rather than the
distance. But I think IOs is a much more useful measure.
E.g. for prefetching a index scan on a sequential column, with:
io_effective_io_concurrency=128 io_combine_limit=16
stats using stream->distance:
Prefetch: distance=18.872 count=320174 stalls=30736 skipped=9687128 resets=0
pauses=7684 ungets=0 forwarded=0
histogram [1,2) => 3416, [2,4) => 23052, [4,8) => 53788, [8,16) =>
115244, [16,32) => 124654, [32,64) => 20
Buffers: shared hit=27325 read=312500
I/O Timings: shared read=1794.060
stats using stream->pinned_buffers:
Prefetch: distance=8.259 count=320174 stalls=30736 skipped=9687128 resets=0
pauses=7684 ungets=0 forwarded=29897
histogram [1,2) => 23052, [2,4) => 58070, [4,8) => 84497, [8,16)
=> 105873, [16,32) => 18785
Buffers: shared hit=27325 read=312500
I/O Timings: shared read=887.850
stats using stream->ios_in_progress:
Prefetch: distance=0.059 count=320174 stalls=30736 skipped=9687128 resets=0
pauses=7684 ungets=0 forwarded=301389
histogram [1,2) => 18785
Buffers: shared hit=27325 read=312500
I/O Timings: shared read=881.723
Only the ios-in_progress one really shows that we are basically not doing
any readahead, due to heapam pausing, thinking we're far enough ahead - but
due to IO combining the batchdistance limit is reached before we can issue
multiple IOs.
io_effective_io_concurrency=128 io_combine_limit=4:
stats using stream->ios_in_progress:
Prefetch: distance=4.200 count=328882 stalls=1 skipped=9687128 resets=0
pauses=16391 ungets=0 forwarded=9
histogram [1,2) => 8, [2,4) => 129775, [4,8) => 199090
Buffers: shared hit=27325 read=312500
I/O Timings: shared read=300.284
FWIW, if I change the batchdistance <= 2 check to <= 8, I get good perf even
with io_combine_limit=16:
stats using stream->ios_in_progress:
Prefetch: distance=2.605 count=315526 stalls=3 skipped=9687128 resets=0
pauses=3035 ungets=0 forwarded=50
histogram [1,2) => 72679, [2,4) => 170115, [4,8) => 72682
Buffers: shared hit=27325 read=312500
I/O Timings: shared read=125.902
but that was just an experiment.
Greetings,
Andres Freund
