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
- The skip checking
- The attachment grepping
- 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.
JustinOn 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:
%# if ($Transaction->CustomFieldValues->Count) {
%# <& /Elements/ShowCustomFields, Object => $Transaction &>
%# }
% $m->comp('ShowTransactionAttachments', %ARGS, Parent => 0)
unless ($Collapsed==1 ||!$ShowBody);
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@orbisuk.com
The rt-users Archives
Community help: http://wiki.bestpractical.com
Commercial support: sales@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@orbisuk.com
Justin Hayes
Orbis Support Manager
justin.hayes@orbisuk.com
The rt-users Archives
Community help: http://wiki.bestpractical.com
Commercial support: sales@bestpractical.com
Discover RT’s hidden secrets with RT Essentials from O’Reilly Media.
Buy a copy at http://rtbook.bestpractical.com
The rt-users Archives
Community help: http://wiki.bestpractical.com
Commercial support: sales@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@orbisuk.com