Re: Planner selects slow "Bitmap Heap Scan" when "Index Scan" is faster

Hi all

On Fri, Apr 6, 2012 at 19:11, Jeff Janes <jeff(dot)janes(at)gmail(dot)com> wrote:
> On Wed, Apr 4, 2012 at 6:47 AM, Kim Hansen <kim(at)rthansen(dot)dk> wrote:
>> Hi All
>>
>> I have a query where the planner makes a wrong cost estimate, it looks
>> like it underestimates the cost of a "Bitmap Heap Scan" compared to an
>> "Index Scan".
>>
>> This it the two plans, I have also pasted them below:
>>  Slow (189ms): http://explain.depesz.com/s/2Wq
>>  Fast (21ms): http://explain.depesz.com/s/ThQ
>
> Could you do explain (analyze, buffers)?

I have done that now, the log is pasted in below. It looks like every
buffer fetched is a hit, I would think that PostgreSQL should know
that as almost nothing happens on the server and effective_cache_size
is configured to 8GB.

> Did you run these queries multiple times in both orders?  If you just
> ran them once each, in the order indicated, then the bitmap scan may
> have done the hard work of reading all the needed buffers into cache,
> and the index scan then got to enjoy that cache.

I have run the queries a few times in order to warm up the caches, the
queries stabilise on 20ms and 180ms.

Regards,
Kim

========

yield=> explain (analyze,buffers) select "filtered_demands"."pol" as
"c0" from "demands"."filtered_demands" as "filtered_demands" where
("filtered_demands"."pod" = 'VELAG') group by "filtered_demands"."pol"
order by "filtered_demands"."pol" ASC NULLS LAST;

QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=38564.80..38564.80 rows=2 width=6) (actual
time=185.497..185.520 rows=221 loops=1)
Sort Key: pol
Sort Method: quicksort Memory: 35kB
Buffers: shared hit=14969
-> HashAggregate (cost=38564.77..38564.79 rows=2 width=6) (actual
time=185.303..185.343 rows=221 loops=1)
Buffers: shared hit=14969
-> Bitmap Heap Scan on filtered_demands
(cost=566.23..38503.77 rows=24401 width=6) (actual time=6.119..179.056
rows=18588 loops=1)
Recheck Cond: (pod = 'VELAG'::text)
Buffers: shared hit=14969
-> Bitmap Index Scan on filtered_demands_pod_pol_idx
(cost=0.00..560.12 rows=24401 width=0) (actual time=4.661..4.661
rows=18588 loops=1)
Index Cond: (pod = 'VELAG'::text)
Buffers: shared hit=74
Total runtime: 185.577 ms
(13 rows)

yield=> set enable_bitmapscan = false;
SET
yield=> explain (analyze,buffers) select "filtered_demands"."pol" as
"c0" from "demands"."filtered_demands" as "filtered_demands" where
("filtered_demands"."pod" = 'VELAG') group by "filtered_demands"."pol"
order by "filtered_demands"."pol" ASC NULLS LAST;

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------
Group (cost=0.00..76534.33 rows=2 width=6) (actual
time=0.029..20.202 rows=221 loops=1)
Buffers: shared hit=18386
-> Index Scan using filtered_demands_pod_pol_idx on
filtered_demands (cost=0.00..76473.33 rows=24401 width=6) (actual
time=0.027..16.455 rows=18588 loops=1)
Index Cond: (pod = 'VELAG'::text)
Buffers: shared hit=18386
Total runtime: 20.246 ms
(6 rows)

--
Kim Rydhof Thor Hansen
Vadgårdsvej 3, 2. tv.
2860 Søborg
Phone: +45 3091 2437