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/

Christoph Berg <christoph(dot)berg(at)credativ(dot)de> writes:
> 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:

The newer rowcount estimates are much further away from reality:

> Unique (cost=1117.67..1118.46 rows=9 width=1115) (actual time=82.646..85.695 rows=439 loops=1)

> Unique (cost=784205.94..796940.08 rows=145533 width=1061) (actual time=9710.683..9713.175 rows=439 loops=1)

Has the new DB been analyzed? Maybe you had custom stats targets in
the old DB that didn't get copied to the new one?

regards, tom lane

On Tue, Apr 30, 2013 at 7:20 AM, Christoph Berg
<christoph(dot)berg(at)credativ(dot)de> wrote:
> -> 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))

The planner is estimating this the outer side of this nested loop will
produce 33 rows and that the inner side will produce 1. One would
assume that the row estimate for the join product couldn't be more
than 33 * 1 = 33 rows, but the planner is estimating 62335 rows, which
seems like nonsense. The actual result cardinality is 23.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Tue, 30 Apr 2013 06:20:55 -0500, Christoph Berg
<christoph(dot)berg(at)credativ(dot)de> wrote:

> 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:

What version of DBIx-SearchBuilder do you have on that server? The RT guys
usually recommend you have the latest possible so RT is performing the
most sane/optimized queries possible for your database. I honestly don't
know if it will make a difference for you, but it's worth a shot.

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> The planner is estimating this the outer side of this nested loop will
> produce 33 rows and that the inner side will produce 1. One would
> assume that the row estimate for the join product couldn't be more
> than 33 * 1 = 33 rows, but the planner is estimating 62335 rows, which
> seems like nonsense.

You know, of course, that the join size estimate isn't arrived at that
way. Still, this point does make it seem more like a planner bug and
less like bad input stats. It would be nice to see a self-contained
example ...

regards, tom lane

On Mon, May 13, 2013 at 4:14 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> The planner is estimating this the outer side of this nested loop will
>> produce 33 rows and that the inner side will produce 1. One would
>> assume that the row estimate for the join product couldn't be more
>> than 33 * 1 = 33 rows, but the planner is estimating 62335 rows, which
>> seems like nonsense.
>
> You know, of course, that the join size estimate isn't arrived at that
> way. Still, this point does make it seem more like a planner bug and
> less like bad input stats. It would be nice to see a self-contained
> example ...

Yeah, I remember there have been examples like this that have come up
before. Unfortunately, I haven't fully grokked what's actually going
on here that allows this kind of thing to happen. Refresh my memory
on where the relevant code is?

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Mon, May 13, 2013 at 4:14 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> You know, of course, that the join size estimate isn't arrived at that
>> way. Still, this point does make it seem more like a planner bug and
>> less like bad input stats. It would be nice to see a self-contained
>> example ...

> Yeah, I remember there have been examples like this that have come up
> before. Unfortunately, I haven't fully grokked what's actually going
> on here that allows this kind of thing to happen. Refresh my memory
> on where the relevant code is?

The point is that we estimate the size of a joinrel independently of
any particular input paths for it, and indeed before we've built any
such paths. So this seems like a bug somewhere in selectivity
estimation, but I'm not prepared to speculate as to just where.

regards, tom lane

On Mon, May 13, 2013 at 4:33 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> On Mon, May 13, 2013 at 4:14 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>>> You know, of course, that the join size estimate isn't arrived at that
>>> way. Still, this point does make it seem more like a planner bug and
>>> less like bad input stats. It would be nice to see a self-contained
>>> example ...
>
>> Yeah, I remember there have been examples like this that have come up
>> before. Unfortunately, I haven't fully grokked what's actually going
>> on here that allows this kind of thing to happen. Refresh my memory
>> on where the relevant code is?
>
> The point is that we estimate the size of a joinrel independently of
> any particular input paths for it, and indeed before we've built any
> such paths. So this seems like a bug somewhere in selectivity
> estimation, but I'm not prepared to speculate as to just where.

Hmm. I went looking for the relevant code and found
calc_joinrel_size_estimate(). If that's actually the right place to
be looking, it's hard to escape the conclusion that pselec > 1.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: Tom Lane 2013-05-06 <1583(dot)1367858328(at)sss(dot)pgh(dot)pa(dot)us>
> The newer rowcount estimates are much further away from reality:
>
> > Unique (cost=1117.67..1118.46 rows=9 width=1115) (actual time=82.646..85.695 rows=439 loops=1)
>
> > Unique (cost=784205.94..796940.08 rows=145533 width=1061) (actual time=9710.683..9713.175 rows=439 loops=1)
>
> Has the new DB been analyzed? Maybe you had custom stats targets in
> the old DB that didn't get copied to the new one?

The new DB was analyzed with various stats targets, including values
that were higher that anything we would have used in 8.1. I don't
think we had per-table settings in there (the actual DB is now gone
for good).

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

Re: Mark Felder 2013-05-13 <op(dot)ww1gv9fd34t2sn(at)markf(dot)office(dot)supranet(dot)net>
> What version of DBIx-SearchBuilder do you have on that server? The
> RT guys usually recommend you have the latest possible so RT is
> performing the most sane/optimized queries possible for your
> database. I honestly don't know if it will make a difference for
> you, but it's worth a shot.

That's a "never touch a running system" kind of machine there, we are
happy that they let us finally upgrade at least the PostgreSQL part of
the setup, so changing any perl libs there is out of the question.

The version is libdbix-searchbuilder-perl 1.26-1 from Debian Sarge/3.1
*cough*.

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

On Tue, May 14, 2013 at 11:52:29PM -0700, Christoph Berg wrote:
> Re: Mark Felder 2013-05-13 <op(dot)ww1gv9fd34t2sn(at)markf(dot)office(dot)supranet(dot)net>
> > What version of DBIx-SearchBuilder do you have on that server? The
> > RT guys usually recommend you have the latest possible so RT is
> > performing the most sane/optimized queries possible for your
> > database. I honestly don't know if it will make a difference for
> > you, but it's worth a shot.
>
> That's a "never touch a running system" kind of machine there, we are
> happy that they let us finally upgrade at least the PostgreSQL part of
> the setup, so changing any perl libs there is out of the question.
>
> The version is libdbix-searchbuilder-perl 1.26-1 from Debian Sarge/3.1
> *cough*.
>
> Christoph
> --

Hi Christoph,

I understand the sentiment but you really should consider upgrading. I
think the current release is 1.63 and since it is the DB interface it
could have a positive effect on your problem not to mention that they
do fix bugs. :)

Regards,
Ken