RT3.4 query needed a lot more tuning with 9.2 than it did with 8.1 - Mailing list pgsql-performance

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.141rows=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.054rows=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.041rows=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.036rows=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)
(actualtime=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=0loops=22) 
                                                   ->  Bitmap Index Scan on groups2  (cost=0.00..2.01 rows=1 width=0)
(actualtime=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)
(actualtime=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.13rows=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.005rows=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)
(actualtime=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.364rows=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=1600loops=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)
(actualtime=0.032..205.696 rows=383693 loops=1) 
                           ->  Materialize  (cost=327350.03..328077.71 rows=145536 width=4) (actual
time=5618.545..5619.315rows=1635 loops=1) 
                                 ->  Sort  (cost=327350.03..327713.87 rows=145536 width=4) (actual
time=5618.539..5618.940rows=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.609rows=1635 loops=1) 
                                             Hash Cond: (cachedgroupmembers_4.groupid = groups_3.id)
                                             ->  Seq Scan on cachedgroupmembers cachedgroupmembers_4
(cost=0.00..185630.60rows=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.760rows=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.633rows=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.064rows=0 loops=1) 
                                                                     ->  Bitmap Index Scan on acl1  (cost=0.00..4.47
rows=22width=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=13width=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=1width=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.019rows=0 loops=22) 
                                                                     ->  Bitmap Index Scan on groups_pkey
(cost=0.00..4.76rows=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)
(actualtime=0.013..0.013 rows=0 loops=22) 
                                                                           ->  Bitmap Index Scan on groups2
(cost=0.00..5.33rows=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.33rows=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=1635loops=1) 
                                 ->  Nested Loop  (cost=15.67..1108.61 rows=62334 width=4) (actual time=0.219..0.903
rows=23loops=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)
(actualtime=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=0loops=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.013rows=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.89rows=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)
(actualtime=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)
(actualtime=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)
(actualtime=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=1635loops=1) 
                                 ->  Nested Loop  (cost=15.67..937.99 rows=61327 width=4) (actual time=0.073..2.047
rows=23loops=1) 
                                       ->  Seq Scan on acl acl_2  (cost=0.00..154.68 rows=33 width=10) (actual
time=0.022..1.485rows=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)
(actualtime=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=0loops=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.014rows=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.86rows=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)
(actualtime=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)
(actualtime=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.023rows=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)
(actualtime=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=0loops=22) 
                                                   ->  Bitmap Index Scan on groups2  (cost=0.00..2.80 rows=1 width=0)
(actualtime=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)
(actualtime=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.45rows=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)
(actualtime=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.003rows=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@df7cb.de | http://www.df7cb.de/