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

[Justin Hayes]

Alternatively I might look into only showing say the first 10  
transactions and last 30 for tickets with over 100 transactions or  
something (numbers are initial guesses).

I could pass a flag into ShowHistory to decide whether or not to do  
this (so I can disable it on the full History screen) and then work  
out how much to show based on how many transactions the ticket has.

Justin

On 29 Apr 2009, at 07:35, Justin Hayes wrote:

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