Am 02.03.2011 09:25 schrieb Patrick Ben Koetter:
> I'm trying to locate a bottleneck in a mailsystem. The TIMING in amavis
> logging shows ...
some weeks ago I posted a little helpersript. For me it's usefull to know
which steps take most of the time.
$ grep TIMINGS /var/log/mail | amavisd-timings
Maybe it helps ...
Andreas
--
Andreas Schulze
Internetdienste | P252
DATEV eG
90329 Nürnberg | Telefon +49 911 319-0 | Telefax +49 911 319-3196
E-Mail info @datev.de | Internet www.datev.de
Sitz: 90429 Nürnberg, Paumgartnerstr. 6-14 | Registergericht Nürnberg, GenReg
Nr.70
Vorstand
Prof. Dieter Kempf (Vorsitzender)
Dipl.-Kfm. Wolfgang Stegmann (stellvertretender Vorsitzender)
Dipl.-Kfm. Michael Leistenschneider
Jörg Rabe v. Pappenheim
Dipl.-Vw. Eckhard Schwarzer
Vorsitzender des Aufsichtsrates: Reinhard Verholen
#!/usr/bin/perl
# Author: Mathias Weiss / Andreas Schulze / DATEV eG
# Patches and problem reports are welcome.
# Script Analyse von Logdateien im Mailscanvorgang.
#Im Log ist je Zeile ein Scanvorgang beschrieben. Es werden die einzelnen
Subprozesse aufgelistet, wie lange welcher Prozess gedauert hat und welchen
Anteil dieser am Gesamtvorgang hatte.
#Zeitangaben in Millisekunden.
#Beispielzeile:
# Dec 14 09:59:36 securemail11 amavis[3032]: (03032-01) TIMING [total 1978 ms]
- SMTP greeting: 8 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 1 (0%)1, mkdir
tempdir: 1 (0%)1, create email.txt: 1 (0%)1, SMTP pre-DATA-flush: 94 (5%)5,
SMTP DATA: 148 (7%)13, check_init: 1 (0%)13, digest_hdr: 1 (0%)13, digest_body:
0 (0%)13, gen_mail_id: 2 (0%)13, mkdir parts: 1 (0%)13, mime_decode: 17 (1%)14,
get-file-type1: 13 (1%)15, decompose_part: 10 (1%)15, parts_decode: 0 (0%)15,
check_header: 2 (0%)15, AV-scan-1: 6 (0%)16, AV-scan-2: 1593 (81%)96,
update_cache: 1 (0%)96, decide_mail_destiny: 1 (0%)96, fwd-connect: 20 (1%)97,
fwd-mail-pip: 14 (1%)98, fwd-rcpt-pip: 0 (0%)98, fwd-data-chkpnt: 0 (0%)98,
write-header: 1 (0%)98, fwd-data-contents: 0 (0%)98, fwd-end-chkpnt: 18 (1%)99,
prepare-dsn: 1 (0%)99, main_log_entry: 16 (1%)100, SMTP pre-response: 0
(0%)100, SMTP response: 2 (0%)100, unlink-2-files: 1 (0%)100, rundown: 1 (0%)100
# Das Log wird zeilenweise eingelesen, Datums und Informationsfragmente
abgeschnitten und anschließend in einzelne Prozesse und die dazugehörigen
Zeiten aufgespaltet.
# Es werden zeitlich gesehen die drei am längsten andauernden Prozesse
beobachtet. Drei Plätze oder auch Positionen werden gebildet (Rank1, Rank2 und
Rank3) und es wird sortiert, welcher Prozess wie oft auf welchem Platz war.
use strict;
use warnings;
my $linecount;
my %rank1 = ();
my %rank2 = ();
my %rank3 = ();
my %min = ();
my %max = ();
my %avg = ();
my %abs = (); #Angabe der absoluten Zeit in Millisekunden
my %abs_min = ();
my %abs_max = ();
my %rel = (); #Angabe der relativen Zeit gemessen an der Gesamtzeit
my $REGEX_SUBACTION = qr {
^(.*): # kommentar
\s
([\d\.]+)
\s
\(
([\d\.]+)
\%\)
.*$
}xms;
# Funktionsdeklaration
sub set_min($$);
sub set_max($$);
$linecount = 0;
my $prev_incomplete_line = '';
while (<>){
# nächsten Zeile, ausser sie enthält TIMING
next unless (/ TIMING /);
next unless (/- got data/);
# ev. vorhanden, unvollständige Vorgängerzeile
if ($prev_incomplete_line) {
$_ = $_ . $prev_incomplete_line;
$prev_incomplete_line = '';
}
# Test, ob die Zeile nun Fertig ist
if (/.*\.\.\./) {
s/(.*)\.\.\.$/$1/;
$prev_incomplete_line = $_;
next;
}
# Abschneiden der Datums- und Informationsfragmente zu Beginn jeder Zeile
s/^.* - //;
# Zeilenumbruch am Ende auch weg
chomp;
# Aufsplitten der Zeilen, Kommagetrennt
my @keys = ();
@keys = split(', ');
foreach my $key (@keys) {
my ($action, $duration_abs, $duration_rel) = $key =~ $REGEX_SUBACTION;
$abs{$action} = $duration_abs;
$rel{$action} = $duration_rel;
$avg{$action} += $duration_abs;
set_min($action, $duration_abs);
set_max($action, $duration_abs);
}
# Zeilenzähler
$linecount++;
my $i = 0;
my @tmp = sort{ $abs{$b} <=> $abs{$a} } keys %abs;
# sortierten Hash einer Zeile
# mit einem 1. einem 2. und einem 3. Platz...
for ($i=0;$i<3;$i++) {
my $key = $tmp[$i];
#$avg{$key}=$avg{$key}+$abs{$key}; #Addieren aller abs-Werte pro
Prozessname zur Berechnung des Durchschnitts am Ende.
if ($i==0) {
$rank1{"$key"}++;
}
if ($i==1) {
$rank2{"$key"}++;
}
if ($i==2) {
$rank3{"$key"}++;
}
}
}
#Sortieren nach Häufigkeiten
print "-----------------------------------------------------------------\n";
print "| Das Script gibt an, wie oft welcher Subprozess im Scanvorgang |\n";
print "| am meisten Zeit benötigt hat. Es werden die Häufigkeiten der |\n";
print "| obersten drei Positionen je Logfile betrachtet und für die |\n";
print "| Berechnung der Werte herangezogen. |\n";
print "| |\n";
print "| Detaillierte Informationen, so wie auch Beispiele und |\n";
print "| Erklärungen befinden sich im Script. |\n";
print "| |\n";
print "| Zeitangaben in Millisekunden. |\n";
print "-----------------------------------------------------------------\n\n";
print "Zusammenfassung:\n";
print "\nRank 1 Minimalzeit | Durchschnitt |
Maximalzeit\n";
foreach ( sort{ $rank1{$b} <=> $rank1{$a} } keys %rank1) { #Sortierung:
Haeufigstes an erster Stelle
printf "% 5s x % 20s % 10d | % 11d | % 10d\n", $rank1{$_},
$_,$abs_min{$_}, $avg{$_} / $linecount, $abs_max{$_};
}
print "\nRank 2 Minimalzeit | Durchschnitt |
Maximalzeit\n";
foreach ( sort{ $rank2{$b} <=> $rank2{$a} } keys %rank2) {
printf "% 5s x % 20s % 10d | % 11d | % 10d\n", $rank2{$_},
$_,$abs_min{$_}, $avg{$_} / $linecount, $abs_max{$_};
}
print "\nRank 3 Minimalzeit | Durchschnitt |
Maximalzeit\n";
foreach ( sort{ $rank3{$b} <=> $rank3{$a} } keys %rank3) {
printf "% 5s x % 20s % 10d | % 11d | % 10d\n", $rank3{$_},
$_,$abs_min{$_}, $avg{$_} / $linecount, $abs_max{$_};
}
print "\n\nZeilen: $linecount\n"; #Zeilenzaehler ausgeben
exit 0;
# Suchen des kleinsten abs-Wertes
sub set_min($$) {
my ($text, $abs) = @_;
if (not defined $abs_min{$text}) {
$abs_min{$text} = $abs;
} else {
if ($abs_min{$text} > $abs) {
$abs_min{$text} = $abs;
}
}
}
# Suchen des größten abs-Wertes.
sub set_max($$) {
my ($text, $abs) = @_;
if (not defined $abs_max{$text}) {
$abs_max{$text} = $abs;
} else {
if ($abs_max{$text} < $abs) {
$abs_max{$text} = $abs;
}
}
}
------------------------------------------------------------------------------
Free Software Download: Index, Search & Analyze Logs and other IT data in
Real-Time with Splunk. Collect, index and harness all the fast moving IT data
generated by your applications, servers and devices whether physical, virtual
or in the cloud. Deliver compliance at lower cost and gain new business
insights. http://p.sf.net/sfu/splunk-dev2dev
_______________________________________________
AMaViS-user mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/amavis-user
Please visit http://www.ijs.si/software/amavisd/ regularly
For administrativa requests please send email to rainer at openantivirus dot
org
