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

Justin Hayes justin.hayes at orbisuk.com
Tue Apr 28 13:29:13 EDT 2009 

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