[rt-users] Slow loading of long tickets in 3.6.3
Kenneth Marshall
ktm at rice.edu
Tue Apr 28 13:54:53 EDT 2009
Just looking at what we have:
while ( my $Transaction = $Transactions->Next ) {
my $skip = 0;
$m->comp( '/Elements/Callback',
_CallbackName => 'SkipTransaction',
Transaction => $Transaction,
skip => \$skip,
%ARGS );
next if $skip;
my $transcreator = $Transaction->Creator;
next if ( $transcreator == 1 and $ShowHeaders != 1 ); # RT_System
next if ( $transcreator == 96711 and $ShowHeaders != 1 ); # escalate
$i++;
...
I skip all the RT_System transactions unless the "full" option
is specified. That seemed to make the biggest difference. Everything
else ended up being a micro-optimization at best. As you have noticed,
the key is to reduce the amount of transactions processed completely.
Just nuking the RT_System transactions really helped.
My two cents,
Ken
On Tue, Apr 28, 2009 at 06:29:13PM +0100, Justin Hayes wrote:
> I'm already skipping a load of transactions, but there's a minimum I can
> cut down to.
>
> In ShowHistory we have this loop, where all the time goes. I've added
> interval logging round the 3 main sections
>
> 1) The skip checking
> 2) The attachment grepping
> 3) The call to ShowTransaction
>
> while ( my $Transaction = $Transactions->Next ) {
>
> my $t10 = [gettimeofday];
> my $skip = 0;
> $m->comp( '/Elements/Callback',
> _CallbackName => 'SkipTransaction',
> Transaction => $Transaction,
> skip => \$skip,
> %ARGS );
> next if $skip;
> $i++;
> my $elapsed10 = tv_interval ( $t10 );
> $RT::Logger->debug("Transaction Loop1 - time taken: $elapsed10");
>
> my @trans_attachments = grep { $_->TransactionId == $Transaction->Id }
> @attachments;
>
> my $trans_content = {};
> grep { ($_->TransactionId == $Transaction->Id ) &&
> ($trans_content->{$_->Id} = $_) } @attachment_content;
>
> $elapsed10 = tv_interval ( $t10 );
> $RT::Logger->debug("Transaction Loop2 - time taken: $elapsed10");
> #Args is first because we're clobbering the "Attachments" parameter
> $m->comp( 'ShowTransaction',
> %ARGS,
>
> AttachPath => $AttachPath,
> UpdatePath => $UpdatePath,
> Ticket => $Ticket,
> Transaction => $Transaction,
> ShowHeaders => $ShowHeaders,
> Collapsed => $Collapsed,
> RowNum => $i,
> EntryNum => ((
> $Transaction->Type =~ /^(Create|Correspond|Comment)$/ ) ? (++$EntryNum) : "
> "),
> ShowTitleBarCommands => $ShowTitleBarCommands,
> Attachments => \@trans_attachments,
> AttachmentContent => $trans_content,
> LastTransaction => $Transactions->IsLast
> );
>
> # manually flush the content buffer after each txn, so the user sees
> # some update
> $m->flush_buffer();
> $elapsed10 = tv_interval ( $t10 );
> $RT::Logger->debug("Transaction Loop3 - time taken: $elapsed10");
> }
>
> We get output like this (time taken to get from the start of the iteration
> to the logging point)
>
> Apr 28 18:17:14 calypso RT: Transaction Loop1 - time taken: 0.004148
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:102)
> Apr 28 18:17:14 calypso RT: Transaction Loop2 - time taken: 0.010705
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:110)
> Apr 28 18:17:14 calypso RT: Transaction Loop3 - time taken: 0.048624
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:133)
> Apr 28 18:17:14 calypso RT: Transaction Loop1 - time taken: 0.004812
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:102)
> Apr 28 18:17:14 calypso RT: Transaction Loop2 - time taken: 0.011379
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:110)
> Apr 28 18:17:14 calypso RT: Transaction Loop3 - time taken: 0.024753
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:133)
> Apr 28 18:17:14 calypso RT: Transaction Loop1 - time taken: 0.004143
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:102)
> Apr 28 18:17:14 calypso RT: Transaction Loop2 - time taken: 0.010706
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:110)
> Apr 28 18:17:14 calypso RT: Transaction Loop3 - time taken: 0.024104
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:133)
> Apr 28 18:17:14 calypso RT: Transaction Loop1 - time taken: 0.004148
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:102)
> Apr 28 18:17:14 calypso RT: Transaction Loop2 - time taken: 0.01071
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:110)
> Apr 28 18:17:14 calypso RT: Transaction Loop3 - time taken: 0.049055
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:133)
> Apr 28 18:17:14 calypso RT: Transaction Loop1 - time taken: 0.00481
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:102)
> Apr 28 18:17:14 calypso RT: Transaction Loop2 - time taken: 0.011399
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:110)
> Apr 28 18:17:14 calypso RT: Transaction Loop3 - time taken: 0.024773
> (/opt/rt3/local/html/Ticket/Elements/ShowHistory:133)
>
>
> So very little time lost checking for skip, then maybe 0.01s to get past
> the attachment grep, and then another 0.01 - 0.04s to show the transaction
> itself.
>
> So times that by 300 transactions and you're up to 10 secs easily.
>
> Those grep commands seem to cost 0.01 (which is 3s over 300 transactions)
> and I'm not sure what they do......
>
> Then you're into the ShowTransaction itself, where the bulk of the time
> goes, so maybe I need to look there next.
>
> Justin
>
> On 28 Apr 2009, at 18:12, Kenneth Marshall wrote:
>
>> Hi, Justin,
>>
>> We found similar results from a slow ticket load investigation.
>> For a "fix", we added a "brief" mode and a "full" mode to the
>> display code. The "full" mode show it all, but the "brief" mode
>> skipped uninteresting transactions. Maybe an approach like that
>> would help.
>>
>> Cheers,
>> Ken
>>
>> On Tue, Apr 28, 2009 at 04:19:21PM +0100, Justin Hayes wrote:
>>> I've put some high resolution timestamping into the code and found
>>> some interesting things.
>>>
>>> Am example ticket that took 10 seconds to render spent 8.17 seconds in
>>> the
>>>
>>> while ( my $Transaction = $Transactions->Next ) {
>>>
>>> loop inside ShowHistory:
>>>
>>> Apr 28 16:10:05 calypso RT: After Transaction Loop - time taken:
>>> 8.172556 (/opt/rt3/local/html/Ticket/Elements/ShowHistory:151)
>>>
>>> So then I put some logging in ShowTransaction
>>>
>>> Each INIT takes milliseconds (so I think we can discount that):
>>>
>>> Apr 28 16:10:05 calypso RT: <- ShowTransaction INIT - time taken:
>>> 0.006261 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:253)
>>>
>>> But each Body of ShowTransaction takes between 0.03 and 0.15 seconds eg:
>>>
>>> Apr 28 16:09:59 calypso RT: After show transaction - time taken:
>>> 0.130829 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:102)
>>> Apr 28 16:09:59 calypso RT: After show transaction - time taken:
>>> 0.038523 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:102)
>>> Apr 28 16:10:00 calypso RT: After show transaction - time taken:
>>> 0.033974 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:102)
>>> Apr 28 16:10:00 calypso RT: After show transaction - time taken:
>>> 0.027394 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:102)
>>> Apr 28 16:10:00 calypso RT: After show transaction - time taken:
>>> 0.030395 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:102)
>>> Apr 28 16:10:00 calypso RT: After show transaction - time taken:
>>> 0.005656 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:102)
>>> Apr 28 16:10:00 calypso RT: After show transaction - time taken:
>>> 0.030067 (/opt/rt3/local/html/Ticket/Elements/ShowTransaction:102)
>>>
>>> So multiply that for 100 comments + 100 other transactions (status
>>> changes etc) and it's easy to see where the time goes...
>>>
>>> Justin
>>>
>>>
>>> On 28 Apr 2009, at 16:06, Raed El-Hames wrote:
>>>
>>>> Justin;
>>>>
>>>> One of the other things I done here is to hide show summary by
>>>> default, as I noticed the ShowSummary and in particular
>>>> <& /Ticket/Elements/ShowRequestor, Ticket => $Ticket &> (Thats the
>>>> box that shows Other ticket by requestor etc)
>>>> was taking a long time to render
>>>>
>>>> If you can play and test in your system try to comment out
>>>> <& /Ticket/Elements/ShowSummary, Ticket => $TicketObj, Attachments
>>>> => $attachments &>
>>>>
>>>> see if ticket loading is quicker,
>>>> remember to restart apache after you do the change ..
>>>>
>>>> I am on 3.6.3 and some of our monitoring tickets are over 300
>>>> updates long .. having been through the pain you having, I tried all
>>>> possible options
>>>>
>>>> Roy
>>>>
>>>>
>>>> Justin Hayes wrote:
>>>>> Thanks for the advice Roy, but I think I'd already tried that at
>>>>> some point in the past:
>>>>>
>>>>> <tr>
>>>>> <td colspan="4" class="content <%perl> $m->print('hidden') if
>>>>> $Collapsed==2;</%perl>" id="txn-body-<%$Transaction->id%>">
>>>>> %# if ($Transaction->CustomFieldValues->Count) {
>>>>> %# <& /Elements/ShowCustomFields, Object => $Transaction &>
>>>>> %# }
>>>>> % $m->comp('ShowTransactionAttachments', %ARGS, Parent => 0)
>>>>> unless ($Collapsed==1 ||!$ShowBody);
>>>>> </td>
>>>>> </tr>
>>>>>
>>>>> Justin
>>>>>
>>>>> On 28 Apr 2009, at 11:00, Raed El-Hames wrote:
>>>>>
>>>>>
>>>>>> Justin;
>>>>>>
>>>>>> I 've had similar slow loading tickets in the past, and it turned
>>>>>> out (in my case) the problem was with transactions custom fields,
>>>>>> do you use those?? if you don't you can comment out the
>>>>>> following lines from Ticket/Elements/ShowTransaction
>>>>>>
>>>>>> 65 % if ($Transaction->CustomFieldValues->Count) {
>>>>>> 66 <& /Elements/ShowCustomFields, Object => $Transaction &>
>>>>>> 67 % }
>>>>>>
>>>>>> The numbers you see there are the line numbers
>>>>>>
>>>>>> Roy
>>>>>>
>>>>>>
>>>>>> Justin Hayes wrote:
>>>>>>
>>>>>>> Hi,
>>>>>>>
>>>>>>> Some of our tickets can get pretty long and the longer they get
>>>>>>> the longer the page takes to load. So for a long ticket with
>>>>>>> say 100 comments/replies and assorted status changes etc it
>>>>>>> might take 10+ seconds to render.
>>>>>>>
>>>>>>> A lot of the time seems to be looping over every transaction,
>>>>>>> checking permissions etc etc, I guess maybe to decide whether
>>>>>>> to display the reply/comment options and other things.
>>>>>>>
>>>>>>> Have any improvements been made to the history display code in
>>>>>>> 3.8? I would have thought it was more sensible to check
>>>>>>> permissions once for the ticket and then quickly render all the
>>>>>>> attachments, but I'm sure that's a simplistic view of it.
>>>>>>>
>>>>>>> Any thoughts welcome!
>>>>>>>
>>>>>>> Justin
>>>>>>>
>>>>>>> -------------------------------------------------
>>>>>>> Justin Hayes
>>>>>>> Orbis Support Manager
>>>>>>> justin.hayes at orbisuk.com
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> _______________________________________________
>>>>>>> http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-users
>>>>>>>
>>>>>>> Community help: http://wiki.bestpractical.com
>>>>>>> Commercial support: sales at bestpractical.com
>>>>>>>
>>>>>>>
>>>>>>> Discover RT's hidden secrets with RT Essentials from O'Reilly
>>>>>>> Media. Buy a copy at http://rtbook.bestpractical.com
>>>>>>>
>>>>>>>
>>>>>
>>>>>
>>>>> -------------------------------------------------
>>>>> Justin Hayes
>>>>> Orbis Support Manager
>>>>> justin.hayes at orbisuk.com
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>
>>>
>>> -------------------------------------------------
>>> Justin Hayes
>>> Orbis Support Manager
>>> justin.hayes at orbisuk.com
>>>
>>>
>>>
>>>
>>> _______________________________________________
>>> http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-users
>>>
>>> Community help: http://wiki.bestpractical.com
>>> Commercial support: sales at bestpractical.com
>>>
>>>
>>> Discover RT's hidden secrets with RT Essentials from O'Reilly Media.
>>> Buy a copy at http://rtbook.bestpractical.com
>>>
>> _______________________________________________
>> http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-users
>>
>> Community help: http://wiki.bestpractical.com
>> Commercial support: sales at bestpractical.com
>>
>>
>> Discover RT's hidden secrets with RT Essentials from O'Reilly Media.
>> Buy a copy at http://rtbook.bestpractical.com
>
>
> -------------------------------------------------
> Justin Hayes
> Orbis Support Manager
> justin.hayes at orbisuk.com
>
>
>
>
>
More information about the rt-users
mailing list