Perl Notes/processing time.pl: Difference between revisions

From Federal Burro of Information
Jump to navigationJump to search
(Created page with "<pre> #!/usr/bin/perl -w use strict; use Time::Local; my $DEBUG = 0; # This script will tell you how long each message took to process so that you can figure out what's taking ...")
 
No edit summary
 
(5 intermediate revisions by the same user not shown)
Line 1: Line 1:
Mail processing time , for postfix logs.
Non streaming version.
cat /var/log/maillog to this and it makes a report sorted by start time.
<pre>
<pre>
#!/usr/bin/perl -w
#!/usr/bin/perl -w
Line 4: Line 10:
use strict;
use strict;
use Time::Local;
use Time::Local;
use Data::Dumper;
my $DEBUG = 1;


my $DEBUG = 0;
# This script will tell you how long each message took to process so that you can figure out what's taking so long.
# 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.uoguelph.ca[131.104.91.36]
# 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/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: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@uoguelph.ca>, orig_to=<thomas.jones@guelphhumber.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.1]:10025): 250 2.0.0 Ok: queued as 6FEE71E418E)
# 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
# Mar 18 04:02:36 amazon postfix/qmgr[17756]: D675E1E4184: removed


Line 17: Line 26:


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


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


while (<>) {
while (<>) {
Line 28: Line 39:
         $total++;
         $total++;


         if ( /(\w+)\s{1}(\d{2})\s{1}(\d{2}):(\d{2}):(\d{2})\s{1}(\w+)\s{1}postfix\/(\w+)\[\d+\]:\s{1}(\w+):(.+)/ ){
         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
         #     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!
                 # A log line!
                 my $mon  = $1; my $day    = $2;
                 $mon  = $1; $day    = $2;
                 my $hour = $3; my $min    = $4; my $sec    = $5;
                 $hour = $3; $min    = $4; $sec    = $5;
                 my $host = $6; my $process = $7; my $messid = $8; my $mess = $9;
                 $host = $6; $process = $7; $messid = $8; $mess = $9;


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


                 if ( $messages{$messid} && ( $mess =~ /removed/ ) ) {
                if ( /NOQUEUE/ ) {
                         $messages{$messid} = $epoch - $messages{$messid};
                        $noqueue{$messid} = $_;
                 } elsif ( ! $messages{$messid} ) {
                        next;
                         $messages{$messid} = $epoch;
                }
                 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 {
                 } else {
                         $DEBUG && print "Mid message message\n";
                         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{1}(\d{2})\s{1}(\d{2}):(\d{2}):(\d{2})\s{1}(\w+)\s{1}postfix\/(\w+)\[\d+\]:\s{1}(.+)/ ){
         } 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]
                 # Mar 18 04:02:14 amazon postfix/smtpd[10247]: connect from localhost.localdomain[127.0.0.1]
                 $DEBUG && print "CONNECT: ".$_ ."\n";
                 #$DEBUG && print "CONNECT: ".$_ ."\n";
         } else {
         } else {
                 $failed++;
                 $failed++;
                 $DEBUG && print "FAILED: ". $_."\n"
                 #$DEBUG && print "FAILED: ". $_."\n"
         }
         }


}
}


print "Total $total\nparsed $parsed\nFailed $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";
print "Value Message\n";
foreach my $value (sort {$messages{$a} <=> $messages{$b} } keys %messages)
foreach my $value (sort {$messages{$a}->{'start'} <=> $messages{$b}->{'start'} } keys %messages)
{
{
    print "$value $messages{$value}\n";
        if ( $messages{$value}->{'start'} && $messages{$value}->{'elapsed'} ) {
                print "$messages{$value}->{'start'} $messages{$value}->{'elapsed'}\n";
                # print $messages{$value};
        }
}
}
print Dumper(%noqueue);
</pre>
</pre>
streaming version:
tail -F /var/log/maillog and whatch whats up on you mail server in real-time.
<pre>
#!/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";
        }
}
</pre>
[[Category:Script]]

Latest revision as of 05:50, 6 April 2021

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";
        }

}
Retrieved from "https://wiki.quadratic.net/index.php?title=Perl_Notes/processing_time.pl&oldid=5411"