Greatly increased query time after update to 4.2.9

I’ve just updated the development instance of our RT service, which had been running at 4.0.8, to the latest 4.2.9 in preparation for a planned production update to follow. Unfortunately, we’ve hit a significant snag: the UI is now hugely slow in some views that were relatively snappy before the update. The slow query log identifies a likely culprit:

Query_time: 23 Lock_time: 0 Rows_sent: 28 Rows_examined: 858133

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’ AND ACL_3.ObjectId = 3) 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;

It appears that this query is reasonably well-indexed, but clearly something has changed in the schema updates between 4.0.8 and 4.2.9:

mysql> explain extended 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’ AND ACL_3.ObjectId = 3) 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;
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
| 1 | SIMPLE | CachedGroupMembers_2 | range | DisGrouMem,CachedGroupMembers3,cachedgroupmembers1 | DisGrouMem | 10 | NULL | 606 | Using where; Using index; Using temporary; Using filesort |
| 1 | SIMPLE | main | eq_ref | PRIMARY | PRIMARY | 4 | rt34.CachedGroupMembers_2.MemberId | 1 | |
| 1 | SIMPLE | Principals_1 | eq_ref | PRIMARY | PRIMARY | 4 | rt34.main.id | 1 | Using where; Distinct |
| 1 | SIMPLE | CachedGroupMembers_4 | ref | DisGrouMem,CachedGroupMembers3,cachedgroupmembers1 | CachedGroupMembers3 | 5 | rt34.CachedGroupMembers_2.MemberId | 1 | Using where; Distinct |
| 1 | SIMPLE | ACL_3 | range | ACL1 | ACL1 | 85 | NULL | 13 | Using where; Using index; Distinct |
5 rows in set, 1 warning (0.00 sec)

Can anyone offer any advice on what might have precipitated this sudden drop in query performance?

Cheers,

Jeff

Hi,

have you tried a mysql restart?
This fixed it for me (I didn’t dig deeper what exactly was the problem).

ChrisAm 27.11.2014 um 02:11 schrieb Jeff Albert:

I’ve just updated the development instance of our RT service, which had
been running at 4.0.8, to the latest 4.2.9 in preparation for a planned
production update to follow. Unfortunately, we’ve hit a significant
snag: the UI is now hugely slow in some views that were relatively
snappy before the update. The slow query log identifies a likely culprit:

Hi Chris,
Sadly a restart didn’t help; the first query after the restart was even worse as the cache got repopulated, and performance has since returned to where I found it immediately after the upgrade. Thanks for the suggestion, though! Has anybody else seen this with 4.2.9 installs?

Cheers,
JeffFrom: Christian Loos [mailto:cloos@netcologne.de]
Sent: Wednesday, November 26, 2014 10:52 PM
To: Jeff Albert; rt-devel@lists.bestpractical.com
Subject: Re: Greatly increased query time after update to 4.2.9

Hi,

have you tried a mysql restart?
This fixed it for me (I didn’t dig deeper what exactly was the problem).

Chris

Hi Jeff

I can’t reproduce this locally(I doubt it’s easy to reproduce too because it depends on quite a few things). I would suggest reproduce it on a test env and then “bisect” on an RT git repo to find the criminal commit.

Regards
sunnavy> On Nov 28, 2014, at 1:57 AM, Jeff Albert jralbert@uvic.ca wrote:

Hi Chris,
Sadly a restart didn’t help; the first query after the restart was even worse as the cache got repopulated, and performance has since returned to where I found it immediately after the upgrade. Thanks for the suggestion, though! Has anybody else seen this with 4.2.9 installs?

Cheers,
Jeff

-----Original Message-----
From: Christian Loos [mailto:cloos@netcologne.de]
Sent: Wednesday, November 26, 2014 10:52 PM
To: Jeff Albert; rt-devel@lists.bestpractical.com
Subject: Re: Greatly increased query time after update to 4.2.9

Hi,

have you tried a mysql restart?
This fixed it for me (I didn’t dig deeper what exactly was the problem).

Chris

Am 27.11.2014 um 02:11 schrieb Jeff Albert:

I’ve just updated the development instance of our RT service, which
had been running at 4.0.8, to the latest 4.2.9 in preparation for a
planned production update to follow. Unfortunately, we’ve hit a
significant
snag: the UI is now hugely slow in some views that were relatively
snappy before the update. The slow query log identifies a likely culprit:

Did some more digging on this issue today, and discovered the following difference between our production RT 4.0.8 environment and the underperforming test instance of RT 4.2.9: an extra join to CachedGroupMembers in a query that creates the SelectOwnerDropdown element under 4.2.9 produces a query that runs for 18 seconds (the one previously mentioned), as compared with 0.0023 seconds under 4.0.8.

4.2.9:
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’ AND ACL_3.ObjectId = 3) 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

Stack:
[/opt/rt-4.2.9/app/sbin/…/lib/RT/Handle.pm:1711]
[/opt/rt-4.2.9/perl/perls/perl-5.20.1-RT/lib/site_perl/5.20.1/DBIx/SearchBuilder/Handle.pm:588]
[/opt/rt-4.2.9/perl/perls/perl-5.20.1-RT/lib/site_perl/5.20.1/DBIx/SearchBuilder.pm:239]
[/opt/rt-4.2.9/app/sbin/…/lib/RT/SearchBuilder.pm:985]
[/opt/rt-4.2.9/perl/perls/perl-5.20.1-RT/lib/site_perl/5.20.1/DBIx/SearchBuilder.pm:507]
[/opt/rt-4.2.9/perl/perls/perl-5.20.1-RT/lib/site_perl/5.20.1/DBIx/SearchBuilder/Union.pm:112]
[/opt/rt-4.2.9/app/share/html/Elements/SelectOwnerDropdown:78]
[/opt/rt-4.2.9/app/share/html/Elements/SelectOwner:48]
[/opt/rt-4.2.9/app/share/html/Ticket/Elements/Reminders:138]
[/opt/rt-4.2.9/app/share/html/Ticket/Elements/Reminders:120]
[/opt/rt-4.2.9/app/share/html/Ticket/Elements/ShowSummary:80]
[/opt/rt-4.2.9/app/share/html/Widgets/TitleBox:56]
[/opt/rt-4.2.9/app/share/html/Ticket/Elements/ShowSummary:83]
[/opt/rt-4.2.9/app/share/html/Ticket/Display.html:62]
[/opt/rt-4.2.9/app/share/html/Widgets/TitleBox:56]
[/opt/rt-4.2.9/app/share/html/Ticket/Display.html:63]
[/opt/rt-4.2.9/app/share/html/Ticket/autohandler:66]
[/opt/rt-4.2.9/app/sbin/…/lib/RT/Interface/Web.pm:681]
[/opt/rt-4.2.9/app/sbin/…/lib/RT/Interface/Web.pm:369]
[/opt/rt-4.2.9/app/share/html/autohandler:53]

4.0.8:
SELECT DISTINCT main.* FROM Users main CROSS JOIN ACL ACL_2 JOIN Principals Principals_1 ON ( Principals_1.id = main.id ) JOIN CachedGroupMembers CachedGroupMembers_3 ON ( CachedGroupMembers_3.MemberId = Principals_1.id ) WHERE (Principals_1.Disabled = ‘0’) AND (ACL_2.PrincipalId = CachedGroupMembers_3.GroupId) AND (Principals_1.id != ‘1’) AND (ACL_2.PrincipalType = ‘Group’) AND (Principals_1.PrincipalType = ‘User’) AND (ACL_2.RightName = ‘OwnTicket’ OR ACL_2.RightName = ‘SuperUser’) AND (CachedGroupMembers_3.Disabled = ‘0’) AND ((ACL_2.ObjectType = ‘RT::Queue’ AND ACL_2.ObjectId = 3) OR (ACL_2.ObjectType = ‘RT::System’) OR (ACL_2.ObjectType = ‘RT::Queue’ AND ACL_2.ObjectId = 3) OR (ACL_2.ObjectType = ‘RT::System’)) ORDER BY main.Name ASC

Stack:
[/opt/rt4/sbin/…/lib/RT/Handle.pm:1190]
[/opt/rt_perl/lib/perl5/DBIx/SearchBuilder/Handle.pm:511]
[/opt/rt_perl/lib/perl5/DBIx/SearchBuilder.pm:235]
[/opt/rt4/sbin/…/lib/RT/SearchBuilder.pm:343]
[/opt/rt_perl/lib/perl5/DBIx/SearchBuilder.pm:503]
[/opt/rt_perl/lib/perl5/DBIx/SearchBuilder/Union.pm:112]
[/opt/rt4/share/html/Elements/SelectOwnerDropdown:80]
[/opt/rt4/share/html/Elements/SelectOwner:48]
[/opt/rt4/share/html/Ticket/Elements/Reminders:128]
[/opt/rt4/share/html/Ticket/Elements/Reminders:116]
[/opt/rt4/share/html/Ticket/Elements/ShowSummary:79]
[/opt/rt4/share/html/Widgets/TitleBox:56]
[/opt/rt4/share/html/Ticket/Elements/ShowSummary:83]
[/opt/rt4/share/html/Ticket/Display.html:61]
[/opt/rt4/share/html/Widgets/TitleBox:56]
[/opt/rt4/share/html/Ticket/Display.html:62]
[/opt/rt4/share/html/Ticket/autohandler:19]
[/opt/rt4/sbin/…/lib/RT/Interface/Web.pm:621]
[/opt/rt4/sbin/…/lib/RT/Interface/Web.pm:326]
[/opt/rt4/share/html/autohandler:53]

I’ve glanced at the code, and at the commit history, but it’s not apparent to me what’s changed in the building of the query that leads to this extra join; nevertheless, this is certainly the problem. RT devs, should I be raising this as a bug against 4.2.9?

Cheers,
JeffFrom: rt-devel [mailto:rt-devel-bounces@lists.bestpractical.com] On Behalf Of Jeff Albert
Sent: Thursday, November 27, 2014 9:57 AM
To: Christian Loos; rt-devel@lists.bestpractical.com
Subject: Re: [rt-devel] Greatly increased query time after update to 4.2.9

Hi Chris,
Sadly a restart didn’t help; the first query after the restart was even worse as the cache got repopulated, and performance has since returned to where I found it immediately after the upgrade. Thanks for the suggestion, though! Has anybody else seen this with 4.2.9 installs?

Cheers,
Jeff

From: Christian Loos [mailto:cloos@netcologne.de]
Sent: Wednesday, November 26, 2014 10:52 PM
To: Jeff Albert; rt-devel@lists.bestpractical.com
Subject: Re: Greatly increased query time after update to 4.2.9

Hi,

have you tried a mysql restart?
This fixed it for me (I didn’t dig deeper what exactly was the problem).

Chris

Did some more digging on this issue today, and discovered the
following difference between our production RT 4.0.8 environment and the
underperforming test instance of RT 4.2.9: an extra join to
CachedGroupMembers in a query that creates the SelectOwnerDropdown
element under 4.2.9 produces a query that runs for 18 seconds (the one
previously mentioned), as compared with 0.0023 seconds under 4.0.8.

The extra join to CGM is to limit the Owner drop-down to Privileged
users; this is a performance win for those folks that have granted
OwnTicket to Everyone instead of to Privileged.

In most places, the join order is:
ACL -> CGM -> Users -> Principals -> CGM (Privileged limit)

How many Privileged users do you have? How many ACL rows, and OwnTicket
/ SuperUser ACL grants? Do you have OwnTicket granted very broadly?

  • Alex