On Tue, 14 Feb 2006, Mark Martinec wrote:
Feb 14 13:27:41 mercury amavis[25023]: (25023-08) TIMING [total 300433 ms]
- SMTP EHLO: 3 (0%)0, SMTP pre-MAIL: 1 (0%)0, SMTP pre-DATA-flush: 461
(0%)0, unlink-0-files: 299967 (100%)100, rundown: 0 (0%)100
Feb 14 13:27:41 mercury amavis[25023]: (25023-08) ESMTP: NOTICE: ABORTING
the session: timed out
Now, Postfix is saying "timeout after DATA", but it looks to me like
amavisd-new's problem was in unlinking zero files? Or is that message
incorrect and the problem was elsewhere?
Most likely the problem is elsewhere, the unlink-0-files is probably
just an innocent bystander that accumulated all the timing in absence
of a better reason.
Well, here's one that did make it through, and I'm not sure where the slowdown
is - I can see the section of code between pre-MAIL and pre-DATA-flush, but am
not enough of a Perl guru to figure out what's going on there that might slow
things down:
Feb 14 17:00:34 mercury amavis[14519]: (14519-03) TIMING [total 30100 ms] -
SMTP EHLO: 3 (0%)0, SMTP pre-MAIL: 1 (0%)0, SMTP pre-DATA-flush: 20431 (68%)68,
SMTP DATA: 9123 (30%)98, body_digest: 1 (0%)98, gen_mail_id: 0 (0%)98,
mime_decode: 32 (0%)98, get-file-type3: 17 (0%)98, decompose_part: 1 (0%)98,
parts_decode: 0 (0%)98, AV-scan-1: 183 (1%)99, spam-wb-list: 9 (0%)99, SA msg
read: 2 (0%)99, SA parse: 4 (0%)99, SA check: 266 (1%)100, update_cache: 2
(0%)100, save-to-local-mailbox: 7 (0%)100, post-do_spam: 1 (0%)100,
main_log_entry: 13 (0%)100, update_snmp: 1 (0%)100, unlink-3-files: 2 (0%)100,
rundown: 0 (0%)100
I also on occasion see similar timings where the holdup is in the SMTP DATA
section, like this one:
Feb 14 17:04:53 mercury amavis[14755]: (14755-03) TIMING [total 114165 ms] -
SMTP EHLO: 3 (0%)0, SMTP pre-MAIL: 1 (0%)0, SMTP pre-DATA-flush: 1962 (2%)2,
SMTP DATA: 111780 (98%)100, body_digest: 1 (0%)100, gen_mail_id: 0 (0%)100,
mime_decode: 9 (0%)100, get-file-type1: 13 (0%)100, decompose_part: 1 (0%)100,
parts_decode: 0 (0%)100, AV-scan-1: 181 (0%)100, spam-wb-list: 3 (0%)100, SA
msg read: 0 (0%)100, SA parse: 2 (0%)100, SA check: 116 (0%)100, update_cache:
1 (0%)100, fwd-connect: 8 (0%)100, fwd-xforward: 1 (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: 60 (0%)100, fwd-rundown: 3 (0%)100, main_log_entry: 14 (0%)100,
update_snmp: 1 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0 (0%)100
During this time, the load on the machine is below 1 (.3 to .5), memory is
fully used (I'll guess 3/4 used+shared, a little bit of buffers and the rest
cached) and there's not a lot of other mails going through. There's 20
amavisd-new processes set to run with an equal limit for Postfix's smtpd.
I'm stumped on this one.. most of
the time, these messages it times out on are junkmail, so I don't mind too
much if it forces a spammer to try again - but now and then I'm getting
user reports of anywhere from 15 seconds to 4 minutes to send an email.
Please try to capture such event with $log_level set to 5
(or 'amavisd debug').
Will do soon - I have a feeling that if I figure out the timing issue above,
it will reduce or remove the other problems.
--
Steve Huston - W2SRH - Unix Sysadmin, Dept. of Astrophysical Sciences
Princeton University | ICBM Address: 40.346525 -74.651285
126 Peyton Hall |"On my ship, the Rocinante, wheeling through
Princeton, NJ 08544 | the galaxies; headed for the heart of Cygnus,
(609) 258-7375 | headlong into mystery." -Rush, 'Cygnus X-1'
-------------------------------------------------------
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=lnk&kid=103432&bid=230486&dat=121642
_______________________________________________
AMaViS-user mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/
