I'm running spamassassin 3.4.0 on CentOS 7, being in the process of
migrating from an old SA 3.3.1 on CentOS 5 server. I am running
tests etc before moving over at the moment to make sure all is
working OK. Both servers are VMs on the same host, which is not
highly loaded at all, and each VM has plenty of RAM.
I sent the same email through the two postfix servers, each of which
is then running amavisd-new, calling spamassassin.
On the old server, the SA process takes about 600ms. Worst case
looking though the logs it's about 1500ms.
On the new server, the identical email takes about 4000ms.
On each server it is tests_pri_0 that takes the majority of the
time, which I understand from reading is to be expected. Is the
extended duration to be expected with newer SA, or do I need to be
digging deeper to try and find out why it's so much slower?
Simon
--
Simon Wilson
M: 0400 12 11 16
I've run sa-compile to see if that helps, DNS is locally setup on the
mail server as a caching nameserver, forwarding queries it cannot
answer to a separate BIND DNS server on another local (same host) VM,
which is set up to resolve directly (i.e. no forwarders to ISP or
Google, etc.).
This is a fairly typical message with duration:
May 1 13:39:33 emp07 amavis[9437]: (09437-03) TIMING-SA total 3667 ms
- parse: 1.30 (0.0%), extract_message_metadata: 22 (0.6%),
get_uri_detail_list: 2.6 (0.1%), tests_pri_-1000: 16 (0.4%),
tests_pri_-950: 1.14 (0.0%), tests_pri_-900: 1.19 (0.0%),
tests_pri_-400: 23 (0.6%), check_bayes: 22 (0.6%), b_tokenize: 8
(0.2%), b_tok_get_all: 6 (0.2%), b_comp_prob: 4.6 (0.1%),
b_tok_touch_all: 0.36 (0.0%), b_finish: 0.48 (0.0%), tests_pri_0: 2289
(62.4%), check_dkim_adsp: 6 (0.2%), check_spf: 4.6 (0.1%),
poll_dns_idle: 1270 (34.6%), check_razor2: 2128 (58.0%), check_pyzor:
0.16 (0.0%), tests_pri_500: 1298 (35.4%), get_report: 0.56 (0.0%)
The long ones are:
tests_pri_0: 2289
poll_dns_idle: 1270
check_razor2: 2128
tests_pri_500: 1298
Although with a total time of 3667ms I assume some of those are
concurrently running.
Another email:
May 1 13:41:42 emp07 amavis[9435]: (09435-03) TIMING-SA total 3863 ms
- parse: 1.06 (0.0%), extract_message_metadata: 15 (0.4%),
get_uri_detail_list: 1.45 (0.0%), tests_pri_-1000: 30 (0.8%),
tests_pri_-950: 1.08 (0.0%), tests_pri_-900: 1.13 (0.0%),
tests_pri_-400: 19 (0.5%), check_bayes: 17 (0.5%), b_tokenize: 6
(0.2%), b_tok_get_all: 4.9 (0.1%), b_comp_prob: 3.9 (0.1%),
b_tok_touch_all: 0.33 (0.0%), b_finish: 0.50 (0.0%), tests_pri_0: 1552
(40.2%), check_dkim_adsp: 6 (0.2%), check_spf: 616 (16.0%),
poll_dns_idle: 2796 (72.4%), check_razor2: 858 (22.2%), check_pyzor:
0.17 (0.0%), tests_pri_500: 2229 (57.7%), get_report: 0.54 (0.0%)
tests_pri_0: 1552
poll_dns_idle: 2796
check_razor2: 858
tests_pri_500: 2229
It looks like some of the DNS checks are taking too long. Given the
DNS is local (and fast, I've checked it, and it is working fine).
I'll see if I can work out why some DNS checks are taking so long.
Simon
--
Simon Wilson
M: 0400 12 11 16
