Debug Timmings

[Nuno Fernandes]

On Monday 18 April 2011, david touzeau wrote:
> Le lundi 18 avril 2011 à 17:32 +0100, Nuno Fernandes a écrit :
> > Hello,
> > 
> > I have a amavisd-new-2.6.4 installed and somewhat this weekend, it
> > started to take long time to process emails (drom 2/3 sec to 15/20 sec
> > per email).
> > 
> > I've increased amavisd-new loglevel to 5 and see that spamassassin
> > takes 97% of the time:
> > 
> > Apr 18 17:32:19 etmx1 amavis[19306]: (19306-10) TIMING [total 13003
> > ms] - SMTP greeting: 2 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 2
> > (0%)0, lookup_sql: 5 (0%)0, SMTP pre-DATA-flush: 1 (0%)0, SMTP DATA:
> > 31 (0%)0, check_init: 0 (0%)0, digest_hdr: 142 (1%)1,
> > digest_body_dkim: 2 (0%)1, sql-enter: 8 (0%)2, mime_decode: 15 (0%)2,
> > get-file-type1: 87 (1%)2, decompose_part: 1 (0%)2, parts_decode: 0
> > (0%)2, AV-scan-1: 7 (0%)2, AV-scan-2: 2 (0%)2, lookup_sql: 4 (0%)2,
> > lookup_sql: 2 (0%)2, lookup_sql: 3 (0%)2, lookup_sql: 1 (0%)2,
> > spam-wb-list: 2 (0%)2, SA parse: 5 (0%)2, SA check: 12607 (97%)99,
> > update_cache: 9 (0%)100, decide_mail_destiny: 3 (0%)100, fwd-connect:
> > 8 (0%)100, fwd-xforward: 1 (0%)100, fwd-mail-pip: 10 (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: 16 (0%)100,
> > prepare-dsn: 2 (0%)100, main_log_entry: 6 (0%)100, sql-update: 4
> > (0%)100, update_snmp: 2 (0%)100, SMTP pre-response: 1 (0%)100, SMTP
> > response: 1 (0%)100,
> > 
> > How can i increase the loglevel so that i can see what is taking that
> > long?
> > 
> > Thanks,
> > 
> > Nuno Fernandes
> 
> Hi
> 
> I have the same issues for men amavisd childs turn to 100% CPU and
> exceed the TTL child period !
> You can find here what i have set in spamassassin in order to reduce the
> time
> perhaps you are more lucky
> http://groups.google.com/group/mailing.unix.amavis-user/browse_thread/threa
> d/2f41658d956bca51

Hum.. my doesn't  turn 100% cpu, but as i have spamassassin >= 3.3.0, i've 
checked the logs and found:

Apr 18 17:32:19 etmx1 amavis[19306]: (19306-10) TIMING-SA total 12614 ms - 
parse: 3 (0.0%), extract_message_metadata: 145 (1.1%), get_uri_detail_list: 
1.24 (0.0%), tests_pri_-1000: 23 (0.2%), tests_pri_-950: 1.51 (0.0%), 
tests_pri_-900: 3 (0.0%), tests_pri_-400: 26 (0.2%), check_bayes: 23 (0.2%), 
tests_pri_0: 12357 (98.0%), check_dkim_adsp: 58 (0.5%), check_spf: 261 (2.1%), 
poll_dns_idle: 240 (1.9%), check_razor2: 907 (7.2%), check_dcc: 478 (3.8%), 
check_pyzor: 185 (1.5%), tests_pri_500: 18 (0.1%), tests_pri_1000: 6 (0.0%), 
total_awl: 4 (0.0%), check_awl: 0.97 (0.0%), update_awl: 0.36 (0.0%), 
tests_pri_2000: 1.62 (0.0%), get_report: 1.21 (0.0%)

Aparently is that tests_pri in spamassassin that is taking 98% of the time.. 
Does anyone know what it is?

Thanks,
Nuno Fernandes

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.amavis.org/pipermail/amavis-users/attachments/20110418/ade9cce6/attachment.html>