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
