Postfix Spamassassin Amavisd Clamav: Slow down

jinfeld · #1 13th November 2006, 06:08 AM

We are using Postfix Spamassassin Amavisd ClamAV as an email gateway to an Exchange Server.
During heavy loads the system is very slow (many minutes) to respond to a command prompt and the mail just stacks up in the Postfix queue. Oftentimes a reboot will help.

The maillog shows an inordinate amount of time is spent during the AMAVIS fwd-data-end stage.
What does "fwd-data-end" indicate?
Where do I go to check/fix whatever controls "fwd-data-end"?
Is this the cause of the severe slowdowns or should I bark up another tree (I am already howling at the moon)?
Thanks,
Jerry

For example, some TIMING entries:

Nov 10 13:59:25 ISISDSPAM amavis[4563]: (04563-07-19) TIMING [total 14410 ms] - SMTP pre-DATA-flush: 10 (0%)0, SMTP DATA: 107 (1%)1, body_digest: 1 (0%)1, gen_mail_id: 0 (0%)1, mime_decode: 9 (0%)1, get-file-type2: 108 (1%)2, decompose_part: 1 (0%)2, parts_decode: 0 (0%)2, AV-scan-1: 11 (0%)2, spam-wb-list: 1 (0%)2, SA msg read: 1 (0%)2, SA parse: 1 (0%)2, SA check: 4149 (29%)31, SA finish: 2 (0%)31, update_cache: 1 (0%)31, decide_mail_destiny: 1 (0%)31, fwd-connect: 5 (0%)31, fwd-mail-from: 1 (0%)31, fwd-rcpt-to: 1 (0%)31, fwd-data-cmd: 0 (0%)31, write-header: 0 (0%)31, fwd-data-contents: 0 (0%)31, fwd-data-end: 9578 (66%)97, fwd-rundown: 108 (1%)98, prepare-dsn: 68 (0%)98, main_log_entry: 246 (2%)100, unlink-2-files: 1 (0%)100, rundown: 0 (0%)100

Nov 10 13:59:26 ISISDSPAM amavis[4562]: (04562-07-22) TIMING [total 6196 ms] - SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 29 (0%)1, body_digest: 1 (0%)1, gen_mail_id: 0 (0%)1, mime_decode: 194 (3%)4, get-file-type1: 10 (0%)4, decompose_part: 1 (0%)4, parts_decode: 0 (0%)4, spam-wb-list: 3 (0%)4, update_cache: 0 (0%)4, decide_mail_destiny: 1 (0%)4, fwd-connect: 399 (6%)10, fwd-mail-from: 1 (0%)10, fwd-rcpt-to: 303 (5%)15, fwd-data-cmd: 0 (0%)15, write-header: 0 (0%)15, fwd-data-contents: 0 (0%)15, fwd-data-end: 5194 (84%)99, fwd-rundown: 21 (0%)99, prepare-dsn: 12 (0%)100, main_log_entry: 23 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0 (0%)100

Nov 10 13:59:37 ISISDSPAM amavis[4562]: (04562-07-23) TIMING [total 10596 ms] - SMTP pre-DATA-flush: 9 (0%)0, SMTP DATA: 32 (0%)0, body_digest: 1 (0%)0, gen_mail_id: 0 (0%)0, mime_decode: 5 (0%)0, get-file-type1: 10 (0%)1, decompose_part: 1 (0%)1, parts_decode: 0 (0%)1, spam-wb-list: 3 (0%)1, update_cache: 0 (0%)1, decide_mail_destiny: 1 (0%)1, fwd-connect: 5 (0%)1, fwd-mail-from: 1 (0%)1, fwd-rcpt-to: 1 (0%)1, fwd-data-cmd: 0 (0%)1, write-header: 1 (0%)1, fwd-data-contents: 0 (0%)1, fwd-data-end: 10520 (99%)100, fwd-rundown: 1 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 4 (0%)100, unlink-1-files: 0 (0%)100, rundown: 0 (0%)100

Nov 10 13:59:49 ISISDSPAM amavis[4562]: (04562-07-24) TIMING [total 11917 ms] - SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 69 (1%)1, body_digest: 1 (0%)1, gen_mail_id: 0 (0%)1, mime_decode: 438 (4%)4, get-file-type2: 10 (0%)4, parts_decode: 0 (0%)4, AV-scan-1: 11 (0%)4, spam-wb-list: 2 (0%)4, SA msg read: 1 (0%)4, SA parse: 2 (0%)4, SA check: 1988 (17%)21, SA finish: 2 (0%)21, update_cache: 1 (0%)21, decide_mail_destiny: 2 (0%)21, fwd-connect: 5 (0%)21, fwd-mail-from: 1 (0%)21, fwd-rcpt-to: 1 (0%)21, fwd-data-cmd: 0 (0%)21, write-header: 0 (0%)21, fwd-data-contents: 1 (0%)21, fwd-data-end: 9372 (79%)100, fwd-rundown: 1 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 6 (0%)100, unlink-2-files: 1 (0%)100, rundown: 0 (0%)100

Nov 10 13:59:50 ISISDSPAM amavis[4563]: (04563-07-20) TIMING [total 24444 ms] - SMTP pre-DATA-flush: 106 (0%)0, SMTP DATA: 133 (1%)1, body_digest: 1 (0%)1, gen_mail_id: 0 (0%)1, mime_decode: 275 (1%)2, get-file-type3: 16 (0%)2, parts_decode: 0 (0%)2, AV-scan-1: 36 (0%)2, spam-wb-list: 1 (0%)2, SA msg read: 3 (0%)2, SA parse: 5 (0%)2, SA check: 3527 (14%)17, SA finish: 2 (0%)17, update_cache: 1 (0%)17, decide_mail_destiny: 1 (0%)17, fwd-connect: 5 (0%)17, fwd-mail-from: 1 (0%)17, fwd-rcpt-to: 1 (0%)17, fwd-data-cmd: 0 (0%)17, write-header: 0 (0%)17, fwd-data-contents: 3 (0%)17, fwd-data-end: 20211 (83%)100, fwd-rundown: 24 (0%)100, prepare-dsn: 0 (0%)100, main_log_entry: 90 (0%)100, unlink-3-files: 1 (0%)100, rundown: 0 (0%)100

Zigzagcom · #2 13th November 2006, 06:45 AM

Hi, I found this link explaining "fwd-data-end". Maybe the explanation will help you pinpoint the problem.
http://www.mail-archive.com/amavis-u.../msg00062.html

On the page of the link I posted, at the bottom, there are a couple of responses...check them out. It seems that the mail is making a second pass through postfix, being forwarded to the exchange server.

I also would look at the input queue on the exchange server.

jinfeld · #3 13th November 2006, 07:19 PM

How can I check that Postfix is not wasting time doing mail checks during the second pass?
These are the setting in /etc/postfix/master.cf
Doesn't the line receive_override_option stop the second pass scanning?

smtp-amavis unix - - n - 2 lmtp
-o lmtp_data_done_timeout=1200s
-o lmtp_never_send_ehlo=yes
-o disable_dns_lookups=yes
-o lmtp_send_xforward_command=yes
-o max_use=20

127.0.0.1:10025 inet n - n - - smtpd
-o content_filter=
-o smtpd_restriction_classes=
-o smtpd_delay_reject=no
-o smtpd_client_restrictions=permit_mynetworks,reject
-o smtpd_helo_restrictions=
-o smtpd_sender_restrictions=
-o smtpd_recipient_restrictions=permit_mynetworks,rej ect
-o smtpd_data_restrictions=reject_unauth_pipelining
-o smtpd_end_of_data_restrictions=
-o mynetworks=127.0.0.0/8
-o smtpd_error_sleep_time=0
-o smtpd_soft_error_limit=1001
-o smtpd_hard_error_limit=1000
-o smtpd_client_connection_count_limit=0
-o smtpd_milters=
-o local_header_rewrite_clients=
-o local_recipient_maps=
-o relay_recipient_maps=
-o receive_override_options=no_header_body_checks,no_ unknown_recipient_checks