[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