hi all,
amavis logs timinginformation for every mail. may times I asked myself, what
took longest while prozessing one particulat mail. What does usualy take time
while processing many mails ?
So I started together with a trainee to program a small script.
It's not perfect, its only german and needs some polish. but it works:
$ cat /var/log/mail | amavis-timings
-----------------------------------------------------------------
| Das Script gibt an, wie oft welcher Subprozess im Scanvorgang |
| am meisten Zeit benötigt hat. Es werden die Häufigkeiten der |
| obersten drei Positionen je Logfile betrachtet und für die |
| Berechnung der Werte herangezogen. |
| |
| Detaillierte Informationen, so wie auch Beispiele und |
| Erklärungen befinden sich im Script. |
| |
| Zeitangaben in Millisekunden. |
-----------------------------------------------------------------
Zusammenfassung:
Rank 1 Minimalzeit | Durchschnitt | Maximalzeit
110 x SA check ( 320 | 2342 | 11781)
94 x AV-scan-3 ( 541 | 1510 | 1137)
4 x AV-scan-1 ( 4 | 40 | 935)
1 x mime_decode ( 15 | 30 | 71)
1 x get-file-type2 ( 23 | 22 | 208)
Rank 2 Minimalzeit | Durchschnitt | Maximalzeit
110 x AV-scan-3 ( 541 | 1510 | 1137)
81 x SA check ( 320 | 2342 | 11781)
10 x mime_decode ( 15 | 30 | 71)
7 x get-file-type2 ( 23 | 22 | 208)
2 x get-file-type4 ( 41 | 2 | 41)
Rank 3 Minimalzeit | Durchschnitt | Maximalzeit
98 x decompose_part ( 3 | 50 | 124)
57 x get-file-type5 ( 43 | 11 | 43)
22 x get-file-type2 ( 23 | 22 | 208)
12 x get-file-type1 ( 16 | 36 | 322)
12 x get-file-type4 ( 41 | 2 | 41)
4 x mime_decode ( 15 | 30 | 71)
2 x get-file-type3 ( 35 | 0 | 40)
2 x AV-scan-1 ( 4 | 40 | 935)
1 x open-mbx ( 1 | 6 | 70)
Zeilen: 210
----
Maybe you find the script usefull.
The algorithm should also be fine to report about TIMING-SA lines.
Would be nice, if enhancements will be published.
--
Andreas Schulze
Internetdienste | P532
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 %rank1 = ();
my %rank2 = ();
my %rank3 = ();
my $linecount;
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($$);
my @keys;
$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/^.* - //;
# Aufsplitten der Zeilen, Kommagetrennt
@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 "---------------------------------------------------------P532----\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 "% 3s 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 "% 3s 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 "% 3s 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;
}
}
}
------------------------------------------------------------------------------
This SF.net Dev2Dev email is sponsored by:
Show off your parallel programming skills.
Enter the Intel(R) Threading Challenge 2010.
http://p.sf.net/sfu/intel-thread-sfd
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
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
