Re: Help Me Understand Why I'm Getting a Bad Query Plan

On Wed, Mar 25, 2009 at 9:15 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> I think what you should be doing is messing with the cost parameters
> ... and not in the direction you tried before.  I gather from
>        effective_cache_size = 12GB
> that you have plenty of RAM on this machine.  If the tables involved
> are less than 1GB then it's likely that you are operating in a fully
> cached condition, and the default cost parameters are not set up for
> that.  You want to be charging a lot less for page accesses relative to
> CPU effort.  Try reducing both seq_page_cost and random_page_cost to 0.5
> or even 0.1.  You'll need to watch your other queries to make sure
> nothing gets radically worse though ...
>
>                        regards, tom lane

Thanks Tom, I think that did the trick. I'm going to have to keep an
eye on the database for a few days to make sure there are no
unintended consequences, but it looks good. Here's the new query
plan:

HashAggregate (cost=40906.58..40906.67 rows=7 width=37) (actual
time=204.661..204.665 rows=4 loops=1)
-> Nested Loop (cost=0.00..40906.55 rows=7 width=37) (actual
time=0.293..204.628 rows=11 loops=1)
-> Nested Loop (cost=0.00..40531.61 rows=1310 width=70)
(actual time=0.261..113.576 rows=3210 loops=1)
-> Nested Loop (cost=0.00..39475.97 rows=1310
width=37) (actual time=0.232..29.484 rows=3210 loops=1)
-> Index Scan using visitors_userid_index2 on
visitors v (cost=0.00..513.83 rows=1002 width=33) (actual
time=0.056..2.307 rows=899 loops=1)
Index Cond: (userid =
'fbe2537f21d94f519605612c0bf7c2c5'::bpchar)
-> Index Scan using
itemexperiencelog__index__visitorid on itemexperiencelog l
(cost=0.00..37.43 rows=116 width=70) (actual time=0.013..0.021 rows=4
loops=899)
Index Cond: (l.visitorid = v.id)
-> Index Scan using items_primary_pkey on items_primary
p (cost=0.00..0.79 rows=1 width=66) (actual time=0.018..0.019 rows=1
loops=3210)
Index Cond: (p.id = l.itemid)
-> Index Scan using feeds_pkey on feeds f (cost=0.00..0.27
rows=1 width=33) (actual time=0.023..0.023 rows=0 loops=3210)
Index Cond: (f.id = p.feedid)
Filter: (lower((f.slug)::text) =
'wealth_building_by_nightingaleconant'::text)
Total runtime: 204.759 ms

What I did was change seq_page_cost back to 1.0 and then changed
random_page_cost to 0.5

This also makes logical sense to me. We've completely rewritten our
caching layer over the last three weeks, and introduced slony into our
architecture, so our usage patterns have transformed overnight.
Previously we were very i/o bound, now most of the actively used data
is actually in memory. Just a few weeks ago there was so much churn
almost nothing stayed cached for long.

This is great, thanks guys!

Bryan