Perl Notes/processing time.pl

Mail processing time , for postfix logs.

Non streaming version.

cat /var/log/maillog to this and it makes a report sorted by start time.

#!/usr/bin/perl -w

use strict;
use Time::Local;
use Data::Dumper;

my $DEBUG = 1;

# This script will tell you how long each message took to process so that you can figure out what's taking so long.

# Mar 18 04:02:33 amazon postfix/smtpd[6001]: D675E1E4184: client=esa-annu.mail.domain.ca[131.104.91.36]
# Mar 18 04:02:33 amazon postfix/cleanup[29358]: D675E1E4184: message-id=<702030269448694818992@LENOVO-3C887B0D>
# Mar 18 04:02:33 amazon postfix/qmgr[17756]: D675E1E4184: from=<mail@prophecy.info>, size=22995, nrcpt=1 (queue active)
# Mar 18 04:02:36 amazon postfix/smtp[9802]: D675E1E4184: to=<jonesth@domain.ca>, orig_to=<thomas.jones@domain2.ca>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.7, delays=0.06/0/0.07/2.5, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=08738-03, from MTA([127.0.0.
]:10025): 250 2.0.0 Ok: queued as 6FEE71E418E)
# Mar 18 04:02:36 amazon postfix/qmgr[17756]: D675E1E4184: removed

my %month = (   'Jan' => '0', 'Feb' => '1', 'Mar' => '2', 'Apr' => '3', 'May' => '4', 'Jun' => '5', 'Jul' => '6', 'Aug' => '7', 'Sep' => '8', 'Oct' => '9', 'Nov' => '10', 'Dec' => '11' );

# Woo dirty!
my $year = "2012";

my %messages ;
my %noqueue;
my $total = 0;
my $failed = 0 ;
my $parsed = 0 ; # log lines
my $parsedmess = 0 ; # parsed messages

while (<>) {
        chop;
        $total++;

        if ( /(\w+)\s+(\d+)\s+(\d{2}):(\d{2}):(\d{2})\s+(\S+)\s(\S+)\s+(\S+):\s+(.*)$/ ) {
        #      Month   day     hh:    mm:     ss         host    process           messid mess
                $DEBUG && print $_."\n";
                my $mon = '';
                my $day = '';
                my $hour = '';
                my $min = '';
                my $sec = '';
                my $host = '';
                my $process = '';
                my $messid ='';
                my $mess = '';
                # A log line!
                $mon  = $1; $day     = $2;
                $hour = $3; $min     = $4; $sec    = $5;
                $host = $6; $process = $7; $messid = $8; $mess = $9;

                $parsed++;
                # $DEBUG && print "Mon $mon Day $day Hour $hour Min $min Sec $sec Host $host Process $process ID $messid Message $mess\n";
                my $epoch = timelocal($sec,$min,$hour,$day,$month{$mon},$year);
                # $DEBUG && print "Epoch $epoch Time ".localtime($epoch)."\n";

                if ( /NOQUEUE/ ) {
                        $noqueue{$messid} = $_;
                        next;
                }
                if ( $messages{$messid}->{'start'} && $mess =~ /removed/ ) {
                        $messages{$messid}->{'elapsed'} = $epoch - $messages{$messid}->{'start'};
                        $DEBUG && print "End of message $messid elapsed: $messages{$messid}->{'elapsed'}\n";
                        $parsedmess++;
                }
                if ( !  $messages{$messid}->{'start'}  ) {
                        $messages{$messid}->{'start'} = $epoch;
                        $DEBUG && print "Start of message $messid\n";
                } else {
                        print "message messid defined \n";
                        print Dumper($messages{$messid});
                }
                # $DEBUG && print "Adding message line to messag record\n";
                $messages{$messid}->{'body'}  .= $_."\n";

        } elsif ( /(\w+)\s+(\d+)\s+(\d{2}):(\d{2}):(\d{2})\s+(\S+):\sconnect\sfrom/ ) {
                # Mar 18 04:02:14 amazon postfix/smtpd[10247]: connect from localhost.localdomain[127.0.0.1]
                #$DEBUG && print "CONNECT: ".$_ ."\n";
        } else {
                $failed++;
                #$DEBUG && print "FAILED: ". $_."\n"
        }

}

print "##################################################\n";
print "Total $total\nparsed lines $parsed\nFailed $failed\n";
print "Parsed messages $parsedmess\n";
print "##################################################\n";

foreach my $value ( keys %messages) {
        if ( ! defined $messages{$value}->{'start'} ) { delete $messages{$value};}
        if ( $messages{$value} && ! defined ( $messages{$value}->{'elapsed'} ) ) { delete $messages{$value};}
}

print "Value Message\n";
foreach my $value (sort {$messages{$a}->{'start'} <=> $messages{$b}->{'start'} } keys %messages)
{
        if ( $messages{$value}->{'start'} && $messages{$value}->{'elapsed'} ) {
                print "$messages{$value}->{'start'} $messages{$value}->{'elapsed'}\n";
                # print $messages{$value};
        }
}

print Dumper(%noqueue);

streaming version:

tail -F /var/log/maillog and whatch whats up on you mail server in real-time.

#!/usr/bin/perl -w

use strict;
use Time::Local;
use Data::Dumper;

my $DEBUG = 1;

# This script will tell you how long each message took to process so that you can figure out what's taking so long.

# Mar 18 04:02:33 amazon postfix/smtpd[6001]: D675E1E4184: client=esa-annu.mail.domain.ca[131.104.91.36]
# Mar 18 04:02:33 amazon postfix/cleanup[29358]: D675E1E4184: message-id=<702030269448694818992@LENOVO-3C887B0D>
# Mar 18 04:02:33 amazon postfix/qmgr[17756]: D675E1E4184: from=<mail@prophecy.info>, size=22995, nrcpt=1 (queue active)
# Mar 18 04:02:36 amazon postfix/smtp[9802]: D675E1E4184: to=<jonesth@domain.ca>, orig_to=<thomas.jones@domain2.ca>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.7, delays=0.06/0/0.07/2.5, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=08738-03, from MTA([127.0.0.
]:10025): 250 2.0.0 Ok: queued as 6FEE71E418E)
# Mar 18 04:02:36 amazon postfix/qmgr[17756]: D675E1E4184: removed

my %month = (   'Jan' => '0', 'Feb' => '1', 'Mar' => '2', 'Apr' => '3', 'May' => '4', 'Jun' => '5', 'Jul' => '6', 'Aug' => '7', 'Sep' => '8', 'Oct' => '9', 'Nov' => '10', 'Dec' => '11' );

# Woo dirty!
my $year = "2012";

my %messages ;
my %noqueue;
my $total = 0;
my $failed = 0 ;
my $parsed = 0 ; # log lines
my $parsedmess = 0 ; # parsed messages

while (<>) {
        chop;
        $total++;

        if ( /(\w+)\s+(\d+)\s+(\d{2}):(\d{2}):(\d{2})\s+(\S+)\s(\S+)\s+(\S+):\s+(.*)$/ ) {
        #      Month   day     hh:    mm:     ss         host    process           messid mess
                # $DEBUG && print $_."\n";
                my $mon = '';
                my $day = '';
                my $hour = '';
                my $min = '';
                my $sec = '';
                my $host = '';
                my $process = '';
                my $messid ='';
                my $mess = '';
                # A log line!
                $mon  = $1; $day     = $2;
                $hour = $3; $min     = $4; $sec    = $5;
                $host = $6; $process = $7; $messid = $8; $mess = $9;

                $parsed++;
                # $DEBUG && print "Mon $mon Day $day Hour $hour Min $min Sec $sec Host $host Process $process ID $messid Message $mess\n";
                my $epoch = timelocal($sec,$min,$hour,$day,$month{$mon},$year);
                # $DEBUG && print "Epoch $epoch Time ".localtime($epoch)."\n";

                if ( /NOQUEUE/ ) {
                        $noqueue{$messid} = $_;
                        next;
                }
                if ( $messages{$messid}->{'start'} && $mess =~ /removed/ ) {
                        $messages{$messid}->{'elapsed'} = $epoch - $messages{$messid}->{'start'};
                        # $DEBUG && print "End of message $messid elapsed: $messages{$messid}->{'elapsed'}\n";
                        print $messages{$messid}->{'start'} . " " . $messages{$messid}->{'elapsed'} ." " . keys( %messages ). "\n";
                        delete $messages{$messid} ;
                        $parsedmess++;
                }
                if ( !  $messages{$messid}->{'start'}  ) {
                        $messages{$messid}->{'start'} = $epoch;
                        # $DEBUG && print "Start of message $messid\n";
                }
                # $DEBUG && print "Adding message line to messag record\n";
                # $messages{$messid}->{'body'}  .= $_."\n";

        } elsif ( /(\w+)\s+(\d+)\s+(\d{2}):(\d{2}):(\d{2})\s+(\S+):\sconnect\sfrom/ ) {
                # Mar 18 04:02:14 amazon postfix/smtpd[10247]: connect from localhost.localdomain[127.0.0.1]
                $DEBUG && print "CONNECT: ".$_ ."\n";
                print ".\n";
        } else {
                $failed++;
                #$DEBUG && print "FAILED: ". $_."\n"
                # print "F $_\n";
        }

}