Same SQL, 104296ms of difference between 7.4.12 and 8.0.7 - Mailing list pgsql-performance

From Rafael Martinez Guerrero
Subject Same SQL, 104296ms of difference between 7.4.12 and 8.0.7
Date
Msg-id 1144413933.24060.253.camel@bbking.uio.no
Whole thread Raw
Responses Re: Same SQL, 104296ms of difference between 7.4.12 and  (Richard Huxton <dev@archonet.com>)
Re: Same SQL, 104296ms of difference between 7.4.12 and 8.0.7  (Tom Lane <tgl@sss.pgh.pa.us>)
List pgsql-performance
Hello

I have a sql statement that takes 108489.780 ms with 8.0.7 in a
RHEL4/amd64linux server with 2xAMD Opteron(tm) Processor 275 2.00GHz /
8GB RAM and only 4193.588 ms with 7.4.12 in a RHEL3/386linux server with
2xIntel(R) Xeon(TM) CPU 2.40GHz / 4GB RAM.

Some information:

- There is no IO when I am running the sql, but it uses 99% of the cpu.
- I run VACUUM VERBOSE ANALYZE in both databases before the test.
- The databases are identical.
- No other jobs running when testing.
- Some different parameters between 7.4.12 and 8.0.7 :

7.4.12:
-------
shared_buffers = 114966   #(15% of ram)
sort_mem = 16384
vacuum_mem = 524288
wal_buffers = 64
checkpoint_segments = 16
effective_cache_size = 383220   #(50% ram)
random_page_cost = 3
default_statistics_target = 100

8.0.7:
------
shared_buffers = 250160   #(25% ram)
work_mem = 8192
maintenance_work_mem = 131072
wal_buffers = 128
checkpoint_segments = 64
effective_cache_size = 500321  #(50% ram)
random_page_cost = 3
default_statistics_target = 100

Any ideas of what I can test/configurate to find out why this happens?
Thanks in advance.


*******************
With 7.4.12
*******************
rtprod=# explain analyze SELECT DISTINCT main.* FROM Users main ,
Principals Principals_1, ACL ACL_2, Groups Groups_3, CachedGroupMembers
CachedGroupMembers_4  WHERE ((ACL_2.RightName = 'OwnTicket')) AND
((CachedGroupMembers_4.MemberId = Principals_1.id)) AND ((Groups_3.id =
CachedGroupMembers_4.GroupId)) AND ((Principals_1.Disabled =
'0')OR(Principals_1.Disabled = '0')) AND ((Principals_1.id != '1')) AND
((main.id = Principals_1.id)) AND  ( (    ACL_2.PrincipalId =
Groups_3.id AND ACL_2.PrincipalType = 'Group' AND (   Groups_3.Domain =
'SystemInternal' OR Groups_3.Domain = 'UserDefined' OR Groups_3.Domain =
'ACLEquivalence')) OR ( ( (Groups_3.Domain = 'RT::Queue-Role' )  )  AND
Groups_3.Type = ACL_2.PrincipalType) )  AND (ACL_2.ObjectType =
'RT::System' OR  (ACL_2.ObjectType = 'RT::Queue') )  ORDER BY main.Name
ASC;



                                                                                    QUERYPLAN


                                                                       

 Unique  (cost=40250.00..40250.09 rows=1 width=695) (actual
time=3974.528..4182.343 rows=264 loops=1)
   ->  Sort  (cost=40250.00..40250.00 rows=1 width=695) (actual
time=3974.522..3992.487 rows=24697 loops=1)
         Sort Key: main.name, main.id, main."password", main.comments,
main.signature, main.emailaddress, main.freeformcontactinfo,
main.organization, main.realname, main.nickname, main.lang,
main.emailencoding, main.webencoding, main.externalcontactinfoid,
main.contactinfosystem, main.externalauthid, main.authsystem,
main.gecos, main.homephone, main.workphone, main.mobilephone,
main.pagerphone, main.address1, main.address2, main.city, main.state,
main.zip, main.country, main.timezone, main.pgpkey, main.creator,
main.created, main.lastupdatedby, main.lastupdated
         ->  Nested Loop  (cost=33.67..40249.99 rows=1 width=695)
(actual time=37.793..3240.146 rows=24697 loops=1)
               ->  Nested Loop  (cost=33.67..40246.95 rows=1 width=699)
(actual time=37.754..2635.812 rows=24697 loops=1)
                     ->  Nested Loop  (cost=33.67..40242.47 rows=1
width=4) (actual time=37.689..2091.634 rows=24755 loops=1)
                           ->  Nested Loop  (cost=33.67..40225.72 rows=1
width=4) (actual time=37.663..1967.388 rows=54 loops=1)
                                 Join Filter:
(((("outer"."domain")::text = 'RT::Queue-Role'::text) OR
("inner".principalid = "outer".id)) AND ((("outer"."type")::text =
("inner".principaltype)::text) OR ("inner".principalid = "outer".id))
AND ((("outer"."domain")::text = 'RT::Queue-Role'::text) OR
(("inner".principaltype)::text = 'Group'::text)) AND
((("outer"."type")::text = ("inner".principaltype)::text) OR
(("inner".principaltype)::text = 'Group'::text)) AND
((("outer"."type")::text = ("inner".principaltype)::text) OR
(("outer"."domain")::text = 'SystemInternal'::text) OR
(("outer"."domain")::text = 'UserDefined'::text) OR
(("outer"."domain")::text = 'ACLEquivalence'::text)))
                                 ->  Index Scan using groups4, groups4,
groups4, groups4 on groups groups_3  (cost=0.00..2164.05 rows=15845
width=32) (actual time=0.041..43.636 rows=16160 loops=1)
                                       Index Cond: ((("domain")::text =
'RT::Queue-Role'::text) OR (("domain")::text = 'SystemInternal'::text)
OR (("domain")::text = 'UserDefined'::text) OR (("domain")::text =
'ACLEquivalence'::text))
                                 ->  Materialize  (cost=33.67..34.15
rows=48 width=13) (actual time=0.001..0.040 rows=54 loops=16160)
                                       ->  Seq Scan on acl acl_2
(cost=0.00..33.67 rows=48 width=13) (actual time=0.016..0.989 rows=54
loops=1)
                                             Filter: (((rightname)::text
= 'OwnTicket'::text) AND (((objecttype)::text = 'RT::System'::text) OR
((objecttype)::text = 'RT::Queue'::text)))
                           ->  Index Scan using cachedgroupmembers3 on
cachedgroupmembers cachedgroupmembers_4  (cost=0.00..16.45 rows=23
width=8) (actual time=0.015..1.296 rows=458 loops=54)
                                 Index Cond: ("outer".id =
cachedgroupmembers_4.groupid)
                     ->  Index Scan using users_pkey on users main
(cost=0.00..4.47 rows=1 width=695) (actual time=0.007..0.009 rows=1
loops=24755)
                           Index Cond: (main.id = "outer".memberid)
               ->  Index Scan using principals_pkey on principals
principals_1  (cost=0.00..3.02 rows=1 width=4) (actual time=0.010..0.012
rows=1 loops=24697)
                     Index Cond: ("outer".id = principals_1.id)
                     Filter: ((disabled = 0::smallint) AND (id <> 1))
 Total runtime: 4193.588 ms
(21 rows)


*****************************
With 8.0.7
*****************************

rtprod=# explain analyze SELECT DISTINCT main.* FROM Users main ,
Principals Principals_1, ACL ACL_2, Groups Groups_3, CachedGroupMembers
CachedGroupMembers_4  WHERE ((ACL_2.RightName = 'OwnTicket')) AND
((CachedGroupMembers_4.MemberId = Principals_1.id)) AND ((Groups_3.id =
CachedGroupMembers_4.GroupId)) AND ((Principals_1.Disabled =
'0')OR(Principals_1.Disabled = '0')) AND ((Principals_1.id != '1')) AND
((main.id = Principals_1.id)) AND  ( (    ACL_2.PrincipalId =
Groups_3.id AND ACL_2.PrincipalType = 'Group' AND (   Groups_3.Domain =
'SystemInternal' OR Groups_3.Domain = 'UserDefined' OR Groups_3.Domain =
'ACLEquivalence')) OR ( ( (Groups_3.Domain = 'RT::Queue-Role' )  )  AND
Groups_3.Type = ACL_2.PrincipalType) )  AND (ACL_2.ObjectType =
'RT::System' OR  (ACL_2.ObjectType = 'RT::Queue') )  ORDER BY main.Name
ASC;




                              QUERYPLAN

                                                                             
 Unique  (cost=164248.03..164250.91 rows=33 width=695) (actual
time=108249.642..108479.808 rows=264 loops=1)
   ->  Sort  (cost=164248.03..164248.11 rows=33 width=695) (actual
time=108249.637..108293.474 rows=24697 loops=1)
         Sort Key: main.name, main.id, main."password", main.comments,
main.signature, main.emailaddress, main.freeformcontactinfo,
main.organization, main.realname, main.nickname, main.lang,
main.emailencoding, main.webencoding, main.externalcontactinfoid,
main.contactinfosystem, main.externalauthid, main.authsystem,
main.gecos, main.homephone, main.workphone, main.mobilephone,
main.pagerphone, main.address1, main.address2, main.city, main.state,
main.zip, main.country, main.timezone, main.pgpkey, main.creator,
main.created, main.lastupdatedby, main.lastupdated
         ->  Nested Loop  (cost=4702.57..164247.19 rows=33 width=695)
(actual time=2949.010..107407.145 rows=24697 loops=1)
               Join Filter: ((("inner".principalid = "outer".id) AND
(("inner".principaltype)::text = 'Group'::text) AND
((("outer"."domain")::text = 'SystemInternal'::text) OR
(("outer"."domain")::text = 'UserDefined'::text) OR
(("outer"."domain")::text = 'ACLEquivalence'::text))) OR
((("outer"."domain")::text = 'RT::Queue-Role'::text) AND
(("outer"."type")::text = ("inner".principaltype)::text)))
               ->  Hash Join  (cost=4667.85..51078.88 rows=62852
width=727) (actual time=649.028..13602.451 rows=513264 loops=1)
                     Hash Cond: ("outer".groupid = "inner".id)
                     ->  Merge Join  (cost=0.00..32353.73 rows=62852
width=699) (actual time=0.809..6644.928 rows=513264 loops=1)
                           Merge Cond: ("outer".id = "inner".memberid)
                           ->  Merge Join  (cost=0.00..6379.54
rows=15877 width=699) (actual time=0.118..911.395 rows=15866 loops=1)
                                 Merge Cond: ("outer".id = "inner".id)
                                 ->  Index Scan using users_pkey on
users main  (cost=0.00..1361.01 rows=15880 width=695) (actual
time=0.016..49.141 rows=15880 loops=1)
                                 ->  Index Scan using principals_pkey on
principals principals_1  (cost=0.00..4399.08 rows=168394 width=4)
(actual time=0.026..412.688 rows=168409 loops=1)
                                       Filter: ((disabled = 0::smallint)
AND (id <> 1))
                           ->  Index Scan using cachedgroupmembers2 on
cachedgroupmembers cachedgroupmembers_4  (cost=0.00..18647.25
rows=666758 width=8) (actual time=0.008..1513.877 rows=666754 loops=1)
                     ->  Hash  (cost=3094.48..3094.48 rows=152548
width=32) (actual time=637.618..637.618 rows=0 loops=1)
                           ->  Seq Scan on groups groups_3
(cost=0.00..3094.48 rows=152548 width=32) (actual time=0.017..333.669
rows=152548 loops=1)
               ->  Materialize  (cost=34.72..35.20 rows=48 width=13)
(actual time=0.001..0.077 rows=54 loops=513264)
                     ->  Seq Scan on acl acl_2  (cost=0.00..34.67
rows=48 width=13) (actual time=0.013..0.850 rows=54 loops=1)
                           Filter: (((rightname)::text =
'OwnTicket'::text) AND (((objecttype)::text = 'RT::System'::text) OR
((objecttype)::text = 'RT::Queue'::text)))
 Total runtime: 108486.306 ms
(21 rows)




--
Rafael Martinez, <r.m.guerrero@usit.uio.no>
Center for Information Technology Services
University of Oslo, Norway

PGP Public Key: http://folk.uio.no/rafael/


pgsql-performance by date:

Previous
From: Brian Herlihy
Date:
Subject: Re: Query planner is using wrong index.
Next
From: Richard Huxton
Date:
Subject: Re: Same SQL, 104296ms of difference between 7.4.12 and