Regression: 8.3 2 seconds -> 8.4 100+ seconds

From: Francisco Reyes <lists(at)stringsutils(dot)com>
To: Pgsql performance <pgsql-performance(at)postgresql(dot)org>
Subject: Regression: 8.3 2 seconds -> 8.4 100+ seconds
Date: 2010-10-27 12:41:23
Message-ID: cone.1288183283.263738.5695.1000@shelca
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

CentOS 5.4 and 5.5

Query
SELECT sum(usramt) as givensum,
sum (case when usedid > 0 then usramt else 0 end) as usedsum
FROM argrades
WHERE userstatus in (5) and
membid in (select distinct members.membid from members, cards
where members.membid = cards.membid and members.membershipid = 40 and useraccount in
( select useraccount from cards where membid in
(select membid from members where commonid = 3594)))

Run on 8.3.7. Result below was from second run. First run took 2 seconds.
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=205095.01..205095.02 rows=1 width=10) (actual time=1.430..1.431 rows=1 loops=1)
-> Nested Loop (cost=948.04..204823.07 rows=54387 width=10) (actual time=0.153..1.016 rows=472 loops=1)
-> Unique (cost=948.04..948.42 rows=76 width=4) (actual time=0.126..0.128 rows=2 loops=1)
-> Sort (cost=948.04..948.23 rows=76 width=4) (actual time=0.126..0.126 rows=2 loops=1)
Sort Key: public.members.membid
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=362.66..945.66 rows=76 width=4) (actual time=0.089..0.113 rows=2 loops=1)
-> Nested Loop (cost=362.66..891.84 rows=76 width=4) (actual time=0.082..0.097 rows=2 loops=1)
-> HashAggregate (cost=362.66..363.07 rows=41 width=29) (actual time=0.055..0.056 rows=2 loops=1)
-> Nested Loop (cost=11.79..362.55 rows=41 width=29) (actual time=0.044..0.054 rows=2 loops=1)
-> HashAggregate (cost=11.79..12.20 rows=41 width=4) (actual time=0.032..0.032 rows=2 loops=1)
-> Index Scan using members_commonid on members (cost=0.00..11.69 rows=41 width=4) (actual time=0.010..0.013 rows=2 loops=1)
Index Cond: (commonid = 3594)
-> Index Scan using cards_membid on cards (cost=0.00..8.53 rows=1 width=33) (actual time=0.007..0.007 rows=1 loops=2)
Index Cond: (public.cards.membid = public.members.membid)
-> Index Scan using cards_useraccount on cards (cost=0.00..12.87 rows=2 width=33) (actual time=0.019..0.019 rows=1 loops=2)
Index Cond: (public.cards.useraccount = public.cards.useraccount)
-> Index Scan using members_pkey on members (cost=0.00..0.70 rows=1 width=4) (actual time=0.006..0.007 rows=1 loops=2)
Index Cond: (public.members.membid = public.cards.membid)
Filter: (public.members.membershipid = 40)
-> Index Scan using argrades_membid on argrades (cost=0.00..2673.60 rows=716 width=14) (actual time=0.020..0.319 rows=236 loops=2)
Index Cond: (argrades.membid = public.members.membid)
Filter: (argrades.userstatus = 5)
Total runtime: 1.576 ms

Query on 8.4.4 shown below. Unfortunately the RPMs used for that install had enable-cassert.
Same run on identical machine with 8.4.5 was 120 seconds.
QUERY PLAN

--------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=8726078.65..8726078.66 rows=1 width=10) (actual time=280704.491..280704.492 rows=1 loops=1)
-> Hash Semi Join (cost=295565.48..8725460.91 rows=123547 width=10) (actual time=1995.191..280698.091 rows=472 loops=1)
Hash Cond: (argrades.membid = public.members.membid)
-> Seq Scan on argrades (cost=0.00..7705748.40 rows=197758125 width=14) (actual time=0.033..245808.983 rows=197504297 loops=1)
Filter: (userstatus = 5)
-> Hash (cost=265133.95..265133.95 rows=2434522 width=4) (actual time=1837.777..1837.777 rows=2 loops=1)
-> HashAggregate (cost=216443.51..240788.73 rows=2434522 width=4) (actual time=1834.352..1837.760 rows=2 loops=1)
-> Hash Join (cost=31151.39..210357.21 rows=2434522 width=4) (actual time=1620.620..1830.788 rows=2 loops=1)
Hash Cond: (public.members.membid = public.cards.membid)
-> Seq Scan on members (cost=0.00..121379.95 rows=2434956 width=4) (actual time=0.024..1085.143 rows=2435153 loops=1)
Filter: (membershipid = 40)
-> Hash (cost=719.87..719.87 rows=2434522 width=4) (actual time=241.921..241.921 rows=2 loops=1)
-> Nested Loop (cost=293.80..719.87 rows=2434522 width=4) (actual time=228.867..241.909 rows=2 loops=1)
-> HashAggregate (cost=293.80..294.13 rows=33 width=29) (actual time=169.551..169.553 rows=2 loops=1)
-> Nested Loop (cost=11.33..293.71 rows=33 width=29) (actual time=145.940..169.543 rows=2 loops=1)
-> HashAggregate (cost=11.33..11.66 rows=33 width=4) (actual time=64.730..64.732 rows=2 loops=1)
-> Index Scan using members_commonid on members (cost=0.00..11.25 rows=33 width=4) (actual time = 64.688..64.703 rows=2 loops=1)
Index Cond: (commonid = 3594)
-> Index Scan using cards_membid on cards (cost=0.00..8.53 rows=1 width=33) (actual time= 52.400..52.401 rows=1 loops=2)
Index Cond: (public.cards.membid = public.members.membid)
-> Index Scan using cards_useraccount on cards (cost=0.00..12.88 rows=2 width=33) (actual time=36.172.. 36.173 rows=1 loops=2)
Index Cond: (public.cards.useraccount = public.cards.useraccount)
Total runtime: 280730.327 ms

The 8.4 machines have more memory than the 8.3.7 and are in general much
better machines.
8.4 settings
Shared_buffers 18GB
effective_cache_size 18GB

Machines have 72GB of RAM
Tried turning off sequential scan on the 8.4.5 and that did not help.

Any ideas/suggestions?

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Brad Nicholson 2010-10-27 12:42:33 Re: AIX slow buffer reads
Previous Message Merlin Moncure 2010-10-27 11:05:44 Re: Re: Postgres insert performance and storage requirement compared to Oracle