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.
<snip>
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.
<snip>
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:
<snip>
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.
<snip>
I ran the same email on both servers through spamassassin manually,
and got very different results. Total time to process on the old
server was 1.6s, on the new one it took 3.0s, although not as dramatic
as some tests, some others took longer.
The spamhaus checks are taking a lot longer, Using tests on
108.199.251.205 as an example:
OLD SERVER - dbg: async: timing: 0.351 .
DNSBL:zen.spamhaus.org.:108.199.251.205
NEW SERVER - dbg: async: timing: 1.494 .
DNSBL:108.199.251.205:zen.spamhaus.org
Digging in some more, searching on that IP address in the output:
Old server:
May 1 14:40:36.897 [14560] dbg: async: starting: URI-DNSBL,
DNSBL:zen.spamhaus.org.:108.199.251.205 (timeout 15.0s, min 3.0s)
May 1 14:40:37.249 [14560] dbg: async: completed in 0.351 s:
URI-DNSBL, DNSBL:zen.spamhaus.org.:108.199.251.205
May 1 14:40:37.271 [14560] dbg: async: timing: 0.351 .
DNSBL:zen.spamhaus.org.:108.199.251.205
The new one is doing a URIBL-SBL check as well as the URI-DNSBL and
DNSBL checks the old server does.
May 1 14:32:51.610 [21742] dbg: async: launching
A/108.199.251.205.sbl.spamhaus.org for
DNSBL:108.199.251.205:sbl.spamhaus.org
May 1 14:32:51.611 [21742] dbg: async: starting: URIBL_SBL_A,
URI-DNSBL, DNSBL:108.199.251.205:sbl.spamhaus.org (timeout 15.0s, min
3.0s)
May 1 14:32:51.611 [21742] dbg: async: launching
A/108.199.251.205.zen.spamhaus.org for
DNSBL:108.199.251.205:zen.spamhaus.org
May 1 14:32:51.612 [21742] dbg: async: starting: URIBL_SBL,
URI-DNSBL, DNSBL:108.199.251.205:zen.spamhaus.org (timeout 15.0s, min
3.0s)
May 1 14:32:53.107 [21742] dbg: async: calling callback on key
DNSBL:108.199.251.205:zen.spamhaus.org, rule URIBL_SBL
May 1 14:32:53.108 [21742] dbg: async: calling callback on key
DNSBL:108.199.251.205:sbl.spamhaus.org, rule URIBL_SBL_A
May 1 14:32:53.109 [21742] dbg: async: completed in 1.494 s:
URIBL_SBL, URI-DNSBL, DNSBL:108.199.251.205:zen.spamhaus.org
May 1 14:32:53.110 [21742] dbg: async: completed in 1.497 s:
URIBL_SBL_A, URI-DNSBL, DNSBL:108.199.251.205:sbl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.494 .
DNSBL:108.199.251.205:zen.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.497 .
DNSBL:108.199.251.205:sbl.spamhaus.org
It appears the new server is running additional checks [URIBL_SBL_A,
URI-DNSBL, DNSBL] as opposed to [URI-DNSBL, DNSBL] - but is taking a
LOT longer to complete them.
Complete timing results are below.
Is this just how long it takes now, or is there any tweaking I can be doing?
Simon
******
Full DNS timings
Old server
May 1 14:40:37.266 [14560] dbg: async: timing: 0.010 .
dns:A:us-west-2.amazonses.com
May 1 14:40:37.266 [14560] dbg: async: timing: 0.010 .
dns:A:67.27.240.54.iadb.isipp.com.
May 1 14:40:37.266 [14560] dbg: async: timing: 0.010 .
dns:MX:us-west-2.amazonses.com
May 1 14:40:37.267 [14560] dbg: async: timing: 0.011 .
dns:A:67.27.240.54.dnsbl.sorbs.net.
May 1 14:40:37.267 [14560] dbg: async: timing: 0.013 .
dns:A:67.27.240.54.list.dnswl.org.
May 1 14:40:37.267 [14560] dbg: async: timing: 0.013 .
dns:A:67.27.240.54.psbl.surriel.com.
May 1 14:40:37.267 [14560] dbg: async: timing: 0.015 .
dns:A:67.27.240.54.bl.score.senderscore.com.
May 1 14:40:37.267 [14560] dbg: async: timing: 0.016 . NS:flexischools.com.au
May 1 14:40:37.267 [14560] dbg: async: timing: 0.017 .
DNSBL:dob.sibl.support-intelligence.net:flexischools.com.au
May 1 14:40:37.267 [14560] dbg: async: timing: 0.018 . NS:amazonses.com
May 1 14:40:37.267 [14560] dbg: async: timing: 0.018 .
DNSBL:multi.surbl.org.:flexischools.com.au
May 1 14:40:37.268 [14560] dbg: async: timing: 0.019 .
DNSBL:dob.sibl.support-intelligence.net:amazonses.com
May 1 14:40:37.268 [14560] dbg: async: timing: 0.019 .
DNSBL:multi.surbl.org.:amazonses.com
May 1 14:40:37.268 [14560] dbg: async: timing: 0.103 . A:ns1.p31.dynect.net.
May 1 14:40:37.268 [14560] dbg: async: timing: 0.104 . A:pdns4.ultradns.org.
May 1 14:40:37.268 [14560] dbg: async: timing: 0.105 . A:pdns1.ultradns.net.
May 1 14:40:37.268 [14560] dbg: async: timing: 0.105 . A:pdns2.ultradns.net.
May 1 14:40:37.269 [14560] dbg: async: timing: 0.105 . A:ns4.p31.dynect.net.
May 1 14:40:37.269 [14560] dbg: async: timing: 0.106 .
A:pdns6.ultradns.co.uk.
May 1 14:40:37.269 [14560] dbg: async: timing: 0.106 . A:ns3.p31.dynect.net.
May 1 14:40:37.269 [14560] dbg: async: timing: 0.106 . A:pdns3.ultradns.org.
May 1 14:40:37.269 [14560] dbg: async: timing: 0.107 .
A:ns-1900.awsdns-45.co.uk.
May 1 14:40:37.269 [14560] dbg: async: timing: 0.107 .
A:ns-1222.awsdns-24.org.
May 1 14:40:37.269 [14560] dbg: async: timing: 0.107 . A:ns2.p31.dynect.net.
May 1 14:40:37.270 [14560] dbg: async: timing: 0.107 .
A:ns-897.awsdns-48.net.
May 1 14:40:37.270 [14560] dbg: async: timing: 0.107 . A:ns-19.awsdns-02.com.
May 1 14:40:37.270 [14560] dbg: async: timing: 0.107 . A:pdns5.ultradns.info.
May 1 14:40:37.270 [14560] dbg: async: timing: 0.143 .
DNSBL:multi.uribl.com.:flexischools.com.au
May 1 14:40:37.270 [14560] dbg: async: timing: 0.147 .
DNSBL:multi.uribl.com.:amazonses.com
May 1 14:40:37.270 [14560] dbg: async: timing: 0.336 .
dns:TXT:67.27.240.54.bl.spamcop.net.
May 1 14:40:37.270 [14560] dbg: async: timing: 0.338 .
dns:A:67.27.240.54.bb.barracudacentral.org.
May 1 14:40:37.271 [14560] dbg: async: timing: 0.346 .
DNSBL:zen.spamhaus.org.:31.71.78.208
May 1 14:40:37.271 [14560] dbg: async: timing: 0.347 .
DNSBL:zen.spamhaus.org.:1.69.7.199
May 1 14:40:37.271 [14560] dbg: async: timing: 0.347 .
DNSBL:zen.spamhaus.org.:1.115.74.204
May 1 14:40:37.271 [14560] dbg: async: timing: 0.348 .
DNSBL:zen.spamhaus.org.:1.114.74.204
May 1 14:40:37.271 [14560] dbg: async: timing: 0.350 .
DNSBL:zen.spamhaus.org.:31.70.78.208
May 1 14:40:37.271 [14560] dbg: async: timing: 0.351 .
DNSBL:zen.spamhaus.org.:1.109.74.204
May 1 14:40:37.271 [14560] dbg: async: timing: 0.351 .
DNSBL:zen.spamhaus.org.:108.199.251.205
May 1 14:40:37.272 [14560] dbg: async: timing: 0.352 .
DNSBL:zen.spamhaus.org.:1.108.74.204
May 1 14:40:37.272 [14560] dbg: async: timing: 0.353 .
DNSBL:zen.spamhaus.org.:31.250.13.204
May 1 14:40:37.272 [14560] dbg: async: timing: 0.353 .
DNSBL:zen.spamhaus.org.:198.196.251.205
May 1 14:40:37.272 [14560] dbg: async: timing: 0.353 .
DNSBL:zen.spamhaus.org.:1.68.7.199
May 1 14:40:37.272 [14560] dbg: async: timing: 0.354 .
DNSBL:zen.spamhaus.org.:129.195.251.205
May 1 14:40:37.272 [14560] dbg: async: timing: 0.355 .
DNSBL:zen.spamhaus.org.:19.192.251.205
May 1 14:40:37.272 [14560] dbg: async: timing: 0.355 .
DNSBL:zen.spamhaus.org.:31.251.13.204
May 1 14:40:37.272 [14560] dbg: async: timing: 0.370 .
dns:TXT:67.27.240.54.sa-accredit.habeas.com.
May 1 14:40:37.273 [14560] dbg: async: timing: 0.372 .
dns:TXT:67.27.240.54.sa-trusted.bondedsender.org.
May 1 14:40:37.273 [14560] dbg: async: timing: 0.377 .
dns:A:67.27.240.54.zen.spamhaus.org.
May 1 14:40:37.273 [14560] dbg: async: timing: 0.379 .
DNSBL:dbl.spamhaus.org.:flexischools.com.au
May 1 14:40:37.273 [14560] dbg: async: timing: 0.382 .
DNSBL:dbl.spamhaus.org.:amazonses.com
New server
May 1 14:32:53.111 [21742] dbg: async: timing: 0.004 .
DNSBL:102.119.65.52:zen.spamhaus.org
May 1 14:32:53.111 [21742] dbg: async: timing: 0.009 . A:ns-19.awsdns-02.com
May 1 14:32:53.111 [21742] dbg: async: timing: 0.010 . A:ns-897.awsdns-48.net
May 1 14:32:53.111 [21742] dbg: async: timing: 0.012 .
A:ns-1222.awsdns-24.org
May 1 14:32:53.111 [21742] dbg: async: timing: 0.013 .
A:ns-1900.awsdns-45.co.uk
May 1 14:32:53.111 [21742] dbg: async: timing: 0.017 .
dns:A:67.27.240.54.iadb.isipp.com
May 1 14:32:53.111 [21742] dbg: async: timing: 0.020 .
dns:A:67.27.240.54.list.dnswl.org
May 1 14:32:53.111 [21742] dbg: async: timing: 0.020 .
dns:A:67.27.240.54.psbl.surriel.com
May 1 14:32:53.111 [21742] dbg: async: timing: 0.021 .
dns:A:67.27.240.54.bl.score.senderscore.com
May 1 14:32:53.111 [21742] dbg: async: timing: 0.022 .
dns:A:67.27.240.54.dnsbl.sorbs.net
May 1 14:32:53.112 [21742] dbg: async: timing: 0.022 .
DNSBL:flexischools.com.au:multi.surbl.org
May 1 14:32:53.112 [21742] dbg: async: timing: 0.022 .
dns:A:us-west-2.amazonses.com
May 1 14:32:53.112 [21742] dbg: async: timing: 0.022 . NS:flexischools.com.au
May 1 14:32:53.112 [21742] dbg: async: timing: 0.022 .
dns:MX:us-west-2.amazonses.com
May 1 14:32:53.112 [21742] dbg: async: timing: 0.024 .
askdns:TXT:flexischools.com.au._vouch.dwl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 0.024 .
askdns:TXT:amazonses.com._vouch.dwl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 0.025 .
DNSBL:flexischools.com.au:dob.sibl.support-intelligence.net
May 1 14:32:53.112 [21742] dbg: async: timing: 0.270 .
A:www.flexischools.com.au
May 1 14:32:53.112 [21742] dbg: async: timing: 0.271 . A:flexischools.com.au
May 1 14:32:53.112 [21742] dbg: async: timing: 0.357 .
dns:TXT:67.27.240.54.sa-accredit.habeas.com
May 1 14:32:53.112 [21742] dbg: async: timing: 0.357 .
dns:TXT:67.27.240.54.sa-trusted.bondedsender.org
May 1 14:32:53.112 [21742] dbg: async: timing: 0.359 .
dns:A:67.27.240.54.bb.barracudacentral.org
May 1 14:32:53.112 [21742] dbg: async: timing: 0.362 .
dns:A:67.27.240.54.wl.mailspike.net
May 1 14:32:53.112 [21742] dbg: async: timing: 0.368 .
dns:A:67.27.240.54.zen.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 0.374 .
DNSBL:flexischools.com.au:multi.uribl.com
May 1 14:32:53.112 [21742] dbg: async: timing: 0.375 .
DNSBL:flexischools.com.au:dbl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.267 .
DNSBL:102.119.65.52:sbl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.494 .
DNSBL:108.199.251.205:zen.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.496 .
DNSBL:198.196.251.205:zen.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.496 .
DNSBL:198.196.251.205:sbl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.497 .
DNSBL:108.199.251.205:sbl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.497 .
DNSBL:129.195.251.205:zen.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.497 .
DNSBL:129.195.251.205:sbl.spamhaus.org
May 1 14:32:53.112 [21742] dbg: async: timing: 1.498 .
DNSBL:19.192.251.205:sbl.spamhaus.org
May 1 14:32:53.113 [21742] dbg: async: timing: 1.502 .
DNSBL:19.192.251.205:zen.spamhaus.org
May 1 14:32:53.113 [21742] dbg: async: timing: 1.524 .
dns:A:67.27.240.54.bl.mailspike.net
May 1 14:32:53.113 [21742] dbg: async: timing: 1.533 .
dns:TXT:67.27.240.54.bl.spamcop.net
--
Simon Wilson
M: 0400 12 11 16
