RT3.4 query needed a lot more tuning with 9.2 than it did with 8.1

Hi,

this is more of a report than a question, because we thought this
would be interesting to share.

We recently (finally) migrated an Request Tracker 3.4 database running
on 8.1.19 to 9.2.4. The queries used by rt3.4 are sometimes weird, but
8.1 coped without too much tuning. The schema looks like this:

http://bestpractical.com/rt/3.4-schema.png

One query that took about 80ms on 8.1.19 took 8s on 9.2.4:

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.Instance = 10) OR ( Groups_3.Domain = 'RT::Ticket-Role' AND Groups_3.Instance = 999028) ) AND Groups_3.Type = ACL_2.PrincipalType)
)
AND (ACL_2.ObjectType = 'RT::System' OR (ACL_2.ObjectType = 'RT::Queue' AND ACL_2.ObjectId = 10) )
ORDER BY main.Name ASC;

8.1 plan: (http://explain.depesz.com/s/gZ6)

Unique (cost=1117.67..1118.46 rows=9 width=1115) (actual time=82.646..85.695 rows=439 loops=1)
-> Sort (cost=1117.67..1117.70 rows=9 width=1115) (actual time=82.645..82.786 rows=1518 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=10.51..1117.53 rows=9 width=1115) (actual time=0.205..23.688 rows=1518 loops=1)
-> Nested Loop (cost=10.51..1087.81 rows=9 width=1119) (actual time=0.193..13.495 rows=1600 loops=1)
-> Nested Loop (cost=10.51..1060.15 rows=9 width=4) (actual time=0.175..3.307 rows=1635 loops=1)
-> Nested Loop (cost=10.51..536.13 rows=4 width=4) (actual time=0.161..1.057 rows=23 loops=1)
Join Filter: ((("outer".principalid = "inner".id) AND (("outer".principaltype)::text = 'Group'::text) AND ((("inner"."domain")::text = 'SystemInternal'::text) OR (("inner"."domain")::text = 'UserDefined'::text) OR (("inner"."domain")::text = 'ACLEquivalence'::text))) OR ((((("inner"."domain")::text = 'RT::Queue-Role'::text) AND ("inner".instance = 10)) OR ((("inner"."domain")::text = 'RT::Ticket-Role'::text) AND ("inner".instance = 999028))) AND (("inner"."type")::text = ("outer".principaltype)::text)))
-> Bitmap Heap Scan on acl acl_2 (cost=4.24..61.15 rows=33 width=13) (actual time=0.107..0.141 rows=22 loops=1)
Recheck Cond: ((((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::System'::text)) OR (((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::Queue'::text) AND (objectid = 10)))
-> BitmapOr (cost=4.24..4.24 rows=34 width=0) (actual time=0.097..0.097 rows=0 loops=1)
-> Bitmap Index Scan on acl1 (cost=0.00..2.13 rows=22 width=0) (actual time=0.054..0.054 rows=8 loops=1)
Index Cond: (((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::System'::text))
-> Bitmap Index Scan on acl1 (cost=0.00..2.11 rows=13 width=0) (actual time=0.041..0.041 rows=14 loops=1)
Index Cond: (((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::Queue'::text) AND (objectid = 10))
-> Bitmap Heap Scan on groups groups_3 (cost=6.27..14.32 rows=2 width=36) (actual time=0.036..0.036 rows=1 loops=22)
Recheck Cond: (("outer".principalid = groups_3.id) OR ((((groups_3."type")::text = ("outer".principaltype)::text) AND (groups_3.instance = 10) AND ((groups_3."domain")::text = 'RT::Queue-Role'::text)) OR (((groups_3."type")::text = ("outer".principaltype)::text) AND (groups_3.instance = 999028) AND ((groups_3."domain")::text = 'RT::Ticket-Role'::text))))
Filter: ((("domain")::text = 'SystemInternal'::text) OR (("domain")::text = 'UserDefined'::text) OR (("domain")::text = 'ACLEquivalence'::text) OR ((("domain")::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (instance = 999028))
-> BitmapOr (cost=6.27..6.27 rows=2 width=0) (actual time=0.033..0.033 rows=0 loops=22)
-> Bitmap Index Scan on groups_pkey (cost=0.00..2.00 rows=1 width=0) (actual time=0.006..0.006 rows=1 loops=22)
Index Cond: ("outer".principalid = groups_3.id)
-> BitmapOr (cost=4.02..4.02 rows=1 width=0) (actual time=0.025..0.025 rows=0 loops=22)
-> Bitmap Index Scan on groups2 (cost=0.00..2.01 rows=1 width=0) (actual time=0.013..0.013 rows=0 loops=22)
Index Cond: (((groups_3."type")::text = ("outer".principaltype)::text) AND (groups_3.instance = 10) AND ((groups_3."domain")::text = 'RT::Queue-Role'::text))
-> Bitmap Index Scan on groups2 (cost=0.00..2.01 rows=1 width=0) (actual time=0.011..0.011 rows=0 loops=22)
Index Cond: (((groups_3."type")::text = ("outer".principaltype)::text) AND (groups_3.instance = 999028) AND ((groups_3."domain")::text = 'RT::Ticket-Role'::text))
-> Index Scan using cachedgroupmembers3 on cachedgroupmembers cachedgroupmembers_4 (cost=0.00..130.13 rows=70 width=8) (actual time=0.007..0.074 rows=71 loops=23)
Index Cond: ("outer".id = cachedgroupmembers_4.groupid)
-> Index Scan using users_pkey on users main (cost=0.00..3.06 rows=1 width=1115) (actual time=0.004..0.005 rows=1 loops=1635)
Index Cond: (main.id = "outer".memberid)
-> Index Scan using principals_pkey on principals principals_1 (cost=0.00..3.29 rows=1 width=4) (actual time=0.005..0.005 rows=1 loops=1600)
Index Cond: ("outer".memberid = principals_1.id)
Filter: ((disabled = 0) AND (id <> 1))
Total runtime: 86.293 ms
(34 Zeilen)

Untuned 9.2 plan: (http://explain.depesz.com/s/mQw)

Unique (cost=784205.94..796940.08 rows=145533 width=1061) (actual time=9710.683..9713.175 rows=439 loops=1)
-> Sort (cost=784205.94..784569.77 rows=145533 width=1061) (actual time=9710.682..9710.792 rows=1518 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
Sort Method: quicksort Memory: 569kB
-> Hash Join (cost=379261.01..568771.27 rows=145533 width=1061) (actual time=6432.551..9673.393 rows=1518 loops=1)
Hash Cond: (principals_1.id = main.id)
-> Seq Scan on principals principals_1 (cost=0.00..111112.14 rows=4970343 width=4) (actual time=0.024..1903.364 rows=4970357 loops=1)
Filter: ((id <> 1) AND (disabled = 0))
Rows Removed by Filter: 149
-> Hash (cost=357969.80..357969.80 rows=145537 width=1065) (actual time=5887.121..5887.121 rows=1600 loops=1)
Buckets: 1024 Batches: 256 Memory Usage: 17kB
-> Merge Join (cost=327489.90..357969.80 rows=145537 width=1065) (actual time=5618.604..5880.608 rows=1600 loops=1)
Merge Cond: (main.id = cachedgroupmembers_4.memberid)
-> Index Scan using users_pkey on users main (cost=0.00..27100.40 rows=389108 width=1061) (actual time=0.032..205.696 rows=383693 loops=1)
-> Materialize (cost=327350.03..328077.71 rows=145536 width=4) (actual time=5618.545..5619.315 rows=1635 loops=1)
-> Sort (cost=327350.03..327713.87 rows=145536 width=4) (actual time=5618.539..5618.940 rows=1635 loops=1)
Sort Key: cachedgroupmembers_4.memberid
Sort Method: quicksort Memory: 125kB
-> Hash Join (cost=1868.02..312878.08 rows=145536 width=4) (actual time=0.890..5617.609 rows=1635 loops=1)
Hash Cond: (cachedgroupmembers_4.groupid = groups_3.id)
-> Seq Scan on cachedgroupmembers cachedgroupmembers_4 (cost=0.00..185630.60 rows=10696560 width=8) (actual time=0.018..2940.137 rows=10696622 loops=1)
-> Hash (cost=844.83..844.83 rows=62335 width=4) (actual time=0.760..0.760 rows=23 loops=1)
Buckets: 4096 Batches: 4 Memory Usage: 12kB
-> Nested Loop (cost=24.57..844.83 rows=62335 width=4) (actual time=0.109..0.633 rows=23 loops=1)
-> Bitmap Heap Scan on acl acl_2 (cost=8.90..61.36 rows=33 width=10) (actual time=0.070..0.112 rows=22 loops=1)
Recheck Cond: ((((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::System'::text)) OR (((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::Queue'::text) AND (objectid = 10)))
-> BitmapOr (cost=8.90..8.90 rows=35 width=0) (actual time=0.064..0.064 rows=0 loops=1)
-> Bitmap Index Scan on acl1 (cost=0.00..4.47 rows=22 width=0) (actual time=0.036..0.036 rows=8 loops=1)
Index Cond: (((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::System'::text))
-> Bitmap Index Scan on acl1 (cost=0.00..4.41 rows=13 width=0) (actual time=0.026..0.026 rows=14 loops=1)
Index Cond: (((rightname)::text = 'OwnTicket'::text) AND ((objecttype)::text = 'RT::Queue'::text) AND (objectid = 10))
-> Bitmap Heap Scan on groups groups_3 (cost=15.67..23.73 rows=1 width=30) (actual time=0.022..0.023 rows=1 loops=22)
Recheck Cond: ((acl_2.principalid = id) OR ((((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text)) OR (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))))
Filter: ((((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text) OR (((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (((domain)::text = 'RT::Ticket-Role'::text) AND (instance = 999028))) AND (((acl_2.principalid = id) AND ((acl_2.principaltype)::text = 'Group'::text) AND (((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text))) OR (((((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (((domain)::text = 'RT::Ticket-Role'::text) AND (instance = 999028))) AND ((type)::text = (acl_2.principaltype)::text))))
-> BitmapOr (cost=15.67..15.67 rows=2 width=0) (actual time=0.019..0.019 rows=0 loops=22)
-> Bitmap Index Scan on groups_pkey (cost=0.00..4.76 rows=1 width=0) (actual time=0.005..0.005 rows=1 loops=22)
Index Cond: (acl_2.principalid = id)
-> BitmapOr (cost=10.66..10.66 rows=1 width=0) (actual time=0.013..0.013 rows=0 loops=22)
-> Bitmap Index Scan on groups2 (cost=0.00..5.33 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text))
-> Bitmap Index Scan on groups2 (cost=0.00..5.33 rows=1 width=0) (actual time=0.006..0.006 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))
Total runtime: 9713.547 ms
(43 Zeilen)

Things got a lot better with enable_seqscan=off: (http://explain.depesz.com/s/WPt)

Unique (cost=1509543.77..1522277.91 rows=145533 width=1061) (actual time=306.972..309.551 rows=439 loops=1)
-> Sort (cost=1509543.77..1509907.60 rows=145533 width=1061) (actual time=306.971..307.108 rows=1518 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
Sort Method: quicksort Memory: 569kB
-> Nested Loop (cost=828855.15..1294109.10 rows=145533 width=1061) (actual time=2.951..267.996 rows=1518 loops=1)
Join Filter: (main.id = principals_1.id)
-> Merge Join (cost=828855.15..858971.23 rows=145537 width=1065) (actual time=2.940..260.852 rows=1600 loops=1)
Merge Cond: (cachedgroupmembers_4.memberid = main.id)
-> Sort (cost=828715.29..829079.13 rows=145537 width=4) (actual time=2.903..3.321 rows=1635 loops=1)
Sort Key: cachedgroupmembers_4.memberid
Sort Method: quicksort Memory: 125kB
-> Nested Loop (cost=15.67..814243.24 rows=145537 width=4) (actual time=0.234..2.407 rows=1635 loops=1)
-> Nested Loop (cost=15.67..1108.61 rows=62334 width=4) (actual time=0.219..0.903 rows=23 loops=1)
-> Index Only Scan using acl1 on acl acl_2 (cost=0.00..325.14 rows=33 width=10) (actual time=0.121..0.367 rows=22 loops=1)
Index Cond: (rightname = 'OwnTicket'::text)
Filter: (((objecttype)::text = 'RT::System'::text) OR (((objecttype)::text = 'RT::Queue'::text) AND (objectid = 10)))
Rows Removed by Filter: 220
Heap Fetches: 242
-> Bitmap Heap Scan on groups groups_3 (cost=15.67..23.73 rows=1 width=30) (actual time=0.023..0.023 rows=1 loops=22)
Recheck Cond: ((acl_2.principalid = id) OR ((((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text)) OR (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))))
Filter: ((((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text) OR (((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (((domain)::text = 'RT::Ticket-Role'::text) AND (instance = 999028))) AND (((acl_2.principalid = id) AND ((acl_2.principaltype)::text = 'Group'::text) AND (((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text))) OR (((((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (((domain)::text = 'RT::Ticket-Role'::text) AND (instance = 999028))) AND ((type)::text = (acl_2.principaltype)::text))))
-> BitmapOr (cost=15.67..15.67 rows=2 width=0) (actual time=0.019..0.019 rows=0 loops=22)
-> Bitmap Index Scan on groups_pkey (cost=0.00..4.76 rows=1 width=0) (actual time=0.005..0.005 rows=1 loops=22)
Index Cond: (acl_2.principalid = id)
-> BitmapOr (cost=10.66..10.66 rows=1 width=0) (actual time=0.013..0.013 rows=0 loops=22)
-> Bitmap Index Scan on groups2 (cost=0.00..5.33 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text))
-> Bitmap Index Scan on groups2 (cost=0.00..5.33 rows=1 width=0) (actual time=0.006..0.006 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))
-> Index Scan using cachedgroupmembers3 on cachedgroupmembers cachedgroupmembers_4 (cost=0.00..12.89 rows=15 width=8) (actual time=0.009..0.049 rows=71 loops=23)
Index Cond: (groupid = groups_3.id)
-> Index Scan using users_pkey on users main (cost=0.00..27100.40 rows=389108 width=1061) (actual time=0.030..201.696 rows=384832 loops=1)
-> Index Scan using principals_pkey on principals principals_1 (cost=0.00..2.98 rows=1 width=4) (actual time=0.003..0.004 rows=1 loops=1600)
Index Cond: (id = cachedgroupmembers_4.memberid)
Filter: ((id <> 1) AND (disabled = 0))
Rows Removed by Filter: 0
Total runtime: 309.868 ms
(37 Zeilen)

A similar result was with seqscans re-enabled, but effective_cache_size=32GB
(anything >= 2GB worked), and the cachedgroupmembers.memberis stats target set
to 500: (http://explain.depesz.com/s/GJa)

Unique (cost=422364.07..434891.88 rows=143175 width=1085) (actual time=313.184..315.682 rows=439 loops=1)
-> Sort (cost=422364.07..422722.01 rows=143175 width=1085) (actual time=313.181..313.301 rows=1518 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
Sort Method: quicksort Memory: 569kB
-> Nested Loop (cost=197638.24..342080.48 rows=143175 width=1085) (actual time=4.382..274.157 rows=1518 loops=1)
Join Filter: (main.id = principals_1.id)
-> Merge Join (cost=197638.24..220156.59 rows=143179 width=1089) (actual time=4.369..267.021 rows=1600 loops=1)
Merge Cond: (main.id = cachedgroupmembers_4.memberid)
-> Index Scan using users_pkey on users main (cost=0.00..19537.00 rows=389111 width=1085) (actual time=0.033..206.621 rows=383693 loops=1)
-> Sort (cost=197499.17..197857.11 rows=143178 width=4) (actual time=4.326..4.737 rows=1635 loops=1)
Sort Key: cachedgroupmembers_4.memberid
Sort Method: quicksort Memory: 125kB
-> Nested Loop (cost=15.67..185237.80 rows=143178 width=4) (actual time=0.088..3.749 rows=1635 loops=1)
-> Nested Loop (cost=15.67..937.99 rows=61327 width=4) (actual time=0.073..2.047 rows=23 loops=1)
-> Seq Scan on acl acl_2 (cost=0.00..154.68 rows=33 width=10) (actual time=0.022..1.485 rows=22 loops=1)
Filter: (((rightname)::text = 'OwnTicket'::text) AND (((objecttype)::text = 'RT::System'::text) OR (((objecttype)::text = 'RT::Queue'::text) AND (objectid = 10))))
Rows Removed by Filter: 4912
-> Bitmap Heap Scan on groups groups_3 (cost=15.67..23.73 rows=1 width=30) (actual time=0.024..0.024 rows=1 loops=22)
Recheck Cond: ((acl_2.principalid = id) OR ((((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text)) OR (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))))
Filter: ((((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text) OR (((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (instance = 999028)) AND (((acl_2.principalid = id) AND ((acl_2.principaltype)::text = 'Group'::text) AND (((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text))) OR (((((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (((domain)::text = 'RT::Ticket-Role'::text) AND (instance = 999028))) AND ((type)::text = (acl_2.principaltype)::text))))
-> BitmapOr (cost=15.67..15.67 rows=2 width=0) (actual time=0.020..0.020 rows=0 loops=22)
-> Bitmap Index Scan on groups_pkey (cost=0.00..4.76 rows=1 width=0) (actual time=0.005..0.005 rows=1 loops=22)
Index Cond: (acl_2.principalid = id)
-> BitmapOr (cost=10.66..10.66 rows=1 width=0) (actual time=0.014..0.014 rows=0 loops=22)
-> Bitmap Index Scan on groups2 (cost=0.00..5.33 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text))
-> Bitmap Index Scan on groups2 (cost=0.00..5.33 rows=1 width=0) (actual time=0.006..0.006 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))
-> Index Scan using cachedgroupmembers3 on cachedgroupmembers cachedgroupmembers_4 (cost=0.00..2.86 rows=15 width=8) (actual time=0.009..0.055 rows=71 loops=23)
Index Cond: (groupid = groups_3.id)
-> Index Scan using principals_pkey on principals principals_1 (cost=0.00..0.84 rows=1 width=4) (actual time=0.003..0.004 rows=1 loops=1600)
Index Cond: (id = cachedgroupmembers_4.memberid)
Filter: ((id <> 1) AND (disabled = 0))
Rows Removed by Filter: 0
Total runtime: 316.054 ms
(35 Zeilen)

This plan is still slower than the origial 80ms, due to the Index Scan on
users_pkey. Setting cpu_tuple_cost = 0.06 fixed this:
(http://explain.depesz.com/s/R0g)

Unique (cost=430656.51..443500.29 rows=146786 width=1065) (actual time=50.400..52.876 rows=441 loops=1)
-> Sort (cost=430656.51..431023.48 rows=146786 width=1065) (actual time=50.399..50.504 rows=1522 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
Sort Method: quicksort Memory: 570kB
-> Nested Loop (cost=8.36..368962.31 rows=146786 width=1065) (actual time=0.326..15.253 rows=1522 loops=1)
-> Nested Loop (cost=8.36..309751.83 rows=146786 width=8) (actual time=0.232..9.224 rows=1551 loops=1)
-> Nested Loop (cost=8.36..211474.01 rows=146790 width=4) (actual time=0.225..2.590 rows=1639 loops=1)
-> Nested Loop (cost=8.36..550.15 rows=63034 width=4) (actual time=0.213..0.919 rows=23 loops=1)
-> Index Only Scan using acl1 on acl acl_2 (cost=0.00..133.99 rows=33 width=10) (actual time=0.117..0.370 rows=22 loops=1)
Index Cond: (rightname = 'OwnTicket'::text)
Filter: (((objecttype)::text = 'RT::System'::text) OR (((objecttype)::text = 'RT::Queue'::text) AND (objectid = 10)))
Rows Removed by Filter: 220
Heap Fetches: 242
-> Bitmap Heap Scan on groups groups_3 (cost=8.36..12.55 rows=1 width=30) (actual time=0.023..0.023 rows=1 loops=22)
Recheck Cond: ((acl_2.principalid = id) OR ((((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text)) OR (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))))
Filter: ((((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text) OR (((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (instance = 999028)) AND (((acl_2.principalid = id) AND ((acl_2.principaltype)::text = 'Group'::text) AND (((domain)::text = 'SystemInternal'::text) OR ((domain)::text = 'UserDefined'::text) OR ((domain)::text = 'ACLEquivalence'::text))) OR (((((domain)::text = 'RT::Queue-Role'::text) AND (instance = 10)) OR (((domain)::text = 'RT::Ticket-Role'::text) AND (instance = 999028))) AND ((type)::text = (acl_2.principaltype)::text))))
-> BitmapOr (cost=8.36..8.36 rows=2 width=0) (actual time=0.019..0.019 rows=0 loops=22)
-> Bitmap Index Scan on groups_pkey (cost=0.00..2.51 rows=1 width=0) (actual time=0.005..0.005 rows=1 loops=22)
Index Cond: (acl_2.principalid = id)
-> BitmapOr (cost=5.60..5.60 rows=1 width=0) (actual time=0.014..0.014 rows=0 loops=22)
-> Bitmap Index Scan on groups2 (cost=0.00..2.80 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 10) AND ((domain)::text = 'RT::Queue-Role'::text))
-> Bitmap Index Scan on groups2 (cost=0.00..2.80 rows=1 width=0) (actual time=0.006..0.006 rows=0 loops=22)
Index Cond: (((type)::text = (acl_2.principaltype)::text) AND (instance = 999028) AND ((domain)::text = 'RT::Ticket-Role'::text))
-> Index Scan using cachedgroupmembers3 on cachedgroupmembers cachedgroupmembers_4 (cost=0.00..2.45 rows=15 width=8) (actual time=0.008..0.054 rows=71 loops=23)
Index Cond: (groupid = groups_3.id)
-> Index Scan using principals_pkey on principals principals_1 (cost=0.00..0.61 rows=1 width=4) (actual time=0.003..0.004 rows=1 loops=1639)
Index Cond: (id = cachedgroupmembers_4.memberid)
Filter: ((id <> 1) AND (disabled = 0))
Rows Removed by Filter: 0
-> Index Scan using users_pkey on users main (cost=0.00..0.34 rows=1 width=1065) (actual time=0.003..0.003 rows=1 loops=1551)
Index Cond: (id = cachedgroupmembers_4.memberid)
Total runtime: 53.174 ms
(33 Zeilen)

The tipping point for cpu_tuple_cost was 0.05, 0.04 didn't have any effect.

Old 8.1 config:
shared_buffers = 262144 # min 16 or max_connections*2, 8KB each
temp_buffers = 65536 # min 100, 8KB each
work_mem = 24576 # min 64, size in KB
maintenance_work_mem = 65536
effective_cache_size = 786432
default_statistics_target = 100

New 9.2 config:
shared_buffers = 4GB
work_mem = 32MB
random_page_cost = 2.0 (after tuning, but didn't change anything)
effective_cache_size = 32GB (after tuning)

Christoph
--
cb(at)df7cb(dot)de | http://www.df7cb.de/