Thread: Planner selects slow "Bitmap Heap Scan" when "Index Scan" is faster
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 I have run "VACUUM FULL VERBOSE ANALYZE". I have configured shared_buffers and effective_cache_size, that didn't solve my problem, the estimates was kept the same and both queries got faster. What can I do to fix the cost estimate? Regards, Kim Hansen ======== yield=> SELECT version(); version ------------------------------------------------------------------------------------------------------- PostgreSQL 9.1.3 on x86_64-unknown-linux-gnu, compiled by gcc-4.4.real (Debian 4.4.5-8) 4.4.5, 64-bit (1 row) yield=> explain analyze 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=188.987..189.003 rows=221 loops=1) Sort Key: pol Sort Method: quicksort Memory: 35kB -> HashAggregate (cost=38564.77..38564.79 rows=2 width=6) (actual time=188.796..188.835 rows=221 loops=1) -> Bitmap Heap Scan on filtered_demands (cost=566.23..38503.77 rows=24401 width=6) (actual time=6.501..182.634 rows=18588 loops=1) Recheck Cond: (pod = 'VELAG'::text) -> Bitmap Index Scan on filtered_demands_pod_pol_idx (cost=0.00..560.12 rows=24401 width=0) (actual time=4.917..4.917 rows=18588 loops=1) Index Cond: (pod = 'VELAG'::text) Total runtime: 189.065 ms (9 rows) yield=> set enable_bitmapscan = false; SET yield=> explain analyze 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.028..20.823 rows=221 loops=1) -> Index Scan using filtered_demands_pod_pol_idx on filtered_demands (cost=0.00..76473.33 rows=24401 width=6) (actual time=0.027..17.174 rows=18588 loops=1) Index Cond: (pod = 'VELAG'::text) Total runtime: 20.877 ms (4 rows) yield=> -- Kim Rydhof Thor Hansen Vadgårdsvej 3, 2. tv. 2860 Søborg Phone: +45 3091 2437
Kim Hansen <kim@rthansen.dk> wrote: > 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". > What can I do to fix the cost estimate? Could you try running the query with cpu_tuple_cost = 0.05 and let us know how that goes? -Kevin
On Thu, Apr 5, 2012 at 17:34, Kevin Grittner
<Kevin.Grittner@wicourts.gov> wrote:
> Kim Hansen <kim@rthansen.dk> wrote:
>
>> 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".
>
>> What can I do to fix the cost estimate?
>
> Could you try running the query with cpu_tuple_cost = 0.05 and let
> us know how that goes?
>
It looks like it just increased the estimated cost of both queries by
about 1000.
Regards,
Kim
===============
yield=> explain analyze 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=39540.92..39540.92 rows=2 width=6) (actual
time=186.833..186.858 rows=221 loops=1)
Sort Key: pol
Sort Method: quicksort Memory: 35kB
-> HashAggregate (cost=39540.81..39540.91 rows=2 width=6) (actual
time=186.643..186.678 rows=221 loops=1)
-> Bitmap Heap Scan on filtered_demands
(cost=566.23..39479.81 rows=24401 width=6) (actual time=6.154..180.654
rows=18588 loops=1)
Recheck Cond: (pod = 'VELAG'::text)
-> Bitmap Index Scan on filtered_demands_pod_pol_idx
(cost=0.00..560.12 rows=24401 width=0) (actual time=4.699..4.699
rows=18588 loops=1)
Index Cond: (pod = 'VELAG'::text)
Total runtime: 186.912 ms
(9 rows)
yield=> set enable_bitmapscan = false;
SET
yield=> explain analyze 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..77510.37 rows=2 width=6) (actual
time=0.029..20.361 rows=221 loops=1)
-> Index Scan using filtered_demands_pod_pol_idx on
filtered_demands (cost=0.00..77449.37 rows=24401 width=6) (actual
time=0.027..16.859 rows=18588 loops=1)
Index Cond: (pod = 'VELAG'::text)
Total runtime: 20.410 ms
(4 rows)
yield=>
--
Kim Rydhof Thor Hansen
Vadgårdsvej 3, 2. tv.
2860 Søborg
Phone: +45 3091 2437
On Wed, Apr 4, 2012 at 6:47 AM, Kim Hansen <kim@rthansen.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)? 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. Cheers, Jeff
Hi all On Fri, Apr 6, 2012 at 19:11, Jeff Janes <jeff.janes@gmail.com> wrote: > On Wed, Apr 4, 2012 at 6:47 AM, Kim Hansen <kim@rthansen.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
On Fri, Apr 6, 2012 at 3:09 PM, Kim Hansen <kim@rthansen.dk> wrote: > Hi all > > On Fri, Apr 6, 2012 at 19:11, Jeff Janes <jeff.janes@gmail.com> wrote: >> On Wed, Apr 4, 2012 at 6:47 AM, Kim Hansen <kim@rthansen.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. That almost nothing happens on the server does not enter into it. It would need to know whether the last thing that did happen (no matter how long ago that was) touched the same data that the current query needs to touch. effective_cache_size is only used when it is anticipated that the same blocks will be accessed repeatedly *within the same query*. It is not used to estimate reuse between different queries. > >> 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. My first curiosity is not why the estimate is too good for Bitmap Index Scan, but rather why the actual execution is too poor. As far as I can see the only explanation for the poor execution is that the bitmap scan has gone lossy, so that every tuple in every touched block needs to be rechecked against the where clause. If that is the case, it suggests that your work_mem is quite small. In 9.2, explain analyze will report the number of tuples filtered out by rechecking, but that isn't reported in your version. It looks like the planner makes no attempt to predict when a bitmap scan will go lossy and then penalize it for the extra rechecks it will do. Since it doesn't know it will be carrying out those extra checks, you can't just increase the tuple or operator costs factors. So that may explain why the bitmap is not getting penalized for its extra CPU time. But that doesn't explain why the estimated cost is substantially lower than the index scan. That is probably because the bitmap scan expects it is doing more sequential IO and less random IO. You could cancel that advantage be setting random_page_cost to about the same as seq_page_cost (which since you indicated most data will be cached, would be an appropriate thing to do regardless of this specific issue). Cheers, Jeff
On Tue, Apr 10, 2012 at 04:59, Jeff Janes <jeff.janes@gmail.com> wrote: > On Fri, Apr 6, 2012 at 3:09 PM, Kim Hansen <kim@rthansen.dk> wrote: > >> I have run the queries a few times in order to warm up the caches, the >> queries stabilise on 20ms and 180ms. > > My first curiosity is not why the estimate is too good for Bitmap > Index Scan, but rather why the actual execution is too poor. As far > as I can see the only explanation for the poor execution is that the > bitmap scan has gone lossy, so that every tuple in every touched block > needs to be rechecked against the where clause. If that is the case, > it suggests that your work_mem is quite small. > > In 9.2, explain analyze will report the number of tuples filtered out > by rechecking, but that isn't reported in your version. > > It looks like the planner makes no attempt to predict when a bitmap > scan will go lossy and then penalize it for the extra rechecks it will > do. Since it doesn't know it will be carrying out those extra checks, > you can't just increase the tuple or operator costs factors. You are right, when I increase the work_mem from 1MB to 2MB the time decreases from 180ms to 30ms for the slow query. I have now configured the server to 10MB work_mem. > So that may explain why the bitmap is not getting penalized for its > extra CPU time. But that doesn't explain why the estimated cost is > substantially lower than the index scan. That is probably because the > bitmap scan expects it is doing more sequential IO and less random IO. > You could cancel that advantage be setting random_page_cost to about > the same as seq_page_cost (which since you indicated most data will be > cached, would be an appropriate thing to do regardless of this > specific issue). I have set seq_page_cost and random_page_cost to 0.1 in order to indicate that data is cached, the system now selects the faster index scan. Thanks for your help, -- Kim Rydhof Thor Hansen Vadgårdsvej 3, 2. tv. 2860 Søborg Phone: +45 3091 2437