Regression: 8.3 2 seconds -> 8.4 100+ seconds - Mailing list pgsql-performance

From Francisco Reyes
Subject Regression: 8.3 2 seconds -> 8.4 100+ seconds
Date
Msg-id cone.1288183283.263738.5695.1000@shelca
Whole thread Raw
Responses Re: Regression: 8.3 2 seconds -> 8.4 100+ seconds
Re: Regression: 8.3 2 seconds -> 8.4 100+ seconds
Re: Regression: 8.3 2 seconds -> 8.4 100+ seconds
List 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=2loops=1) 
                                       ->  Nested Loop  (cost=11.79..362.55 rows=41 width=29) (actual time=0.044..0.054
rows=2loops=1) 
                                             ->  HashAggregate  (cost=11.79..12.20 rows=41 width=4) (actual
time=0.032..0.032rows=2 loops=1) 
                                                   ->  Index Scan using members_commonid on members  (cost=0.00..11.69
rows=41width=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)
(actualtime=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.007rows=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.319rows=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=197504297loops=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=2loops=1) 
                     ->  Hash Join  (cost=31151.39..210357.21 rows=2434522 width=4) (actual time=1620.620..1830.788
rows=2loops=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.143rows=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.909rows=2 loops=1) 
                                       ->  HashAggregate  (cost=293.80..294.13 rows=33 width=29) (actual
time=169.551..169.553rows=2 loops=1) 
                                             ->  Nested Loop  (cost=11.33..293.71 rows=33 width=29) (actual
time=145.940..169.543rows=2 loops=1) 
                                                   ->  HashAggregate  (cost=11.33..11.66 rows=33 width=4) (actual
time=64.730..64.732rows=2 loops=1) 
                                                         ->  Index Scan using members_commonid on members
(cost=0.00..11.25rows=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?

pgsql-performance by date:

Previous
From: Brad Nicholson
Date:
Subject: Re: AIX slow buffer reads
Next
From: Pavel Stehule
Date:
Subject: Re: Regression: 8.3 2 seconds -> 8.4 100+ seconds