Slow loading of long tickets in 3.6.3

RT Users
1

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

2

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:

3

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);

JustinOn 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

4

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…

JustinOn 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

5

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,
KenOn 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

6

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.

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

7

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,
KenOn 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:

%# 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

8

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,

JustinOn 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:

%# 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

http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-
users

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

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

9

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.

JustinOn 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:

%# 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

http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-
users

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

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

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

10

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>

 














Some entries have been removed to speed the loading of this long

ticket.
Please see the History for a full Journal of
this Ticket.


















<%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!

JustinOn 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:

%# 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

http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-
users

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

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

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

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

11

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,
KenOn 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>

 














Some entries have been removed to speed the loading of this long

ticket.
Please see the History for a full Journal
of this Ticket.


















<%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:

%# 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

http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-
users

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

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

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

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

12

Hope it comes in useful. It’s a bit rough and ready but could easily
be improved on.

JustinOn 29 Apr 2009, at 13:44, Kenneth Marshall wrote:

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>

 














Some entries have been removed to speed the loading of this long

ticket.
Please see the History for a full
Journal
of this Ticket.


















<%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:

%# 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

http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-
users

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

http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-
users

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

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

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

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

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