You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Helmut Schneider <ju...@gmx.de> on 2010/06/02 21:52:51 UTC
Performance problem body tests
Hi,
with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
problem:
[/var/amavis/tmp]# spamassassin -D -lint <
/var/amavis/tmp/amavis-20100602T192227-44802/email.txt
Jun 2 21:37:08.809 [50826] warn: The -l option has been deprecated and
is no longer supported, ignoring.
Jun 2 21:37:08.810 [50826] dbg: logger: adding facilities: all
Jun 2 21:37:08.811 [50826] dbg: logger: logging level is DBG
Jun 2 21:37:08.811 [50826] dbg: generic: SpamAssassin version 3.3.1
Jun 2 21:37:08.812 [50826] dbg: generic: Perl 5.010001,
PREFIX=/usr/local, DEF_RULES_DIR=/usr/local/share/spamassassin,
LOCAL_RULES_DIR=/usr/local/etc/mail/spamassassin,
LOCAL_STATE_DIR=/var/db/spamassassin
[...]
Jun 2 21:37:15.626 [50826] dbg: rules: run_generic_tests - compiling
eval code: body, priority 0
Jun 2 21:37:15.627 [50826] dbg: rules: compiled body tests
Jun 2 21:37:20.524 [50826] dbg: rules: ran body rule __DOS_BODY_THU
======> got hit: "Thursday"
Jun 2 21:37:22.444 [50826] dbg: rules: ran body rule __YOU_ASSIST
======> got hit: "your assistance"
Jun 2 21:37:26.018 [50826] dbg: rules: ran body rule
__FILL_THIS_FORM_PARTIAL ======> got hit: "Tel : "
Jun 2 21:37:26.042 [50826] dbg: rules: ran body rule
__FILL_THIS_FORM_PARTIAL ======> got hit: "Tel : "
Jun 2 21:37:26.424 [50826] dbg: rules: ran body rule __DOS_BODY_TUE
======> got hit: "Tuesday"
Jun 2 21:37:27.410 [50826] dbg: rules: ran body rule __PLS_REVIEW
======> got hit: "Please see attached"
Jun 2 21:37:33.503 [50826] dbg: rules: ran body rule __DOS_BODY_FRI
======> got hit: "Friday"
Jun 2 21:37:37.334 [50826] dbg: rules: ran body rule
__SUBSCRIPTION_INFO ======> got hit: "Register"
Jun 2 21:37:37.409 [50826] dbg: rules: ran body rule __HAS_ANY_EMAIL
======> got hit: "s@vodafone.c"
Jun 2 21:37:37.885 [50826] dbg: rules: ran body rule __NONEMPTY_BODY
======> got hit: "R"
Jun 2 21:37:43.231 [50826] dbg: rules: ran body rule __HUSH_HUSH
======> got hit: "confidential"
Jun 2 21:37:44.008 [50826] dbg: rules: running uri tests; score so
far=0
[...]
Jun 2 21:37:45.723 [50826] dbg: learn: initializing learner
Jun 2 21:37:45.789 [50826] dbg: check: is spam? score=0.012 required=5
Jun 2 21:37:45.790 [50826] dbg: check:
tests=HTML_FONT_SIZE_LARGE,HTML_MESSAGE,T_FILL_THIS_FORM
Jun 2 21:37:45.791 [50826] dbg: check:
subtests=__ANY_TEXT_ATTACH,__ANY_TEXT_ATTACH_DOC,__COMMENT_EXISTS,__CT,_
_CTYPE_HAS_BOUNDARY,__CTYPE_MULTIPART_ALT,__CTYPE_MULTIPART_ANY,__DKIM_D
EPENDABLE,__DOS_BODY_FRI,__DOS_BODY_THU,__DOS_BODY_TUE,__DOS_HAS_ANY_URI
,__DOS_RCVD_WED,__DOS_REF_2_WK_DAYS,__DOS_REF_NEXT_WK_DAY,__DOS_RELAYED_
EXT,__FILL_THIS_FORM_PARTIAL,__FILL_THIS_FORM_PARTIAL,__FILL_THIS_FORM_P
ARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__F
ILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_
PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__
HAS_ANY_EMAIL,__HAS_ANY_URI,__HAS_DATE,__HAS_MESSAGE_ID,__HAS_MIMEOLE,__
HAS_MSGID,__HAS_RCVD,__HAS_SUBJECT,__HS_SUBJ_RE_FW,__HUSH_HUSH,__IMS_MSG
ID,__IS_EXCH,__LAST_EXTERNAL_RELAY_NO_AUTH,__LAST_UNTRUSTED_RELAY_NO_AUT
H,__MIME_HTML,__MIME_QP,__MIME_VERSION,__NONEMPTY_BODY,__PLS_REVIEW,__RC
VD_IN_2WEEKS,__SANE_MSGID,__SUBJ_RE,__SUBSCRIPTION_INFO,__TAG_EXISTS_BOD
Y,__TAG_EXISTS_HEAD,__TAG_EXISTS_HTML,__TAG_EXISTS_META,__TOCC_EXISTS,__
TVD_MIME_ATT_TP,__YOU_ASSIST
Jun 2 21:37:45.793 [50826] dbg: timing: total 36840 ms - init: 3827
(10.4%), parse: 43 (0.1%), extract_message_metadata: 822 (2.2%),
get_uri_detail_list: 178 (0.5%), tests_pri_-1000: 212 (0.6%),
compile_gen: 538 (1.5%), compile_eval: 79 (0.2%), tests_pri_-950: 52
(0.1%), tests_pri_-900: 35 (0.1%), tests_pri_-400: 392 (1.1%),
check_bayes: 359 (1.0%), tests_pri_0: 30780 (83.6%), dkim_load_modules:
99 (0.3%), check_dkim_signature: 20 (0.1%), check_dkim_adsp: 13 (0.0%),
check_spf: 81 (0.2%), poll_dns_idle: 0.57 (0.0%), check_dcc: 240
(0.7%), check_pyzor: 2 (0.0%), tests_pri_500: 258 (0.7%),
tests_pri_1000: 61 (0.2%), total_awl: 28 (0.1%), check_awl: 6 (0.0%),
update_awl: 4 (0.0%), learn: 118 (0.3%)
[/var/amavis/tmp]#
So the body tests take ~ 30 of 37 seconds. It's not a load problem,
under load it takes >2 minutes and it is reproducable with certain
mails only.
Any idea where to start?
Thanks, Helmut
--
No Swen today, my love has gone away
My mailbox stands for lorn, a symbol of the dawn
Re: Performance problem body tests
Posted by Helmut Schneider <ju...@gmx.de>.
Helmut Schneider wrote:
> with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
> problem:
I might have been able to "catch" a non-confident example mail[1] (bad
example because of the size, but an example).
While SA 3.2.5 needs ~45 seconds, with SA 3.3.1:
Jun 4 03:36:41.029 [56496] dbg: timing: total 103627 ms - init: 1615
(1.6%), parse: 52 (0.0%), extract_message_metadata: 1971 (1.9%),
poll_dns_idle: 772 (0.7%), get_uri_detail_list: 348 (0.3%),
tests_pri_-1000: 467 (0.5%), compile_gen: 292 (0.3%), compile_eval: 35
(0.0%), tests_pri_-950: 23 (0.0%), tests_pri_-900: 28 (0.0%),
tests_pri_-400: 35 (0.0%), tests_pri_0: 99167 (95.7%),
dkim_load_modules: 59 (0.1%), check_dkim_signature: 26 (0.0%),
check_razor2: 2061 (2.0%), check_pyzor: 1.52 (0.0%), tests_pri_500: 188
(0.2%)
Jun 4 03:35:02.226 [56496] dbg: rules: run_generic_tests - compiling
eval code: body, priority 0
Jun 4 03:35:02.227 [56496] dbg: rules: compiled body tests
Jun 4 03:35:18.067 [56496] dbg: rules: ran body rule __I_INHERIT
======> got hit: "I inherited"
Jun 4 03:35:23.007 [56496] dbg: rules: ran body rule __YOU_HAVE_WON
======> got hit: "you won"
Jun 4 03:35:24.733 [56496] dbg: rules: ran body rule __FB_MA ======>
got hit: "MA"
Jun 4 03:35:24.964 [56496] dbg: rules: ran body rule __MASTERS ======>
got hit: "Masters"
Jun 4 03:35:32.730 [56496] dbg: rules: ran body rule __DOS_BODY_WED
======> got hit: "Wednesday"
Jun 4 03:35:33.415 [56496] dbg: rules: ran body rule __FRAUD_IRJ
======> got hit: "holding company"
Jun 4 03:35:34.848 [56496] dbg: rules: ran body rule __KAM_LOTTO3
======> got hit: "claim"
Jun 4 03:35:35.281 [56496] dbg: rules: ran body rule __MILLIONS
======> got hit: "millions of dollar"
Jun 4 03:35:36.387 [56496] dbg: rules: ran body rule __DEAL ======>
got hit: "the deal"
Jun 4 03:35:41.524 [56496] dbg: rules: ran body rule __FB_NATIONAL
======> got hit: "National"
Jun 4 03:35:46.119 [56496] dbg: rules: ran body rule __F_LARGE_MONEY_2
======> got hit: "10 million"
Jun 4 03:36:04.770 [56496] dbg: rules: ran body rule __MBA ======> got
hit: "mba"
Jun 4 03:36:06.071 [56496] dbg: rules: ran body rule __DOS_BODY_FRI
======> got hit: "Friday"
Jun 4 03:36:07.273 [56496] dbg: rules: ran body rule __DOS_LINK
======> got hit: "link"
Jun 4 03:36:09.234 [56496] dbg: rules: ran body rule __DOS_BODY_SAT
======> got hit: "sat"
Jun 4 03:36:09.838 [56496] dbg: rules: ran body rule
__FILL_THIS_FORM_FRAUD_PHISH ======> got hit: "password.
Jun 4 03:36:09.839 [56496] dbg: rules: [...] "
Jun 4 03:36:15.269 [56496] dbg: rules: ran body rule
__SUBSCRIPTION_INFO ======> got hit: "opt out"
Jun 4 03:36:15.521 [56496] dbg: rules: ran body rule __HAS_ANY_EMAIL
======> got hit: "m@wsj.c"
Jun 4 03:36:16.798 [56496] dbg: rules: ran body rule __FB_NUM_PERCNT
======> got hit: "2%"
Jun 4 03:36:16.998 [56496] dbg: rules: ran body rule __YOU_WON_01
======> got hit: "you won"
Jun 4 03:36:17.226 [56496] dbg: rules: ran body rule __NONEMPTY_BODY
======> got hit: "A"
Jun 4 03:36:21.053 [56496] dbg: rules: ran body rule __FB_PICK ======>
got hit: "pick"
Jun 4 03:36:23.851 [56496] dbg: rules: ran body rule __FB_GAME ======>
got hit: "Game"
Jun 4 03:36:30.641 [56496] dbg: rules: ran body rule __FRAUD_DBI
======> got hit: "dollars"
Jun 4 03:36:34.278 [56496] dbg: rules: ran body rule __F_LARGE_MONEY
======> got hit: "200,000"
Jun 4 03:36:36.247 [56496] dbg: rules: ran body rule __HUSH_HUSH
======> got hit: "private"
Jun 4 03:36:36.785 [56496] dbg: rules: ran body rule __LOTSA_MONEY_03
======> got hit: "$300 million"
Jun 4 03:36:38.060 [56496] dbg: rules: ran body rule __FB_S_PRICE
======> got hit: "price"
Jun 4 03:36:38.066 [56496] dbg: async: select found 1 responses ready
(t.o.=0.0)
Jun 4 03:36:38.066 [56496] dbg: async: completed in 96.650 s:
URI-DNSBL, DNSBL:zen.spamhaus.org.:2.46.246.72
Jun 4 03:36:38.067 [56496] dbg: dns: harvested completed queries
Jun 4 03:36:38.068 [56496] dbg: rules: running uri tests; score so
far=1.206
sa-compile didn't make a difference:
Jun 4 04:15:10.870 [84689] dbg: timing: total 103477 ms - init: 1573
(1.5%), parse: 40 (0.0%), extract_message_metadata: 1196 (1.2%),
poll_dns_idle: 6 (0.0%), get_uri_detail_list: 333 (0.3%),
tests_pri_-1000: 468 (0.5%), compile_gen: 262 (0.3%), compile_eval: 28
(0.0%), tests_pri_-950: 29 (0.0%), tests_pri_-900: 40 (0.0%),
tests_pri_-400: 25 (0.0%), tests_pri_0: 99833 (96.5%),
dkim_load_modules: 58 (0.1%), check_dkim_signature: 20 (0.0%),
check_razor2: 266 (0.3%), check_pyzor: 3 (0.0%), tests_pri_500: 196
(0.2%)
I also can reproduce this with Ubuntu 10.4.
[1] http://www.charlieroot.de/downloads/email.txt
--
No Swen today, my love has gone away
My mailbox stands for lorn, a symbol of the dawn
Re: Performance problem body tests
Posted by Ted Mittelstaedt <te...@ipinc.net>.
On 6/3/2010 7:52 AM, Helmut Schneider wrote:
> Helmut Schneider wrote:
>
>> with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
>> problem:
> [...]
>> Any idea where to start?
>
> Appendix: I set up a fresh and clean FreeBSD 8.0 with only SA 3.3.1 and
> Perl 5.10.1_1 and the problem still persists. I then removed all
> packages, compiled perl 5.8.9_3 and compiled SA 3.3.1 and the problem
> still persists.
>
> I then started from scratch and tried with SA 3.2.5. The particular
> body_tests take only 5 seconds (instead of 30).
>
What about SA 3.3.1 and FreeBSD 7.3? Didn't a.smith@ukgrid.net
say that he had the same problem with FBSD 8.0 + SA 3.3.1 but
not with FBSD 7.X and SA 3.3.1?
Ted
Re: Performance problem body tests
Posted by Charles Gregory <cg...@hwcn.org>.
On Thu, 3 Jun 2010, Mark Martinec wrote:
> Here is one common problem of 'certain mail messages'
> taking a long time to process - unresolvable for now:
> https://issues.apache.org/SpamAssassin/show_bug.cgi?id=5590
Sorry, but that bug has been around since 3.2.3 - it would not explain a
sudden sixfold increase in processing time from 3.2.5 to 3.3.1.....
- C
Re: Performance problem body tests
Posted by Mark Martinec <Ma...@ijs.si>.
On Thursday 03 June 2010 18:02:23 Charles Gregory wrote:
> As I mentioned before, I noticed this difference myself, and presumed it
> was just a characteristic of the 'improved' logic for deep-scanning the
> body of emails, and perhaps just a larger number of rules than before....
> Though I am still intrigued by your comment that this happens only on
> 'some' e-mails, not all. Apologies if I missed a response, but was there
> any difference noticable for the mails that process quicker?
Here is one common problem of 'certain mail messages'
taking a long time to process - unresolvable for now:
https://issues.apache.org/SpamAssassin/show_bug.cgi?id=5590
Mark
Re: Performance problem body tests
Posted by Lee Dilkie <Le...@dilkie.com>.
On 6/3/2010 12:02 PM, Charles Gregory wrote:
> On Thu, 3 Jun 2010, Helmut Schneider wrote:
>> I then started from scratch and tried with SA 3.2.5. The particular
>> body_tests take only 5 seconds (instead of 30).
>
> As I mentioned before, I noticed this difference myself, and presumed
> it was just a characteristic of the 'improved' logic for deep-scanning
> the body of emails, and perhaps just a larger number of rules than
> before.... Though I am still intrigued by your comment that this
> happens only on 'some' e-mails, not all. Apologies if I missed a
> response, but was there any difference noticable for the mails that
> process quicker?
>
> - Charles
Are you folks using sa-compile? I found a vast improvement in body scan
performance by switching to it.
-lee
Re: Performance problem body tests
Posted by Charles Gregory <cg...@hwcn.org>.
On Thu, 3 Jun 2010, Helmut Schneider wrote:
> I then started from scratch and tried with SA 3.2.5. The particular
> body_tests take only 5 seconds (instead of 30).
As I mentioned before, I noticed this difference myself, and presumed it
was just a characteristic of the 'improved' logic for deep-scanning the
body of emails, and perhaps just a larger number of rules than before....
Though I am still intrigued by your comment that this happens only on
'some' e-mails, not all. Apologies if I missed a response, but was there
any difference noticable for the mails that process quicker?
- Charles
Re: Performance problem body tests
Posted by Helmut Schneider <ju...@gmx.de>.
Helmut Schneider wrote:
> with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
> problem:
[...]
> Any idea where to start?
Appendix: I set up a fresh and clean FreeBSD 8.0 with only SA 3.3.1 and
Perl 5.10.1_1 and the problem still persists. I then removed all
packages, compiled perl 5.8.9_3 and compiled SA 3.3.1 and the problem
still persists.
I then started from scratch and tried with SA 3.2.5. The particular
body_tests take only 5 seconds (instead of 30).
--
No Swen today, my love has gone away
My mailbox stands for lorn, a symbol of the dawn
Re: Performance problem body tests
Posted by Helmut Schneider <ju...@gmx.de>.
David Michaels wrote:
> Quoting "Helmut Schneider" <ju...@gmx.de>:
>
> > Hi,
> >
> > with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
> > problem:
[...]
> > timing: total 36840 ms - init: 3827 (10.4%), parse: 43 (0.1%),
> > extract_message_metadata: 822 (2.2%), get_uri_detail_list: 178
> > (0.5%), tests_pri_-1000: 212 (0.6%), compile_gen: 538 (1.5%),
> > compile_eval: 79 (0.2%), tests_pri_-950: 52 (0.1%), tests_pri_-900:
> > 35 (0.1%), tests_pri_-400: 392 (1.1%), check_bayes: 359 (1.0%),
> > tests_pri_0: 30780 (83.6%), dkim_load_modules: 99 (0.3%),
> > check_dkim_signature: 20 (0.1%), check_dkim_adsp: 13 (0.0%),
> > check_spf: 81 (0.2%), poll_dns_idle: 0.57 (0.0%), check_dcc: 240
> > (0.7%), check_pyzor: 2 (0.0%), tests_pri_500: 258 (0.7%),
> > tests_pri_1000: 61 (0.2%), total_awl: 28 (0.1%), check_awl: 6
> > (0.0%), update_awl: 4 (0.0%), learn: 118 (0.3%) [/var/amavis/tmp]#
> >
> > So the body tests take ~ 30 of 37 seconds. It's not a load problem,
> > under load it takes >2 minutes and it is reproducable with certain
> > mails only.
> >
> > Any idea where to start?
>
> are you escaping the white spaces and @?
Yes, and also dots. But I also completely removed my custom-rules.cf if
you refer to that.
--
No Swen today, my love has gone away
My mailbox stands for lorn, a symbol of the dawn
Re: Performance problem body tests
Posted by David Michaels <mi...@ucrwcu.rwc.uc.edu>.
Quoting "Helmut Schneider" <ju...@gmx.de>:
> Hi,
>
> with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
> problem:
>
> [/var/amavis/tmp]# spamassassin -D -lint <
> /var/amavis/tmp/amavis-20100602T192227-44802/email.txt
> Jun 2 21:37:08.809 [50826] warn: The -l option has been deprecated and
> is no longer supported, ignoring.
> Jun 2 21:37:08.810 [50826] dbg: logger: adding facilities: all
> Jun 2 21:37:08.811 [50826] dbg: logger: logging level is DBG
> Jun 2 21:37:08.811 [50826] dbg: generic: SpamAssassin version 3.3.1
> Jun 2 21:37:08.812 [50826] dbg: generic: Perl 5.010001,
> PREFIX=/usr/local, DEF_RULES_DIR=/usr/local/share/spamassassin,
> LOCAL_RULES_DIR=/usr/local/etc/mail/spamassassin,
> LOCAL_STATE_DIR=/var/db/spamassassin
> [...]
> Jun 2 21:37:15.626 [50826] dbg: rules: run_generic_tests - compiling
> eval code: body, priority 0
> Jun 2 21:37:15.627 [50826] dbg: rules: compiled body tests
> Jun 2 21:37:20.524 [50826] dbg: rules: ran body rule __DOS_BODY_THU
> ======> got hit: "Thursday"
> Jun 2 21:37:22.444 [50826] dbg: rules: ran body rule __YOU_ASSIST
> ======> got hit: "your assistance"
> Jun 2 21:37:26.018 [50826] dbg: rules: ran body rule
> __FILL_THIS_FORM_PARTIAL ======> got hit: "Tel : "
> Jun 2 21:37:26.042 [50826] dbg: rules: ran body rule
> __FILL_THIS_FORM_PARTIAL ======> got hit: "Tel : "
> Jun 2 21:37:26.424 [50826] dbg: rules: ran body rule __DOS_BODY_TUE
> ======> got hit: "Tuesday"
> Jun 2 21:37:27.410 [50826] dbg: rules: ran body rule __PLS_REVIEW
> ======> got hit: "Please see attached"
> Jun 2 21:37:33.503 [50826] dbg: rules: ran body rule __DOS_BODY_FRI
> ======> got hit: "Friday"
> Jun 2 21:37:37.334 [50826] dbg: rules: ran body rule
> __SUBSCRIPTION_INFO ======> got hit: "Register"
> Jun 2 21:37:37.409 [50826] dbg: rules: ran body rule __HAS_ANY_EMAIL
> ======> got hit: "s@vodafone.c"
> Jun 2 21:37:37.885 [50826] dbg: rules: ran body rule __NONEMPTY_BODY
> ======> got hit: "R"
> Jun 2 21:37:43.231 [50826] dbg: rules: ran body rule __HUSH_HUSH
> ======> got hit: "confidential"
> Jun 2 21:37:44.008 [50826] dbg: rules: running uri tests; score so
> far=0
> [...]
> Jun 2 21:37:45.723 [50826] dbg: learn: initializing learner
> Jun 2 21:37:45.789 [50826] dbg: check: is spam? score=0.012 required=5
> Jun 2 21:37:45.790 [50826] dbg: check:
> tests=HTML_FONT_SIZE_LARGE,HTML_MESSAGE,T_FILL_THIS_FORM
> Jun 2 21:37:45.791 [50826] dbg: check:
> subtests=__ANY_TEXT_ATTACH,__ANY_TEXT_ATTACH_DOC,__COMMENT_EXISTS,__CT,_
> _CTYPE_HAS_BOUNDARY,__CTYPE_MULTIPART_ALT,__CTYPE_MULTIPART_ANY,__DKIM_D
> EPENDABLE,__DOS_BODY_FRI,__DOS_BODY_THU,__DOS_BODY_TUE,__DOS_HAS_ANY_URI
> ,__DOS_RCVD_WED,__DOS_REF_2_WK_DAYS,__DOS_REF_NEXT_WK_DAY,__DOS_RELAYED_
> EXT,__FILL_THIS_FORM_PARTIAL,__FILL_THIS_FORM_PARTIAL,__FILL_THIS_FORM_P
> ARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__F
> ILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_
> PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__
> HAS_ANY_EMAIL,__HAS_ANY_URI,__HAS_DATE,__HAS_MESSAGE_ID,__HAS_MIMEOLE,__
> HAS_MSGID,__HAS_RCVD,__HAS_SUBJECT,__HS_SUBJ_RE_FW,__HUSH_HUSH,__IMS_MSG
> ID,__IS_EXCH,__LAST_EXTERNAL_RELAY_NO_AUTH,__LAST_UNTRUSTED_RELAY_NO_AUT
> H,__MIME_HTML,__MIME_QP,__MIME_VERSION,__NONEMPTY_BODY,__PLS_REVIEW,__RC
> VD_IN_2WEEKS,__SANE_MSGID,__SUBJ_RE,__SUBSCRIPTION_INFO,__TAG_EXISTS_BOD
> Y,__TAG_EXISTS_HEAD,__TAG_EXISTS_HTML,__TAG_EXISTS_META,__TOCC_EXISTS,__
> TVD_MIME_ATT_TP,__YOU_ASSIST
> Jun 2 21:37:45.793 [50826] dbg: timing: total 36840 ms - init: 3827
> (10.4%), parse: 43 (0.1%), extract_message_metadata: 822 (2.2%),
> get_uri_detail_list: 178 (0.5%), tests_pri_-1000: 212 (0.6%),
> compile_gen: 538 (1.5%), compile_eval: 79 (0.2%), tests_pri_-950: 52
> (0.1%), tests_pri_-900: 35 (0.1%), tests_pri_-400: 392 (1.1%),
> check_bayes: 359 (1.0%), tests_pri_0: 30780 (83.6%), dkim_load_modules:
> 99 (0.3%), check_dkim_signature: 20 (0.1%), check_dkim_adsp: 13 (0.0%),
> check_spf: 81 (0.2%), poll_dns_idle: 0.57 (0.0%), check_dcc: 240
> (0.7%), check_pyzor: 2 (0.0%), tests_pri_500: 258 (0.7%),
> tests_pri_1000: 61 (0.2%), total_awl: 28 (0.1%), check_awl: 6 (0.0%),
> update_awl: 4 (0.0%), learn: 118 (0.3%)
> [/var/amavis/tmp]#
>
> So the body tests take ~ 30 of 37 seconds. It's not a load problem,
> under load it takes >2 minutes and it is reproducable with certain
> mails only.
>
> Any idea where to start?
>
> Thanks, Helmut
>
> --
> No Swen today, my love has gone away
> My mailbox stands for lorn, a symbol of the dawn
>
>
are you escaping the white spaces and @?
Re: Performance problem body tests
Posted by Benny Pedersen <me...@junc.org>.
On Wed 02 Jun 2010 09:52:51 PM CEST, Helmut Schneider wrote
> Hi,
>
> with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
> problem:
>
> [/var/amavis/tmp]# spamassassin -D -lint <
doh :)
- != --
> /var/amavis/tmp/amavis-20100602T192227-44802/email.txt
> Jun 2 21:37:08.809 [50826] warn: The -l option has been deprecated and
> is no longer supported, ignoring.
big hint imho
> Jun 2 21:37:08.810 [50826] dbg: logger: adding facilities: all
> Jun 2 21:37:08.811 [50826] dbg: logger: logging level is DBG
> Jun 2 21:37:08.811 [50826] dbg: generic: SpamAssassin version 3.3.1
> Jun 2 21:37:08.812 [50826] dbg: generic: Perl 5.010001,
> PREFIX=/usr/local, DEF_RULES_DIR=/usr/local/share/spamassassin,
> LOCAL_RULES_DIR=/usr/local/etc/mail/spamassassin,
> LOCAL_STATE_DIR=/var/db/spamassassin
> [...]
> Jun 2 21:37:15.626 [50826] dbg: rules: run_generic_tests - compiling
> eval code: body, priority 0
> Jun 2 21:37:15.627 [50826] dbg: rules: compiled body tests
> Jun 2 21:37:20.524 [50826] dbg: rules: ran body rule __DOS_BODY_THU
> ======> got hit: "Thursday"
> Jun 2 21:37:22.444 [50826] dbg: rules: ran body rule __YOU_ASSIST
> ======> got hit: "your assistance"
> Jun 2 21:37:26.018 [50826] dbg: rules: ran body rule
> __FILL_THIS_FORM_PARTIAL ======> got hit: "Tel : "
> Jun 2 21:37:26.042 [50826] dbg: rules: ran body rule
> __FILL_THIS_FORM_PARTIAL ======> got hit: "Tel : "
> Jun 2 21:37:26.424 [50826] dbg: rules: ran body rule __DOS_BODY_TUE
> ======> got hit: "Tuesday"
> Jun 2 21:37:27.410 [50826] dbg: rules: ran body rule __PLS_REVIEW
> ======> got hit: "Please see attached"
> Jun 2 21:37:33.503 [50826] dbg: rules: ran body rule __DOS_BODY_FRI
> ======> got hit: "Friday"
> Jun 2 21:37:37.334 [50826] dbg: rules: ran body rule
> __SUBSCRIPTION_INFO ======> got hit: "Register"
> Jun 2 21:37:37.409 [50826] dbg: rules: ran body rule __HAS_ANY_EMAIL
> ======> got hit: "s@vodafone.c"
> Jun 2 21:37:37.885 [50826] dbg: rules: ran body rule __NONEMPTY_BODY
> ======> got hit: "R"
> Jun 2 21:37:43.231 [50826] dbg: rules: ran body rule __HUSH_HUSH
> ======> got hit: "confidential"
> Jun 2 21:37:44.008 [50826] dbg: rules: running uri tests; score so
> far=0
> [...]
> Jun 2 21:37:45.723 [50826] dbg: learn: initializing learner
> Jun 2 21:37:45.789 [50826] dbg: check: is spam? score=0.012 required=5
> Jun 2 21:37:45.790 [50826] dbg: check:
> tests=HTML_FONT_SIZE_LARGE,HTML_MESSAGE,T_FILL_THIS_FORM
> Jun 2 21:37:45.791 [50826] dbg: check:
> subtests=__ANY_TEXT_ATTACH,__ANY_TEXT_ATTACH_DOC,__COMMENT_EXISTS,__CT,_
> _CTYPE_HAS_BOUNDARY,__CTYPE_MULTIPART_ALT,__CTYPE_MULTIPART_ANY,__DKIM_D
> EPENDABLE,__DOS_BODY_FRI,__DOS_BODY_THU,__DOS_BODY_TUE,__DOS_HAS_ANY_URI
> ,__DOS_RCVD_WED,__DOS_REF_2_WK_DAYS,__DOS_REF_NEXT_WK_DAY,__DOS_RELAYED_
> EXT,__FILL_THIS_FORM_PARTIAL,__FILL_THIS_FORM_PARTIAL,__FILL_THIS_FORM_P
> ARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__F
> ILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_
> PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__FILL_THIS_FORM_PARTIAL_RAW,__
> HAS_ANY_EMAIL,__HAS_ANY_URI,__HAS_DATE,__HAS_MESSAGE_ID,__HAS_MIMEOLE,__
> HAS_MSGID,__HAS_RCVD,__HAS_SUBJECT,__HS_SUBJ_RE_FW,__HUSH_HUSH,__IMS_MSG
> ID,__IS_EXCH,__LAST_EXTERNAL_RELAY_NO_AUTH,__LAST_UNTRUSTED_RELAY_NO_AUT
> H,__MIME_HTML,__MIME_QP,__MIME_VERSION,__NONEMPTY_BODY,__PLS_REVIEW,__RC
> VD_IN_2WEEKS,__SANE_MSGID,__SUBJ_RE,__SUBSCRIPTION_INFO,__TAG_EXISTS_BOD
> Y,__TAG_EXISTS_HEAD,__TAG_EXISTS_HTML,__TAG_EXISTS_META,__TOCC_EXISTS,__
> TVD_MIME_ATT_TP,__YOU_ASSIST
> Jun 2 21:37:45.793 [50826] dbg: timing: total 36840 ms - init: 3827
> (10.4%), parse: 43 (0.1%), extract_message_metadata: 822 (2.2%),
> get_uri_detail_list: 178 (0.5%), tests_pri_-1000: 212 (0.6%),
> compile_gen: 538 (1.5%), compile_eval: 79 (0.2%), tests_pri_-950: 52
> (0.1%), tests_pri_-900: 35 (0.1%), tests_pri_-400: 392 (1.1%),
> check_bayes: 359 (1.0%), tests_pri_0: 30780 (83.6%), dkim_load_modules:
> 99 (0.3%), check_dkim_signature: 20 (0.1%), check_dkim_adsp: 13 (0.0%),
> check_spf: 81 (0.2%), poll_dns_idle: 0.57 (0.0%), check_dcc: 240
> (0.7%), check_pyzor: 2 (0.0%), tests_pri_500: 258 (0.7%),
> tests_pri_1000: 61 (0.2%), total_awl: 28 (0.1%), check_awl: 6 (0.0%),
> update_awl: 4 (0.0%), learn: 118 (0.3%)
> [/var/amavis/tmp]#
>
> So the body tests take ~ 30 of 37 seconds. It's not a load problem,
> under load it takes >2 minutes and it is reproducable with certain
> mails only.
>
> Any idea where to start?
remove non std rules, use sa-compile (remember extra plugin)
--
xpoint http://www.unicom.com/pw/reply-to-harmful.html
Re: [sa] Performance problem body tests
Posted by Helmut Schneider <ju...@gmx.de>.
Charles Gregory wrote:
> On Wed, 2 Jun 2010, Helmut Schneider wrote:
> > with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
> > problem:
>
> What distinguishes 'certain mails'? Length? Content? Mime
> attachements?
It's around 1 of 1000, I caught one that was a HTML mail, 100kB, no
MIME attachments. But that one reliable, I can reproduce that problem
on all (4) of my installations. Unfortunately it's a company internal
legal mail so I can't share.
> > So the body tests take ~ 30 of 37 seconds. It's not a load problem,
>
> I noticed a significant increase in processing time when I upgraded
> from 3.2 to 3.3..... but it was pretty much for all messages.....
>
> You might want to raise the level of debugging
How?
--
No Swen today, my love has gone away
My mailbox stands for lorn, a symbol of the dawn
Re: [sa] Performance problem body tests
Posted by Charles Gregory <cg...@hwcn.org>.
On Wed, 2 Jun 2010, Helmut Schneider wrote:
> with certain mails on FreeBSD 8.0 and SA 3.3.1 I have a performance
> problem:
What distinguishes 'certain mails'? Length? Content? Mime attachements?
> So the body tests take ~ 30 of 37 seconds. It's not a load problem,
I noticed a significant increase in processing time when I upgraded from
3.2 to 3.3..... but it was pretty much for all messages.....
You might want to raise the level of debugging so that you see the test
which did NOT match, so that you can truly assess how long each body rule
takes to process. Your logs show 6 second 'gaps' but they may have just
been filled with non-hitting rule tests....
- C