[rt-users] RT 4 Upgrade Slow Performance

[Darren Nickerson]

On May 29, 2012, at 4:54 PM, Darren Nickerson wrote:
> 
> We're seeing similar performance regression after an upgrade from 4.0.0rc5 to 4.0.5. I just loaded a very short ticket for the first time, it took 16 seconds. I did a reload on the page, and it took less than 2 seconds. I also went to Tickets -> New Search, and it took a full 20 seconds to load. Subsequent reloads of that page were essentially immediate. Within 10 minutes of not using RT much, opening a few tickets etc but then letting it sit idle for 10 minutes, going back to Tickets->New Search once again took 20 seconds to load, and was fast on subsequent loads
> 
> Have I misconfigured or broken some cache mechanism?
> 
> Our support staff have complained of a variety of long hangs/pauses like this and I still haven't pinned it down enough much more than I outline above. Our setup is very vanilla, MySQL with very little customization of RT ... if there's instructions anywhere on how to figure out what's consuming all the time I'd be happy to dig into it and report back here. I've been meaning to try some of the other ways to invoke RT, we're using apache+FastCGI right now, but there just hasn't been time. Perhaps the next time I'm waiting for query builder to load ... ;-)


I enabled the profiler per Ruslan's advice, and loaded the new search page. It took over 20 seconds. It generated a lot of output, should I include it all here? I think the relevant bit might be:

=Mason= localhost -                                 /Elements/SelectOwnerDropdown {{{
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0021
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0045
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0020
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0042
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0018
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0038
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0018
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0037
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0019
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0038
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0019
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0038
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0019
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0038
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0019
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0038
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0019
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0038
=Mason= localhost -                                     /Elements/ShowUser {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose {{{
=Mason= localhost -                                         /Elements/ShowUserVerbose }}} 0.0019
=Mason= localhost -                                     /Elements/ShowUser }}} 0.0042
=Mason= localhost -                                 /Elements/SelectOwnerDropdown }}} 20.9869

I'm not sure how we get from all those small values to 20 seconds, but it does seem to represent the lion's share of the slow-down. The last few lines look like:

=Mason= localhost -         /Search/Build.html }}} 21.7671
=Mason= localhost -         /Elements/Footer {{{
=Mason= localhost -         /Elements/Footer }}} 0.0030
=Mason= localhost -     /autohandler }}} 21.7901
=Mason= localhost - /Search/Build.html }}} ENDS

So it would seem the SelectOwnerDropdown timer of 20.9869 represents most of the delay ... 

-Darren
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.bestpractical.com/pipermail/rt-users/attachments/20120529/56222761/attachment.htm>