You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by "Daniel J. Luke" <dl...@geeklair.net> on 2016/03/24 17:10:09 UTC
spamd running much slower than spamassassin?
I recently noticed that spamd was running /much/ slower than usual.
With a test message:
/usr/bin/time spamassassin < spam.msg
7.92 real 1.85 user 0.13 sys
/usr/bin/time spamc -U /var/run/spamd.sock < spam.msg
126.44 real 0.00 user 0.00 sys
spamassassin -D timing < spam.msg
Mar 24 12:02:54.767 [79829] dbg: timing: total 7030 ms - init: 1003 (14.3%), b_tie_ro: 10 (0.1%), parse: 2.3 (0.0%), extract_message_metadata: 59 (0.8%), get_uri_detail_list: 7 (0.1%), tests_pri_-1000: 39 (0.5%), compile_gen: 111 (1.6%), compile_eval: 25 (0.4%), tests_pri_-950: 2.2 (0.0%), tests_pri_-900: 2.8 (0.0%), tests_pri_-400: 80 (1.1%), check_bayes: 76 (1.1%), b_tokenize: 13 (0.2%), b_tok_get_all: 12 (0.2%), b_comp_prob: 2.3 (0.0%), b_tok_touch_all: 47 (0.7%), b_finish: 1.00 (0.0%), tests_pri_0: 5770 (82.1%), check_spf: 49 (0.7%), poll_dns_idle: 0.03 (0.0%), dkim_load_modules: 20 (0.3%), check_dkim_signature: 1.30 (0.0%), check_dkim_adsp: 3.5 (0.1%), check_dcc: 150 (2.1%), check_razor2: 5012 (71.3%), check_pyzor: 271 (3.9%), tests_pri_500: 50 (0.7%), tests_pri_1000: 14 (0.2%), total_txrep: 11 (0.2%), check_txrep_msg_id: 2.2 (0.0%), update_txrep_msg_id: 0.02 (0.0%)
spamd running with -D timing - spamc -U /var/run/spamd.sock < spam.msg
Mar 24 12:06:17 lintilla spamd[79885]: timing: total 130906 ms - read_scoreonly_config: 444 (0.3%), signal_user_changed: 12 (0.0%), b_tie_ro: 9 (0.0%), parse: 3.0 (0.0%), extract_message_metadata: 60281 (46.0%), get_uri_detail_list: 5.0 (0.0%), tests_pri_-1000: 38 (0.0%), compile_gen: 28 (0.0%), compile_eval: 27 (0.0%), tests_pri_-950: 1.32 (0.0%), tests_pri_-900: 1.73 (0.0%), tests_pri_-400: 90 (0.1%), check_bayes: 79 (0.1%), b_tokenize: 13 (0.0%), b_tok_get_all: 12 (0.0%), b_comp_prob: 2.6 (0.0%), b_tok_touch_all: 49 (0.0%), b_finish: 1.04 (0.0%), tests_pri_0: 69951 (53.4%), check_dkim_signature: 1.71 (0.0%), check_dkim_adsp: 60184 (46.0%), check_spf: 240 (0.2%), poll_dns_idle: 215 (0.2%), check_dcc: 4325 (3.3%), check_razor2: 5004 (3.8%), check_pyzor: 0.25 (0.0%), tests_pri_500: 6 (0.0%), tests_pri_1000: 12 (0.0%), total_txrep: 10 (0.0%), check_txrep_msg_id: 2.3 (0.0%), update_txrep_msg_id: 0.02 (0.0%), rewrite_mail: 1.12 (0.0%), copy_config: 41 (0.0%)
So, I guess extract_message_metadata and check_dkim_adsp are causing the problem when running under spamd - but I'm not sure why that would be / where I should look next to troubleshoot and fix.
--
Daniel J. Luke
Re: spamd running much slower than spamassassin?
Posted by "Daniel J. Luke" <dl...@geeklair.net>.
On Mar 29, 2016, at 10:41 AM, Daniel J. Luke <dl...@geeklair.net> wrote:
> On Mar 28, 2016, at 8:57 PM, Bill Cole <sa...@billmail.scconsult.com> wrote:
>> On 28 Mar 2016, at 14:42, Daniel J. Luke wrote:
>>> On Mar 24, 2016, at 12:10 PM, Daniel J. Luke <dl...@geeklair.net> wrote:
>>>> /usr/bin/time spamassassin < spam.msg
>>>> 7.92 real 1.85 user 0.13 sys
>>>>
>>>> /usr/bin/time spamc -U /var/run/spamd.sock < spam.msg
>>>> 126.44 real 0.00 user 0.00 sys
>>>
>>> well, it looks like it's DNS related, somehow.
>>
>> The 2 minute pause had me thinking that, but nothing jumped out as a specific explanation and nothing yet does...
>>
>>> I'm still confused as to why 'spamassassin' doesn't have a problem but 'spamd' does. I'm running SA 3.4.1 with perl5.22.1. I've tried both downgrading Net::DNS to 0.83 and upgrading it to 1.05_2
>>>
>>> Any thoughts would be appreciated.
>>
>> You haven't mentioned your platform, that I've seen, but it may be relevant, e.g. historically FreeBSD jails can't do real loopback (not sure on 10.2...) EL6/7 derivatives have SELinux on by default, etc...
>>
>> So: more clues please?
>
> Sorry, this is a Mac OS X 10.11.4 system, perl5.22.1 is self-built (perlbrew). I'm not sure exactly when this started, I noticed it after I upgraded to 10.11.4 from 10.11.3, but it may have been happening before. What else would be helpful to know?
OK, I figured this out (using fs_usage -f network <pid>), I traced this down to spamd waiting on mDNSResponder. Turning up mDNSResponder logging gave me the answer that it was 'unhappy' with ::1 as a resolver address for some reason.
Setting this up so only '127.0.0.1' is used instead makes spamd work like normal again.
I /think/ this is regression in 10.11.4, but as I said before, I'm not entirely sure (I only noticed things were slow after the upgrade, they could have been slow for a little while before).
--
Daniel J. Luke
Re: spamd running much slower than spamassassin?
Posted by "Daniel J. Luke" <dl...@geeklair.net>.
On Mar 28, 2016, at 8:57 PM, Bill Cole <sa...@billmail.scconsult.com> wrote:
> On 28 Mar 2016, at 14:42, Daniel J. Luke wrote:
>> On Mar 24, 2016, at 12:10 PM, Daniel J. Luke <dl...@geeklair.net> wrote:
>>> /usr/bin/time spamassassin < spam.msg
>>> 7.92 real 1.85 user 0.13 sys
>>>
>>> /usr/bin/time spamc -U /var/run/spamd.sock < spam.msg
>>> 126.44 real 0.00 user 0.00 sys
>>
>> well, it looks like it's DNS related, somehow.
>
> The 2 minute pause had me thinking that, but nothing jumped out as a specific explanation and nothing yet does...
>
>> I'm still confused as to why 'spamassassin' doesn't have a problem but 'spamd' does. I'm running SA 3.4.1 with perl5.22.1. I've tried both downgrading Net::DNS to 0.83 and upgrading it to 1.05_2
>>
>> Any thoughts would be appreciated.
>
> You haven't mentioned your platform, that I've seen, but it may be relevant, e.g. historically FreeBSD jails can't do real loopback (not sure on 10.2...) EL6/7 derivatives have SELinux on by default, etc...
>
> So: more clues please?
Sorry, this is a Mac OS X 10.11.4 system, perl5.22.1 is self-built (perlbrew). I'm not sure exactly when this started, I noticed it after I upgraded to 10.11.4 from 10.11.3, but it may have been happening before. What else would be helpful to know?
--
Daniel J. Luke
Re: spamd running much slower than spamassassin?
Posted by Bill Cole <sa...@billmail.scconsult.com>.
On 28 Mar 2016, at 14:42, Daniel J. Luke wrote:
> On Mar 24, 2016, at 12:10 PM, Daniel J. Luke <dl...@geeklair.net>
> wrote:
>> /usr/bin/time spamassassin < spam.msg
>> 7.92 real 1.85 user 0.13 sys
>>
>> /usr/bin/time spamc -U /var/run/spamd.sock < spam.msg
>> 126.44 real 0.00 user 0.00 sys
>
> well, it looks like it's DNS related, somehow.
The 2 minute pause had me thinking that, but nothing jumped out as a
specific explanation and nothing yet does...
> I'm still confused as to why 'spamassassin' doesn't have a problem but
> 'spamd' does. I'm running SA 3.4.1 with perl5.22.1. I've tried both
> downgrading Net::DNS to 0.83 and upgrading it to 1.05_2
>
> Any thoughts would be appreciated.
You haven't mentioned your platform, that I've seen, but it may be
relevant, e.g. historically FreeBSD jails can't do real loopback (not
sure on 10.2...) EL6/7 derivatives have SELinux on by default, etc...
So: more clues please?
Re: spamd running much slower than spamassassin?
Posted by "Daniel J. Luke" <dl...@geeklair.net>.
On Mar 24, 2016, at 12:10 PM, Daniel J. Luke <dl...@geeklair.net> wrote:
> /usr/bin/time spamassassin < spam.msg
> 7.92 real 1.85 user 0.13 sys
>
> /usr/bin/time spamc -U /var/run/spamd.sock < spam.msg
> 126.44 real 0.00 user 0.00 sys
well, it looks like it's DNS related, somehow. The first (and longest) pause is between these two log messages (spamd -D):
Mar 28 13:53:47 lintilla spamd[1532]: dns: LocalAddr: [0.0.0.0]:48704, name server: [127.0.0.1]:53, module IO::Socket::IP
Mar 28 13:54:48 lintilla spamd[1532]: dns: resolver socket rx buffer size is 196724 bytes, local port 48704
The second pause is during the adsp lookup.
On the box, I'm running unbound (listening on 127.0.0.1 and ::1). It's the only nameserver available in /etc/resolv.conf and I've tried both with and without setting dns_server in my local.cf
I'm still confused as to why 'spamassassin' doesn't have a problem but 'spamd' does. I'm running SA 3.4.1 with perl5.22.1. I've tried both downgrading Net::DNS to 0.83 and upgrading it to 1.05_2
Any thoughts would be appreciated.
--
Daniel J. Luke