AMaViS - A Mail Virus Scanner

* Patrick Ben Koetter <p@...>:
> I've run into a problem where amavis seems to take ages to scan messages - at
> least the time it logs make me think so.
> 
> OTOH the system I run is mindblowing fast and I just can't believe it would
> take amavis long run accept, scan and resend a message.
> 
> BUT I copy every message using $archive_quarantine_method and sometimes the
> SMTP-based archive may be slow.
> 
> Would amavis take a slow SMTP archiver into account when it notes %y time in
> log messages?

Feb 28 01:02:24 mail amavis[5059]: (05059-15) Passed CLEAN {RelayedInbound}, [195.63.184.213]:19676 [195.63.184.213]
<yyy@...> -> <xxx@...>, Message-ID: <-1722408731.1298851331338.JavaMail.javamailuser@...>,
mail_id: 5nJbfRaajrPq, Hits: -1.97, size: 58463, queued_as: 6F0961C361B, 1147 ms

We're talking about this last "1147 ms" value (just to make that clear).

-- 
Ralf Hildebrandt
  Geschäftsbereich IT | Abteilung Netzwerk
  Charité - Universitätsmedizin Berlin
  Campus Benjamin Franklin
  Hindenburgdamm 30 | D-12203 Berlin
  Tel. +49 30 450 570 155 | Fax: +49 30 450 570 962
  ralf.hildebrandt@... | http://www.charite.de

Am 28.02.2011 08:23 schrieb Ralf Hildebrandt:
> * Patrick Ben Koetter <p@...>:
> > OTOH the system I run is mindblowing fast and I just can't believe it would
> > take amavis long run accept, scan and resend a message.

> Feb 28 01:02:24 mail amavis[5059]: (05059-15) Passed CLEAN {RelayedInbound}, [195.63.184.213]:19676 [195.63.184.213]
> <yyy@...> -> <xxx@...>, Message-ID: <-1722408731.1298851331338.JavaMail.javamailuser@...>,
> mail_id: 5nJbfRaajrPq, Hits: -1.97, size: 58463, queued_as: 6F0961C361B, 1147 ms
> 
> We're talking about this last "1147 ms" value (just to make that clear).

I use $log_level = 2;
(~line 11230 of amavisd: do_log(2, "%s", Amavis::Timing::report());  # report elapsed times)

This produces detailed TIMING Logs like this:
Feb 28 06:24:45 taro amavis[29610]: (29610) TIMING [total 896 ms] - got data: 0 (0%)0, check_init: 6 (1%)1, digest_hdr: 6 (1%)1, digest_body_dkim: 1 (0%)1, mkdir parts: 4 (0%)2, mime_decode: 15 (
2%)3, get-file-type1: 15 (2%)5, parts_decode: 0 (0%)5, check_header: 2 (0%)5, AV-scan-1: 3 (0%)6, AV-scan-2: 6 (1%)6, AV-scan-3: 17 (2%)8, AV-scan-4: 53 (6%)14, spam-wb-list: 1 (0%)14, SA parse: 
19 (2%)17, SA check: 702 (78%)95, decide_mail_destiny: 17 (2%)97, notif-quar: 1 (0%)97, prepare-dsn: 6 (1%)97, main_log_entry: 15 (2%)99, update_snmp: 3 (0%)99, rundown: 5 (1%)100

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 http://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

Patrick,

> I've run into a problem where amavis seems to take ages to scan messages -
> at least the time it logs make me think so.
> OTOH the system I run is mindblowing fast and I just can't believe it would
> take amavis long run accept, scan and resend a message.
> BUT I copy every message using $archive_quarantine_method and sometimes the
> SMTP-based archive may be slow.
> Would amavis take a slow SMTP archiver into account when it notes %y time in
> log messages?

Yes, the the SMTP archiver would be taken into account in the
reported %y time.

The start timestamp event is taken right after amavisd writes its SMTP
greeting to a tcp socket after session establishment. The end time for
the %y purpose is at the time when the log entry is generated, which
includes all but some final cleanup, which should be insignificant.

As Andreas noted, the TIMING report (at log level 2) is the ultimate
reference.

  Mark