Re: [AMaViS-user] Amavis + Postfix on a separate machine delivery

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), "dpowell@classicheadlines.com"
> 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 dpowell@classicheadlines.com 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/...fo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/