Hi,
Mail occasionally slows down here and the main issue we see is the very
long SA checks and SA TIMEOUTS. This forces us to drop the size mail we
scan and restart Amavis and Apamassasin otherwise the queues will grow
into the thousands. Also note that the Amavis daemons will be running at
100% or so during this. I have included a sampling of our logs and
wanted to see what people thought as to possible problems or solutions
for this. What information should I add to help diagnose this problem.
Spamassassin v. 3.1.8
We do have network checks on to catch embedded urls which catches a
large number of spam messages.
This is a normal, for us, timing log. Is 1193 ms slow as a norm?
Jan 12 18:22:10 atl02010303 amavis[24952]: (24952-08) TIMING [total 1193
ms] - SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 0 (0%)0, SMTP pre-DATA-flush: 1
(0%)0, SMTP DATA: 81 (7%)7, body_digest: 1 (0%)7, gen_mail_id: 0 (0%)7,
mime_decode: 10 (1%)8, get-file-type2: 10 (1%)9, decompose_part: 1
(0%)9, parts_decode: 0 (0%)9, AV-scan-1: 7 (1%)9, spam-wb-list: 1
(0%)10, SA msg read: 1 (0%)10, SA parse: 3 (0%)10, SA check: 926
(78%)88, update_cache: 1 (0%)88, fwd-connect: 3 (0%)88, fwd-mail-from: 1
(0%)88, fwd-rcpt-to: 1 (0%)88, write-header: 1 (0%)88, fwd-data: 1
(0%)88, fwd-data-end: 131 (11%)99, fwd-rundown: 1 (0%)99,
main_log_entry: 7 (1%)100, update_snmp: 1 (0%)100, unlink-2-files: 1
(0%)100, rundown: 0 (0%)100
Shortly after the above we start to see this.
Jan 12 18:22:49 atl02010303 amavis[25081]: (25081-06) SA TIMED OUT,
backtrace: at
/usr/lib/perl5/vendor_perl/5.8.8/Mail/SpamAssassin/DBBasedAddrList.pm
line 165\n\teval {...} called at
/usr/lib/perl5/vendor_perl/5.8.8/Mail/SpamAssassin/DBBasedAddrList.pm
line
165\n\tMail::SpamAssassin::DBBasedAddrList::remove_entry('Mail::SpamAssassin::DBBasedAddrList=HASH(0xb118eb4)',
'HASH(0xb10ca64)') called at
/usr/lib/perl5/vendor_perl/5.8.8/Mail/SpamAssassin/AutoWhitelist.pm line
135\n\tMail::SpamAssassin::AutoWhitelist::check_address('Mail::SpamAssassin::AutoWhitelist=HASH(0xb33b358)',
'newslet...@foreclosure.com', 201.122.43.11) called at
/usr/lib/perl5/vendor_perl/5.8.8/Mail/SpamAssassin/Plugin/AWL.pm line
356\n\teval {...} called at
/usr/lib/perl5/vendor_perl/5.8.8/Mail/SpamAssassin/Plugin/AWL.pm line
352\n\tMail::SpamAssassin::Plugin::AWL::check_from_in_auto_whitelist('Mail::SpamAssassin::Plugin::AWL=HASH(0xa012814)',
'Mail::SpamAssassin::PerMsgStatus=H...
This is an example TIMING during the problem.
Jan 12 18:22:51 atl02010303 amavis[25149]: (25149-01) TIMING [total
29310 ms] - SMTP EHLO: 4 (0%)0, SMTP pre-MAIL: 0 (0%)0, mkdir tempdir: 0
(0%)0, create email.txt: 0 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP
DATA: 77 (0%)0, body_digest: 1 (0%)0, gen_mail_id: 0 (0%)0, mkdir parts:
0 (0%)0, mime_decode: 12 (0%)0, get-file-type2: 11 (0%)0,
decompose_part: 1 (0%)0, parts_decode: 0 (0%)0, AV-scan-1: 8 (0%)0,
spam-wb-list: 2 (0%)0, SA msg read: 1 (0%)0, SA parse: 2 (0%)0, SA
check: 29062 (99%)100, update_cache: 1 (0%)100, fwd-connect: 4 (0%)100,
fwd-mail-from: 0 (0%)100, fwd-rcpt-to: 1 (0%)100, write-header: 1
(0%)100, fwd-data: 1 (0%)100, fwd-data-end: 105 (0%)100, fwd-rundown: 1
(0%)100, main_log_entry: 9 (0%)100, update_snmp: 1 (0%)100,
unlink-2-files: 1 (0%)100, rundown: 0 (0%)100
Another example.
Jan 12 18:23:21 atl02010303 amavis[25149]: (25149-01-2) TIMING [total
30040 ms] - SMTP pre-DATA-flush: 1 (0%)0, SMTP DATA: 39 (0%)0,
body_digest: 1 (0%)0, gen_mail_id: 0 (0%)0, mime_decode: 5 (0%)0,
get-file-type1: 9 (0%)0, parts_decode: 0 (0%)0, AV-scan-1: 6 (0%)0,
spam-wb-list: 1 (0%)0, SA msg read: 1 (0%)0, SA parse: 2 (0%)0, SA
check: 29874 (99%)100, update_cache: 2 (0%)100, post-do_spam: 1 (0%)100,
fwd-connect: 5 (0%)100, fwd-mail-from: 1 (0%)100, fwd-rcpt-to: 1
(0%)100, write-header: 1 (0%)100, fwd-data: 1 (0%)100, fwd-data-end: 79
(0%)100, fwd-rundown: 1 (0%)100, main_log_entry: 7 (0%)100, update_snmp:
1 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0 (0%)100
-rcr
