Mailing List Archive

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
Re: Greatly increased query time after update to 4.2.9 [ In reply to ]
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:
Re: Greatly increased query time after update to 4.2.9 [ In reply to ]
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:
Re: Greatly increased query time after update to 4.2.9 [ In reply to ]
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:
Re: Greatly increased query time after update to 4.2.9 [ In reply to ]
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:
>
Re: Greatly increased query time after update to 4.2.9 [ In reply to ]
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,
Jeff

-----Original Message-----
From: 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

-----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:
Re: Greatly increased query time after update to 4.2.9 [ In reply to ]
On 12/15/2014 11:32 PM, Jeff Albert wrote:
> 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