[rt-devel] Greatly increased query time after update to 4.2.9

[Jeff Albert]

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 at lists.bestpractical.com] On Behalf Of Jeff Albert
Sent: Thursday, November 27, 2014 9:57 AM
To: Christian Loos; rt-devel at 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 at netcologne.de]
Sent: Wednesday, November 26, 2014 10:52 PM
To: Jeff Albert; rt-devel at 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: