Same SQL, 104296ms of difference between 7.4.12 and 8.0.7

From: Rafael Martinez Guerrero <r(dot)m(dot)guerrero(at)usit(dot)uio(dot)no>
To: pgsql-performance(at)postgresql(dot)org
Subject: Same SQL, 104296ms of difference between 7.4.12 and 8.0.7
Date: 2006-04-07 12:45:33
Message-ID: 1144413933.24060.253.camel@bbking.uio.no
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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(dot)m(dot)guerrero(at)usit(dot)uio(dot)no>
Center for Information Technology Services
University of Oslo, Norway

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

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Richard Huxton 2006-04-07 13:31:17 Re: Same SQL, 104296ms of difference between 7.4.12 and
Previous Message Brian Herlihy 2006-04-07 06:41:08 Re: Query planner is using wrong index.