Justin Kim wrote: >> At 07:03 PM 9/12/2007, Justin Kim wrote: >>> ... >> Looks like messages are taking longer to be processed. Notice that >> only 12 PID's are active. >> >> -- >> Noel Jones >> > Hi Noel, > Thank you for your kind explanation. > As you suggested I changed log level = 2 and looked at the timing. > And this looks little longer than what it should be I think. > I don't know what is the ideal timing for amavis. > Could this be because my hardware especially CPU? > When I do top and monitor system, I see some available RAM but I see CPU is > peaking. > I got Xeon 3.0 Ghz and 4 GB of RAM. (2 core) > And can you tell me what are the last few lines of maillog. (Tempdir is to > be preserved!) > Can you suggest me the best possible scenario to get this one working? > Thank you, > Justin > > maillog: > ---------------------------------------------------------------------------- > ------------------------------------------ > Sep 12 22:33:55 amavis1 amavis[15775]: (15775-01-6) TIMING [total 15190 > ms] - lookup_sql: 4 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 35 > (0%)0, check_init: 1 (0%)0, digest_hdr: 1 (0%)0, digest_body: 0 (0%)0, > gen_mail_id: 1 (0%)0, check_header: 3 (0%)0, spam-wb-list: 4 (0%)0, SA > parse: 3 (0%)0, SA check: 15086 (99%)100, update_cache: 10 (0%)100, > decide_mail_destiny: 3 (0%)100, fwd-connect: 14 (0%)100, fwd-xforward: 1 > (0%)100, fwd-mail-pip: 3 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: > 0 (0%)100, write-header: 2 (0%)100, fwd-data-contents: 0 (0%)100, > fwd-end-chkpnt: 4 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 11 > (0%)100, update_snmp: 2 (0%)100, SMTP pre-response: 1 (0%)100, SMTP > response: 0 (0%)100, unlink-0-files: 0 (0%)100, rundown: 0 (0%)100 > > Sep 12 22:33:58 amavis1 amavis[15765]: (15765-01-10) TIMING [total 6550 > ms] - lookup_sql: 60 (1%)1, SMTP pre-DATA-flush: 2 (0%)1, SMTP DATA: 1 > (0%)1, check_init: 1 (0%)1, digest_hdr: 1 (0%)1, digest_body: 0 (0%)1, > gen_mail_id: 1 (0%)1, check_header: 3 (0%)1, spam-wb-list: 4 (0%)1, SA > parse: 4 (0%)1, SA check: 6366 (97%)98, update_cache: 28 (0%)99, > decide_mail_destiny: 3 (0%)99, fwd-connect: 32 (0%)99, fwd-xforward: 20 > (0%)100, fwd-mail-pip: 4 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: > 0 (0%)100, write-header: 2 (0%)100, fwd-data-contents: 0 (0%)100, > fwd-end-chkpnt: 4 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 11 > (0%)100, update_snmp: 2 (0%)100, SMTP pre-response: 1 (0%)100, SMTP > response: 0 (0%)100, unlink-0-files: 0 (0%)100, rundown: 0 (0%)100 > > Sep 12 22:34:00 amavis1 amavis[15774]: (15774-01-6) TIMING [total 14662 > ms] - lookup_sql: 4 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 35 > (0%)0, check_init: 1 (0%)0, digest_hdr: 1 (0%)0, digest_body: 0 (0%)0, > gen_mail_id: 1 (0%)0, check_header: 3 (0%)0, spam-wb-list: 4 (0%)0, SA > parse: 4 (0%)0, SA check: 14556 (99%)100, update_cache: 11 (0%)100, > decide_mail_destiny: 3 (0%)100, fwd-connect: 13 (0%)100, fwd-xforward: 1 > (0%)100, fwd-mail-pip: 4 (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: > 0 (0%)100, write-header: 2 (0%)100, fwd-data-contents: 0 (0%)100, > fwd-end-chkpnt: 4 (0%)100, prepare-dsn: 1 (0%)100, main_log_entry: 10 > (0%)100, update_snmp: 2 (0%)100, SMTP pre-response: 1 (0%)100, SMTP > response: 0 (0%)100, unlink-0-files: 0 (0%)100, rundown: 0 (0%)100 >
I don't see anything wrong with these times. They summarize as: $ ./amavis-logwatch --timings 100 --timing_percentiles "50 100" < maillog.jkim ================================================================= Timing Percentiles % Time Total (s) 50% 100% ----------------------------------------------------------------- SA check 98.91% 36.008 14.556 15.086 SMTP DATA 0.20% 0.071 0.035 0.035 lookup_sql 0.19% 0.068 0.004 0.060 fwd-connect 0.16% 0.059 0.014 0.032 update_cache 0.13% 0.049 0.011 0.028 main_log_entry 0.09% 0.032 0.011 0.011 fwd-xforward 0.06% 0.022 0.001 0.020 spam-wb-list 0.03% 0.012 0.004 0.004 fwd-end-chkpnt 0.03% 0.012 0.004 0.004 SA parse 0.03% 0.011 0.004 0.004 fwd-mail-pip 0.03% 0.011 0.004 0.004 decide_mail_destiny 0.02% 0.009 0.003 0.003 check_header 0.02% 0.009 0.003 0.003 update_snmp 0.02% 0.006 0.002 0.002 write-header 0.02% 0.006 0.002 0.002 SMTP pre-DATA-flush 0.02% 0.006 0.002 0.002 digest_hdr 0.01% 0.003 0.001 0.001 prepare-dsn 0.01% 0.003 0.001 0.001 gen_mail_id 0.01% 0.003 0.001 0.001 SMTP pre-response 0.01% 0.003 0.001 0.001 check_init 0.01% 0.003 0.001 0.001 rundown 0.00% 0.000 0.000 0.000 fwd-data-chkpnt 0.00% 0.000 0.000 0.000 unlink-0-files 0.00% 0.000 0.000 0.000 digest_body 0.00% 0.000 0.000 0.000 fwd-rcpt-pip 0.00% 0.000 0.000 0.000 SMTP response 0.00% 0.000 0.000 0.000 fwd-data-contents 0.00% 0.000 0.000 0.000 ================================================================= Total Time 100.00% 36.406 98% of the time, amavis is doing SpamAssassin checks, which takes no longer than 15.086 seconds (using your three samples, one of which was conspicuously fast). This would lead me to indicate your network checks are enabled. > Sep 12 22:34:00 amavis1 amavis[15774]: (15774-01-7) lookup_sql_field(id) > (WARN: no such field in the SQL table), "[EMAIL PROTECTED]" > result=undef > Sep 12 22:34:01 amavis1 amavis[15758]: Net::Server: 2007/09/12-22:34:01 > Server closing! > Sep 12 22:34:01 amavis1 amavis[15765]: (15765-01-11) (!)TempDir removal: > tempdir is to be PRESERVED: /var/amavis/tmp/amavis-20070912T223232-15765 ... I'm no SQL expert, but it appears there is no "id" field in your table, so lookup of [EMAIL PROTECTED] fails, and that instance of amavis closes. MrC ------------------------------------------------------------------------- This SF.net email is sponsored by: Microsoft Defy all challenges. Microsoft(R) Visual Studio 2005. http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/ _______________________________________________ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
