[AMaViS-user] Re: Postfix/Amavis slow after O.S. upgrade

Hi, Michael!

> Did you enable the SMP stuff?

The problem is on an Intel Xeon with 2 (real) processors, so... the
answer is yes. :)

> Did you reformat? Use new ufs2 file system, or just do a source upgrade?

No reformat, just upgrade.

> You have enough ram to use a ram disk for the /var/amavis/tmp partition?

For our traffic volume, we sure don't... and I don't think
it would solve the problem. :-(

Hello, Mark!

>>> Usually, the 4 sections that "eat" most of the time are SMTP DATA,
>>> fwd-data, fwd-connect and fwd-data-end.
>>>
>>> I accumulated the statistics of 256 msgs to give a better picture of
>>> what we are seeing, these are the results:
>>>
>>> 772.31s (28.01%) SMTP DATA | 3.71s ( 0.13%) SMTP LHLO

> In your first example the SMTP DATA section took only 5% (0.8s),
> which is reasonable. The 772.31 s is clearly outrageous - are you using
> amavisd-new in a pre-queue proxy setup?

Excuse me if I was not clear in my previous post... the time you
commented upon (772.31s) was not of a single message, but the
*accumulated* time of 256 msgs. It means that, in 256 msgs, the SMTP
DATA section took about 3s for each msg.

In average, each message is taking about 11s to be processed... and
previously (before the OS upgrade) it was much faster (less than a third
of that time)!

>>> 482.99s (17.52%) fwd-connect
>>> 438.94s (15.92%) fwd-data
>>> 300.61s (10.90%) fwd-data-end
>>> 177.31s ( 6.43%) fwd-rcpt-to

> Check and double check *_restrictions
> on smtpd service (master.cf). Most of them should be disabled
> on smtpd at port 10025. Likewise header and body checks are better
> not be active twice, unless being trivial. See that you don't have a limit
> on the number of smtpd processes at port 10025 (maxproc column
> in master.cf).

Already checked and rechecked main.cf and master.cf several times... :-(

> Are your smtpd processes running chrooted

No.

> Try 'telnet 127.0.0.1 10025' and see if you are getting instant response;

When there's not much incoming msgs, yes, I get instant response.
Otherwise, it seems that all amavis children are busy talking to
Postfix... :-/

Just to get a few extra things out of the way... the machine is almost
always idle, with very low load (0.09/0.13/0.21), almost no swapping...
and still, the messages are getting through very slowly. During peak
times... it's a nightmare. :-(

Here's something that I should have posted before... the amavis debug at
level 5 (again, cleaned up a bit, for clarity sake):

Obs: I changed the lines from something like:
Feb 14 18:11:47 xxxxxxxx.xxx.xx.xx amavisd[44373]: (44373-04) lookup_acl: key="xxxxxxxxx@xxxxxxxxxxxxx.xxx.xx", no match
.... to something like:
11:47 lookup_acl: key="*from*", no match

------------------------------------------------------------------------
11:47 lookup_acl: key="*from*", no match
11:47 LMTP> 250 2.1.0 Sender *from* OK
11:47 prolong_timer after reading SMTP command: remaining time = 300 s
11:47 LMTP< RCPT TO:<*to*>\r\n
11:47 LMTP> 250 2.1.5 Recipient *to* OK
11:47 prolong_timer after reading SMTP command: remaining time = 300 s
11:47 LMTP< DATA\r\n
11:47 prolong_timer after DATA received - timer reset: remaining time = 300 s
11:47 LMTP::10024 /var/amavis/amavis-20060214T181028-44373: <*from*> -> <*to*> Received: SIZE=2536485 from *local* ([127.0.0.1]) by localhost (*local* [127.0.0.1]) (amavisd-new, port 10024) with LMTP id 44373-04 for <*to*>; Tue, 14 Feb 2006 18:11:47 -0200 (BRDT)
11:47 LMTP> 354 End data with <CR><LF>.<CR><LF>
11:59 LMTP< .\r\n
11:59 body hash: 618642bdfd7671449682a41598b89120
11:59 Original mail size: 2503909; quota set to: 314572800 bytes
11:59 Checking: <*from*> -> <*to*>
11:59 lookup_acl: key="*to*" matches ".", result=1
11:59 lookup_sql "*to*", query keys: "*to*","xxx", "@xxxxxxxxxxxxx.xxx.xx", "@."
11:59 lookup_sql, "*to*" no match
11:59 lookup_sql_field(bypass_header_checks), "*to*" no match
11:59 lookup_acl: key="*to*", no match
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(bypass_banned_checks), "*to*" no match
11:59 lookup_acl: key="*to*", no match
11:59 Extracting mime components
11:59 Issued a new file name: part-00001
11:59 Issued a new file name: part-00002
11:59 Issued a new file name: part-00003
11:59 mime_decode_preamble: 2 lines
11:59 mime_decode: Content-type: multipart/mixed
11:59 mime_decode_epilogue: 1 lines
11:59 mime_decode_preamble: 1 lines
11:59 mime_decode: Content-type: multipart/alternative
11:59 mime_decode_epilogue: 1 lines
11:59 mime_decode: Content-type: application/octet-stream, name: N_Toda em cima_mpg.pdf
11:59 Charging 1851396 bytes to remaining quota 314572800 (out of 314572800, (1%)) -by mime_decode
11:59 mime_decode: Content-type: text/plain, name:
11:59 Charging 406 bytes to remaining quota 312721404 (out of 314572800, (1%)) - by mime_decode
11:59 mime_decode: Content-type: text/html, name:
11:59 Charging 1022 bytes to remaining quota 312720998 (out of 314572800, (1%)) - bymime_decode
11:59 prolong_timer after mime_decode-1: remaining time = 288 s
11:59 Checking for banned MIME types and names
11:59 check_for_banned - mime-type: multipart/mixed
11:59 lookup_RE: key="multipart/mixed", no match
11:59 check_for_banned - mime-type: multipart/alternative
11:59 lookup_RE: key="multipart/alternative", no match
11:59 check_for_banned - mime-type: application/octet-stream
11:59 check_for_banned - declared names: N_Toda em cima_mpg.pdf
11:59 lookup_RE: key="application/octet-stream", no match
11:59 lookup_RE: key="N_Toda em cima_mpg.pdf", no match
11:59 check_for_banned - mime-type: text/plain
11:59 lookup_RE: key="text/plain", no match
11:59 check_for_banned - mime-type: text/html
11:59 lookup_RE: key="text/html", no match
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(bypass_virus_checks), "*to*" no match
11:59 lookup_acl: key="*to*", no match
11:59 Using Clam Antivirus-clamd: (built-in interface)
11:59 Clam Antivirus-clamd: Connecting to socket /var/run/clamav/clamd
11:59 Clam Antivirus-clamd: Sending CONTSCAN /var/amavis/amavis-20060214T181028-44373/parts\n to UNIX socket /var/run/clamav/clamd
11:59 Clam Antivirus-clamd result: /var/amavis/amavis-20060214T181028-44373/parts: OK\n
11:59 prolong_timer after virus_scan: remaining time = 288 s
11:59 white_black_list: checking sender <*from*>
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(id), "*to*" no match
11:59 lookup_acl: key="*from*", no match
11:59 lookup_RE: key="*from*", no match
11:59 lookup_hash: key="*from*", no match
11:59 lookup_hash: key="yyyyyyyyy@", no match
11:59 lookup_hash: key="xxxxxxxxxxxxx.xxx.xx", no match
11:59 lookup_hash: key=".xxxxxxxxxxxxx.xxx.xx", no match
11:59 lookup_hash: key=".xxx.xx", no match
11:59 lookup_hash: key=".xx", no match
11:59 lookup_hash: key=".", no match
11:59 lookup_acl: key="*from*", no match
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(bypass_spam_checks), "*to*" no match
11:59 lookup_acl: key="*to*", no match
11:59 spam_scan: not wasting time on SA, message longer than 65536 bytes: 642+2503266
11:59 spam_scan: hits=
11:59 prolong_timer after spam_scan: remaining time = 288 s
11:59 header: Received: from *local* ([127.0.0.1])\n by localhost (*local* [127.0.0.1]) (amavisd-new, port 10024)\n with LMTP id 44373-04 for <*to*>;\n Tue, 14 Feb 2006 18:11:47 -0200 (BRDT)\n
11:59 header: X-Virus-Scanned: by amavisd-new at mpc.com.br\n
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(local), "*to*" no match
11:59 lookup_acl: key="*to*" matches ".", result=1
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(spam_tag_level), "*to*" no match
11:59 lookup: (scalar) matches, result="4"
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(spam_tag2_level), "*to*" no match
11:59 lookup_sql (cached): "*to*" no match
11:59 lookup_sql_field(spam_kill_level), "*to*" no match
11:59 lookup: (scalar) matches, result="8"
11:59 headers CLUSTERING: NEW CLUSTER <*to*>: hits=-, tag=0, tag2=0, subj=0, local=1, bl=0
11:59 headers CLUSTERING: done all 1 recips in one go
11:59 FWD via SMTP: [127.0.0.1:10025] <*from*> -> <*to*>
11:59 Remote host introduces itself as: *local*
11:59 prolong_timer after fwd-connect: remaining time = 288 s
12:00 prolong_timer after fwd-mail-from: remaining time = 288 s
12:00 prolong_timer after fwd-rcpt-to: remaining time = 288 s
12:00 response to DATA: "354 End data with <CR><LF>.<CR><LF>"
12:13 prolong_timer after fwd-data: remaining time = 275 s
12:14 prolong_timer after fwd-data-end: remaining time = 275 s
12:14 response to data end: "250 2.0.0 Ok: queued as 390B4207A16"
12:14 prolong_timer after fwd-rundown-1: remaining time = 275 s
12:14 mail_via_smtp: 250 2.6.0 Ok, id=44373-04, from MTA: 250 2.0.0 Ok: queued as 390B4207A16
12:14 prolong_timer after forwarding: remaining time = 275 s
12:14 one_response_for_all <*from*>: success, dsn_needed=0, '250 2.6.0 Ok, id=44373-04, from MTA: 250 2.0.0 Ok: queued as 390B4207A16'
12:14 warnsender_with_pass=, dsn_needed=0, exit=0, 250 2.6.0 Ok, id=44373-04, from MTA: 250 2.0.0 Ok: queued as 390B4207A16
12:14 Passed, <*from*> -> <*to*>, Message-ID: <00e701c631aa$91f65880$0100a8c0@Servidor>, Hits: -
12:14 sending LMTP response for <*to*>: "250 2.6.0 Ok, id=44373-04, from MTA: 250 2.0.0 Ok: queued as 390B4207A16"
12:14 timer stopped after DATA end
12:14 rmdir_recursively: /var/amavis/amavis-20060214T181028-44373/parts, excl=1
12:14 TIMING [total 27437 ms]
SMTP LHLO..........: 190 ( 1%)
SMTP pre-MAIL......: 180 ( 1%)
SMTP pre-DATA-flush: 4 ( 0%)
SMTP DATA..........: 11976 (44%)
body hash..........: 25 ( 0%)
lookup_sql.........: 15 ( 0%)
mime_decode........: 314 ( 1%)
AV-scan-1..........: 19 ( 0%)
fwd-connect........: 409 ( 1%)
fwd-mail-from......: 169 ( 1%)
fwd-rcpt-to........: 199 ( 1%)
write-header.......: 143 ( 1%)
fwd-data...........: 13158 (48%)
fwd-data-end.......: 449 ( 2%)
fwd-rundown........: 180 ( 1%)
unlink-3-files.....: 6 ( 0%)
rundown............: 1 ( 0%)
12:14 LMTP> 250 2.6.0 Ok, id=44373-04, from MTA: 250 2.0.0 Ok: queued as 390B4207A16
12:14 LMTP> 250 2.6.0 Ok, id=44373-04, from MTA: 250 2.0.0 Ok: queued as 390B4207A16
12:15 prolong_timer after reading SMTP command: remaining time = 0 s
12:15 LMTP< RSET\r\n
12:15 LMTP> 250 2.0.0 Ok RSET
------------------------------------------------------------------------

Further tests indicate that the bigger the message, the more it takes
to be processed:

TIMING [total 8216 ms] -> msg had 605.157 bytes (73 bytes/ms)
TIMING [total 8887 ms] -> msg had 606.046 bytes (68 bytes/ms)
TIMING [total 11900 ms] -> msg had 867.454 bytes (73 bytes/ms)
TIMING [total 27437 ms] -> msg had 2.503.909 bytes (91 bytes/ms)


I don't know if this problem is with the Perl modules, Postfix
or FreeBSD configuration... but it seems that the communication
between amavis and postfix is much slower than before the OS
upgrade. And we didn't change amavis nor postfix
configuration... :-(

Any more ideas?

[]s!
--
.... Everybody wants to go to heaven, but nobody wants to die.


-------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc. Do you grep through log files
for problems? Stop! Download the new AJAX search engine that makes
searching your log files as easy as surfing the web. DOWNLOAD SPLUNK!
http://sel.as-us.falkag.net/sel?cmd=...486&dat=121642
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/...fo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/