Slow Response Time when Email involved

We have been using RT for a long time now (3 or 4 years?) and have had
great success. Starting sometime in Aug, we found that there was a
LARGE delay when ever updating a ticket in ANY way that would include
sending emails. Since it was also that start of the school year, we
just assumed ‘beginning of year’ load issues. Well the problem is
still there.

Anytime an email has to go out, there is exactly a 12 second delay in
the logs. This then causes the page load to be greater then 12
seconds. It does not seem to matter what time of day, or if the email
includes attachments, etc.

So I went through the code, pretty much line by line, adding comments
to try and narrow down WHERE the delay is, but now I am stuck.

I have edited both
$RT_INSTALL/lib/RT/Action/SendEmail.pm and
$RT_INSTALL/lib/RT/Interface/Email.pm

SendEmail.pm now has “Ticker #” and Email.pm has “Ticker 1#”

Here are my logs:
Nov 4 16:09:16 outrigger RT:
rt-3.8.8-14121-1320437356-1460.35109-6-0@pavcs.org KDS Ticker 0 .
(/usr/share/request-tracker3.8/lib/RT/Action/SendEmail.pm:306) Nov 4
16:09:16 outrigger RT: KDS Ticker 10
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:396) Nov 4
16:09:16 outrigger RT: KDS Ticker 11
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:402) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:445) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0-1
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:449) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0-2
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:451) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0-3
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:455) Nov 4
16:09:28 outrigger RT: KDS Ticker 11-0-4
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:464) Nov 4
16:09:28 outrigger RT: KDS Ticker 11-1
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:466) Nov 4
16:09:28 outrigger RT:
rt-3.8.8-14121-1320437356-1460.35109-6-0@pavcs.org sent To:
gentgeen@wikiak.org
(/usr/share/request-tracker3.8/lib/RT/Action/SendEmail.pm:331)

The 12 Second delay is between 11-0-3 and 11-0-4

Here is my modified code (Email.pm):

$RT::Logger->info( " KDS Ticker 11-0 " );
eval {
# don’t ignore CHLD signal to get proper exit code
local $SIG{‘CHLD’} = ‘DEFAULT’;
$RT::Logger->info( " KDS Ticker 11-0-1 " );
open my $mail, “|$path $args” or die “couldn’t execute
program: $!”; $RT::Logger->info( " KDS Ticker 11-0-2 " );
# if something wrong with $mail->print we will get PIPE
signal, handle it local $SIG{‘PIPE’} = sub { die “program unexpectedly
closed pipe” }; $args{‘Entity’}->print($mail);
$RT::Logger->info( " KDS Ticker 11-0-3 " );
unless ( close $mail ) {
die “close pipe failed: $!” if $!; # system error
# sendmail exit statuses mostly errors with data not
software # TODO: status parsing: core dump, exit on signal or EX_*
my $msg = "$msgid: $path $args exitted with code ".
($?>>8); $msg = ", interrupted by signal ". ($?&127) if $?&127;
$RT::Logger->error( $msg );
}
$RT::Logger->info( " KDS Ticker 11-0-4 " );
};
$RT::Logger->info( " KDS Ticker 11-1 " );

Can anyone PLEASE help me narrow this down … I am just at a lost
now. I just don’t know enough Perl to understand what is going on or
why the large delay right at:

unless ( close $mail ) {
die “close pipe failed: $!” if $!; # system error
# sendmail exit statuses mostly errors with data not software
# TODO: status parsing: core dump, exit on signal or EX_*
my $msg = "$msgid: $path $args exitted with code ". ($?>>8);
$msg = ", interrupted by signal ". ($?&127) if $?&127;
$RT::Logger->error( $msg );
}

http://www.wikiak.org

Associate yourself with men of good quality if you esteem
your own reputation; for 'tis better to be alone then in bad
company. - George Washington, Rules of Civility

Sorry to reply to my own… but since it was after work hours, I
commented out the section that I thought was slowing things down:

unless ( close $mail ) {

die “close pipe failed: $!” if $!; # system error

 # sendmail exit statuses mostly errors with data not software
 # TODO: status parsing: core dump, exit on signal or EX_*

my $msg = "$msgid: $path $args exitted with code ". ($?>>8);

$msg = ", interrupted by signal ". ($?&127) if $?&127;

$RT::Logger->error( $msg );

}

Well all that did was move the perceived slowdown. Now it seems to be
between 11-0-4 and 11-1 (but only thing there is a } ) … So I am
even more confused now what the problem might be.On Fri, 4 Nov 2011 16:36:46 -0400 Kevin Squire gentgeen@wikiak.org wrote:

We have been using RT for a long time now (3 or 4 years?) and have had
great success. Starting sometime in Aug, we found that there was a
LARGE delay when ever updating a ticket in ANY way that would include
sending emails. Since it was also that start of the school year, we
just assumed ‘beginning of year’ load issues. Well the problem is
still there.

Anytime an email has to go out, there is exactly a 12 second delay in
the logs. This then causes the page load to be greater then 12
seconds. It does not seem to matter what time of day, or if the email
includes attachments, etc.

So I went through the code, pretty much line by line, adding comments
to try and narrow down WHERE the delay is, but now I am stuck.

I have edited both
$RT_INSTALL/lib/RT/Action/SendEmail.pm and
$RT_INSTALL/lib/RT/Interface/Email.pm

SendEmail.pm now has “Ticker #” and Email.pm has “Ticker 1#”

Here are my logs:
Nov 4 16:09:16 outrigger RT:
rt-3.8.8-14121-1320437356-1460.35109-6-0@pavcs.org KDS Ticker 0 .
(/usr/share/request-tracker3.8/lib/RT/Action/SendEmail.pm:306) Nov 4
16:09:16 outrigger RT: KDS Ticker 10
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:396) Nov 4
16:09:16 outrigger RT: KDS Ticker 11
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:402) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:445) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0-1
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:449) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0-2
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:451) Nov 4
16:09:16 outrigger RT: KDS Ticker 11-0-3
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:455) Nov 4
16:09:28 outrigger RT: KDS Ticker 11-0-4
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:464) Nov 4
16:09:28 outrigger RT: KDS Ticker 11-1
(/usr/share/request-tracker3.8/lib/RT/Interface/Email.pm:466) Nov 4
16:09:28 outrigger RT:
rt-3.8.8-14121-1320437356-1460.35109-6-0@pavcs.org sent To:
gentgeen@wikiak.org
(/usr/share/request-tracker3.8/lib/RT/Action/SendEmail.pm:331)

The 12 Second delay is between 11-0-3 and 11-0-4

Here is my modified code (Email.pm):

$RT::Logger->info( " KDS Ticker 11-0 " );
eval {
# don’t ignore CHLD signal to get proper exit code
local $SIG{‘CHLD’} = ‘DEFAULT’;
$RT::Logger->info( " KDS Ticker 11-0-1 " );
open my $mail, “|$path $args” or die “couldn’t execute
program: $!”; $RT::Logger->info( " KDS Ticker 11-0-2 " );
# if something wrong with $mail->print we will get PIPE
signal, handle it local $SIG{‘PIPE’} = sub { die “program unexpectedly
closed pipe” }; $args{‘Entity’}->print($mail);
$RT::Logger->info( " KDS Ticker 11-0-3 " );
unless ( close $mail ) {
die “close pipe failed: $!” if $!; # system error
# sendmail exit statuses mostly errors with data not
software # TODO: status parsing: core dump, exit on signal or EX_*
my $msg = "$msgid: $path $args exitted with code ".
($?>>8); $msg = ", interrupted by signal ". ($?&127) if $?&127;
$RT::Logger->error( $msg );
}
$RT::Logger->info( " KDS Ticker 11-0-4 " );
};
$RT::Logger->info( " KDS Ticker 11-1 " );

Can anyone PLEASE help me narrow this down … I am just at a lost
now. I just don’t know enough Perl to understand what is going on or
why the large delay right at:

unless ( close $mail ) {
die “close pipe failed: $!” if $!; # system error
# sendmail exit statuses mostly errors with data not software
# TODO: status parsing: core dump, exit on signal or EX_*
my $msg = "$msgid: $path $args exitted with code ". ($?>>8);
$msg = ", interrupted by signal ". ($?&127) if $?&127;
$RT::Logger->error( $msg );
}

Associate yourself with men of good quality if you esteem
your own reputation; for 'tis better to be alone then in bad
company. - George Washington, Rules of Civility

Sorry to reply to my own… but since it was after work hours, I
commented out the section that I thought was slowing things down:

This isn’t RT being slow, this is the command you pipe mail to being
slow. It may be doing DNS lookups incredibly slowly or if you’re
using sendmail it may be trying to relay the mail before finishing.

We document a solution for this for sendmail in the configuration that
ships with RT. For non-sendmail mailers, it’s usually DNS.

-kevin