[rt-users] Slow loading of long tickets in 3.6.3
Kenneth Marshall
ktm at rice.edu
Wed Apr 29 08:44:40 EDT 2009
Justin,
Thank you for the code for your addition. It will be useful to have
it in the bag-o-tricks when this problem rears its head here.
Cheers,
Ken
On Wed, Apr 29, 2009 at 09:53:36AM +0100, Justin Hayes wrote:
> 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