[rt-users] Slow loading of long tickets in 3.6.3

Justin Hayes justin.hayes at orbisuk.com
Wed Apr 29 02:35:20 EDT 2009


Thanks Ken but I think I'm already doing that in my SkipTransaction  
callback:

<%init>
   my $ttype;
   $ttype = $Transaction->Type;
   $$skip = 1 if (($_SkipSystemMessages) && ((($Transaction->Creator  
eq 1) && ($Transaction->Type ne 'Status') && ($Transaction->Type ne  
'Comment')) || (($Transaction->Creator eq 177) && (($Transaction->Type  
ne 'Give') && ($Transaction->Type ne 'Correspond'))) || ($Transaction- 
 >Type eq 'CustomField') || ($Transaction->Type eq 'Set' &&  
$Transaction->Field eq 'TimeWorked')) );
   my $type = $Transaction->Type;
</%init>

I'm basically only showing comment/correspondence and status changes.  
I'm not sure I can skip anything else.

So I think I'm going to need to look into ShowTransaction and  
ShowTransactionAttachments to see if there are savings to be had. I  
only need to save a couple of hundredths of a second per transaction  
to make a big difference on the longer tickets.

I'm also looking at moving to 3.8.2, but until I can get one set up to  
benchmark against I don't know if it's any faster in this regard.

Cheers,

Justin

On 28 Apr 2009, at 18:54, Kenneth Marshall wrote:

> 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
>>
>>
>>
>>
>>
> _______________________________________________
> 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