Fw: slow query on RT 4.2.9 with postgres

I just upgraded from 4.0.7 to 4.2.9 and I am running to some very slow
page loads that were not an issue with the old version of RT.

When simply requesting the new search page (/Search/Build.html?NewQuery=1)
it takes about 20 seconds to load the page. PostgreSQL (version 9.3.5)
logs this slow query.

LOG: duration: 20985.257 ms execute : SELECT DISTINCT main.*
FROM Users main CROSS JOIN ACL ACL_3 JOIN Principals Principals_1 ON (
Principals_1.id = main.id ) JOIN CachedGroupMembers CachedGroupMembers_2
ON ( CachedGroupMembers_2.MemberId = Principals_1.id ) JOIN
CachedGroupMembers CachedGroupMembers_4 ON (
CachedGroupMembers_4.MemberId = Principals_1.id ) WHERE
((ACL_3.ObjectType = ‘RT::Queue’) OR (ACL_3.ObjectType = ‘RT::System’ AND
ACL_3.ObjectId = 1)) AND (ACL_3.PrincipalId =
CachedGroupMembers_4.GroupId) AND (ACL_3.PrincipalType = ‘Group’) AND
(ACL_3.RightName = ‘OwnTicket’ OR ACL_3.RightName = ‘SuperUser’) AND
(CachedGroupMembers_2.Disabled = ‘0’) AND (CachedGroupMembers_2.GroupId =
‘4’) AND (CachedGroupMembers_4.Disabled = ‘0’) AND (Principals_1.Disabled
= ‘0’) AND (Principals_1.PrincipalType = ‘User’) AND (Principals_1.id !=
‘1’) ORDER BY main.Name ASC

this (slow) query also shows up when look at the
Display/Basics/People/Jumbo tabs of a ticket in the general queue, but not
in other queues.

here is the result of the db expain.

rt4data=# explain analyze SELECT DISTINCT main.* FROM Users main CROSS
JOIN ACL ACL_3 JOIN Principals Principals_1 ON ( Principals_1.id =
main.id ) JOIN CachedGroupMembers CachedGroupMembers_2 ON (
CachedGroupMembers_2.MemberId = Principals_1.id ) JOIN CachedGroupMembers
CachedGroupMembers_4 ON ( CachedGroupMembers_4.MemberId = Principals_1.id
) WHERE ((ACL_3.ObjectType = ‘RT::Ticket’ AND ACL_3.ObjectId = 62017)
OR (ACL_3.ObjectType = ‘RT::Queue’ AND ACL_3.ObjectId = 1) OR
(ACL_3.ObjectType = ‘RT::System’ AND ACL_3.ObjectId = 1)) AND
(ACL_3.PrincipalId = CachedGroupMembers_4.GroupId) AND
(ACL_3.PrincipalType = ‘Group’) AND (ACL_3.RightName = ‘OwnTicket’ OR
ACL_3.RightName = ‘SuperUser’) AND (CachedGroupMembers_2.Disabled = ‘0’)
AND (CachedGroupMembers_2.GroupId = ‘4’) AND
(CachedGroupMembers_4.Disabled = ‘0’) AND (Principals_1.Disabled = ‘0’)
AND (Principals_1.PrincipalType = ‘User’) AND (Principals_1.id != ‘1’)
ORDER BY main.Name ASC;

QUERY PLAN

Unique (cost=681.60…681.69 rows=1 width=1136) (actual
time=20987.915…20988.043 rows=18 loops=1)
-> Sort (cost=681.60…681.60 rows=1 width=1136) (actual
time=20987.911…20987.919 rows=64 loops=1)
Sort Key: main.name, main.id, main.password, main.comments,
main.signature, main.emailaddress, main.freeformcontactinfo,
main.organization, m
ain.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, main.authtoken,
main.smimecertif
icate
Sort Method: quicksort Memory: 57kB
-> Nested Loop (cost=1.83…681.59 rows=1 width=1136) (actual
time=1.680…20985.026 rows=64 loops=1)
-> Nested Loop (cost=1.55…645.50 rows=2 width=1140)
(actual time=0.097…163.455 rows=90643 loops=1)
-> Nested Loop (cost=1.13…643.25 rows=1
width=1144) (actual time=0.057…1.141 rows=36 loops=1)
-> Nested Loop (cost=0.71…623.94 rows=13
width=1140) (actual time=0.044…0.578 rows=36 loops=1)
-> Index Only Scan using disgroumem on
cachedgroupmembers cachedgroupmembers_2 (cost=0.42…189.79 rows=83
width=4)
(actual time=0.031…0.109 rows=37 loops=1)
Index Cond: ((groupid = 4) AND
(disabled = 0))
Heap Fetches: 37
-> Index Scan using users_pkey on users
main (cost=0.29…5.22 rows=1 width=1136) (actual time=0.008…0.010 rows=1
l
oops=37)
Index Cond: (id =
cachedgroupmembers_2.memberid)
-> Index Scan using principals_pkey on
principals principals_1 (cost=0.42…1.48 rows=1 width=4) (actual
time=0.013…0.014
rows=1 loops=36)
Index Cond: (id = main.id)
Filter: ((id <> 1) AND (disabled = 0) AND
((principaltype)::text = ‘User’::text))
-> Index Scan using cachedgroupmembers1 on
cachedgroupmembers cachedgroupmembers_4 (cost=0.42…2.18 rows=7 width=8)
(actual tim
e=0.013…3.208 rows=2518 loops=36)
Index Cond: (memberid = principals_1.id)
Filter: (disabled = 0)
-> Index Only Scan using acl1 on acl acl_3
(cost=0.28…18.04 rows=1 width=4) (actual time=0.229…0.229 rows=0
loops=90643)
Index Cond: ((principaltype = ‘Group’::text) AND
(principalid = cachedgroupmembers_4.groupid))
Filter: ((((rightname)::text = ‘OwnTicket’::text) OR
((rightname)::text = ‘SuperUser’::text)) AND ((((objecttype)::text =
‘RT::Ti
cket’::text) AND (objectid = 62017)) OR (((objecttype)::text =
‘RT::Queue’::text) AND (objectid = 1)) OR (((objecttype)::text =
‘RT::System’::text) AN
D (objectid = 1))))
Rows Removed by Filter: 0
Heap Fetches: 20424
Total runtime: 20988.297 ms
(25 rows)

Any suggestions?

Thanks,
Mark Szidik
Midwest Collaborative for Library Services
1407 Rensen Street, Suite 1, Lansing, MI 48910-3657
Ph:800.530.9019 x117 Fax:517.492.3881
Ph:517.492.3817

I just upgraded from 4.0.7 to 4.2.9 and I am running to some very slow
page loads that were not an issue with the old version of RT.

When simply requesting the new search page
(/Search/Build.html?NewQuery=1
https://rt.mcls.org/Search/Build.html?NewQuery=1) it takes about 20
seconds to load the page. PostgreSQL (version 9.3.5) logs this slow
query.

LOG: duration: 20985.257 ms execute : SELECT DISTINCT main.*
FROM Users main CROSS JOIN ACL ACL_3 JOIN Principals Principals_1 ON (
Principals_1.id = main.id ) JOIN CachedGroupMembers CachedGroupMembers_2
ON ( CachedGroupMembers_2.MemberId = Principals_1.id ) JOIN
CachedGroupMembers CachedGroupMembers_4 ON (
CachedGroupMembers_4.MemberId = Principals_1.id ) WHERE
((ACL_3.ObjectType = ‘RT::Queue’) OR (ACL_3.ObjectType = 'RT::System’
AND ACL_3.ObjectId = 1)) AND (ACL_3.PrincipalId =
CachedGroupMembers_4.GroupId) AND (ACL_3.PrincipalType = ‘Group’) AND
(ACL_3.RightName = ‘OwnTicket’ OR ACL_3.RightName = ‘SuperUser’) AND
(CachedGroupMembers_2.Disabled = ‘0’) AND (CachedGroupMembers_2.GroupId
= ‘4’) AND (CachedGroupMembers_4.Disabled = ‘0’) AND
(Principals_1.Disabled = ‘0’) AND (Principals_1.PrincipalType = ‘User’)
AND (Principals_1.id != ‘1’) ORDER BY main.Name ASC

this (slow) query also shows up when look at the
Display/Basics/People/Jumbo tabs of a ticket in the general queue, but
not in other queues.

How many users have the “OwnTicket” right in the General queue? Have
you run “VACUUM ANALYZE” since the upgrade?

  • Alex

QUERY PLAN

On explain.depesz.com: http://explain.depesz.com/s/Reu

The great bulk of the cost is an index-only scan on acl using index
acl1, as input to a nested loop.

It looks like Pg might be trying to avoid using lots of sort memory. If
you, for testing purposes:

SET work_mem = ‘10MB’

EXPLAIN (BUFFERS, ANALYZE) SELECT …

do you get a different result?

Is it possible that the index is badly bloated? If you can afford the
exclusive lock, try REINDEXing acl1.

Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services