[rt-users] Slow loading of long tickets in 3.6.3
Justin Hayes
justin.hayes at orbisuk.com
Wed Apr 29 04:53:36 EDT 2009
I've implemented stripping out the middle portion of long tickets (set
to more than 200 transactions atm) and here's how I did it in case you
would like to do something similar. For a ticket with 100 comments/
replies that was taking 10s to load it now takes 3s, and it won't get
much slower even if the tickets get longer.
This is my diff from Ticket/Elements/ShowHistory:
/opt/rt3/local/html/Ticket/Elements$ diff ../../../../share/html/
Ticket/Elements/ShowHistory ShowHistory
84a85,87
> my $trans_count = $Transactions->Count;
> my $speed_msg_shown = 0;
>
85a89,117
>
> if ($TruncateLongTicket && $trans_count > 200 && (($j > 10) &&
($j < ($trans_count - 50)))) {
> $j++;
> if (( $Transaction->Type =~ /^(Create|Correspond|Comment)
$/ )) {
> $EntryNum++;
> }
> if ($speed_msg_shown == 0) {
> </%perl>
> <div class="ticket-transaction links<% $i % 2 ? ' odd' : ' even' %>">
> <table width="100%" cellspacing="0" cellpadding="2" border="0">
> <tr><td rowspan="2" valign="top" class="type"> </td>
> <td class="description">
> <br><br><br><br><br>
> <br><br><br><br><br>
> <br><br><br><br><br>
> Some entries have been removed to speed the loading of this long
ticket.<br>Please see the <a href="<% $RT::WebPath %>/Ticket/
History.html?id=<% $Ticket->Id %>">History</a> for a full Journal of
this Ticket.
> <br><br><br><br><br>
> <br><br><br><br><br>
> <br><br><br><br><br>
> </td></tr>
> </table>
> </div>
> <%perl>
> }
> $speed_msg_shown = 1;
> next;
> }
> $j++;
>
100d131
<
111a143
> EntryNum => (( $Transaction->Type =~ /^(Create|
Correspond|Comment)$/ ) ? (++$EntryNum) : " "),
146a179,181
> my $j;
> my $LastTransId;
> my $EntryNum;
161a197
> $TruncateLongTicket => 1
You can then use TruncateLongTicket as an argument to ShowHistory from
Display.html, History.html etc etc to decide when you want to do the
truncating......
Hope this is useful to someone!
Justin
On 29 Apr 2009, at 08:01, Justin Hayes wrote:
> 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
>
>
>
>
> _______________________________________________
> 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