[rt-users] Slow Response Time when Email involved

[Kevin Squire]

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 at 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 at 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 at pavcs.org> sent  To:
> gentgeen at 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