Thread: Mysteriously varying index scan costs

Last week I encountered the following at a customer site on PostgreSQL 9.6,
and I cannot explain it.

The first run gave me this:

 Index Scan using device_outbound_messages_status on device_outbound_messages  (cost=0.43..20.46 rows=97 width=128)
(actualtime=34.021..35.545 rows=133 loops=1)
 
   Index Cond: ((status)::text = ANY ('{WAITING_FOR_TX,WAITING_FOR_IMMEDIATE_TX}'::text[]))
   Buffers: shared hit=74917 dirtied=707

Subsequent runs of the same query gave me:

 Index Scan using device_outbound_messages_status on device_outbound_messages  (cost=0.43..20.46 rows=97 width=128)
(actualtime=2.129..3.907 rows=133 loops=1)
 
   Index Cond: ((status)::text = ANY ('{WAITING_FOR_TX,WAITING_FOR_IMMEDIATE_TX}'::text[]))
   Buffers: shared hit=1185

There were no concurrent changes to the data (test environment).
This was part of a bigger statement.

I understand that some pages can be dirtied because table fetches that
cause hint bits to be set.

But how can it be that the first run has to touch 74917 blocks,
while whe second run only needs to touch 1185?

Thanks for any ideas!

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

Pavan Deolasee wrote:
> On Mon, Sep 24, 2018 at 2:20 PM, Laurenz Albe <laurenz.albe@cybertec.at> wrote:
> > 
> > But how can it be that the first run has to touch 74917 blocks,
> > while whe second run only needs to touch 1185?
> > 
> 
> The first index scan may have killed lots of index tuples.

So the first index scan visited lots of table tuples, found them
dead, and set the LP_DEAD flag on the corresponding index items
so that subsequent index scans could ignore them, right?

Thanks, that must be the correct explanation.  It correlates nicely
with the dirtied pages, too.

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com