spamassassin taking a minute to check SMALL message

plisken · 01-04-2014, 12:08 PM

ok, so after numerous tests on a new(ish) system, I'm finding that scans are taking up to a minute on very small mails.

Could someone please give me an indication on production machines how long scans are taken?

on mine, I'm pulling this information from /var/log/maillog or typically cat /var/log/maillog | grep "seconds"

I had been running spamassassin on an older mahicne (PII) for years and noticed it gradually grind to a near halt and simply assumed it was the hardware v more recent versions of spamassassin but on this new(er) machine, I'm finding the same.

new machine spec: Sunfire X2100m Slack 14 64 4 gb
old machine spec: Dell Poweredge (2xPII) Slack 9.1 512mg

Any pointers as to where to look for this issue would be appreciated.
Example below (old machine):

Code:

Jan  4 15:48:23 morpheus spamd[9935]: spamd: clean message (-2.5/5.0) for thomas2:1010 in 83.1 seconds, 9603 bytes.
Jan  4 16:08:27 morpheus spamd[9935]: spamd: identified spam (38.3/2.8) for plisken:1000 in 83.5 seconds, 1793 bytes.
Jan  4 16:08:29 morpheus spamd[9935]: spamd: identified spam (12.8/5.0) for thomas2:1010 in 1.5 seconds, 986 bytes.
Jan  4 16:38:40 morpheus spamd[9935]: spamd: identified spam (9.5/2.0) for plumper:1001 in 80.5 seconds, 766 bytes.
Jan  4 16:40:47 morpheus spamd[9935]: spamd: identified spam (32.2/2.8) for plisken:1000 in 1.1 seconds, 1864 bytes.
Jan  4 17:04:36 morpheus spamd[9935]: spamd: identified spam (37.6/2.8) for plisken:1000 in 81.2 seconds, 1790 bytes.
Jan  4 17:09:02 morpheus spamd[9935]: spamd: identified spam (5.1/2.8) for plisken:1000 in 1.8 seconds, 13177 bytes.
Jan  4 17:43:25 morpheus spamd[9935]: spamd: clean message (-1.0/2.8) for plisken:1000 in 80.4 seconds, 734 bytes.
Jan  4 18:11:43 morpheus spamd[9935]: spamd: clean message (-1.0/2.8) for plisken:1000 in 80.4 seconds, 739 bytes.
Jan  4 19:04:28 morpheus spamd[9935]: spamd: clean message (-102.9/2.8) for plisken:1000 in 81.5 seconds, 1016 bytes.

Example below (new(er) machine):

Code:

Dec 31 14:25:24 orion spamd[1901]: spamd: clean message (0.8/5.0) for plisken:1000 in 18.2 seconds, 896 bytes.
Dec 31 14:26:19 orion spamd[1436]: spamd: clean message (0.8/5.0) for plisken:1000 in 0.1 seconds, 896 bytes.
Dec 31 14:26:30 orion spamd[1436]: spamd: clean message (0.8/5.0) for plisken:1000 in 0.1 seconds, 896 bytes.
Dec 31 14:35:01 orion spamd[1436]: spamd: clean message (-1.0/5.0) for plisken:1000 in 0.1 seconds, 684 bytes.
Jan  2 16:37:09 orion spamd[1436]: spamd: clean message (-1.0/5.0) for plisken:1000 in 18.1 seconds, 741 bytes.
Jan  2 16:38:45 orion spamd[7225]: spamd: clean message (-1.0/5.0) for plisken:1000 in 0.1 seconds, 746 bytes.
Jan  2 16:41:01 orion spamd[7225]: spamd: clean message (-1.0/5.0) for plisken:1000 in 0.1 seconds, 746 bytes.
Jan  4 17:45:32 orion spamd[13130]: spamd: clean message (0.1/5.0) for plisken:1000 in 0.1 seconds, 1896 bytes.
Jan  4 17:46:20 orion spamd[13130]: spamd: clean message (-99.3/5.0) for plisken:1000 in 0.1 seconds, 2467 bytes.
Jan  4 17:47:15 orion spamd[13130]: spamd: clean message (-100.0/5.0) for plisken:1000 in 0.1 seconds, 2591 bytes.
Jan  4 17:48:24 orion spamd[13130]: spamd: clean message (-99.3/5.0) for plisken:1000 in 0.1 seconds, 2506 bytes.
Jan  4 17:57:25 orion spamd[13130]: spamd: clean message (-0.0/5.0) for plisken:1000 in 54.1 seconds, 955 bytes.
Jan  4 18:11:06 orion spamd[13130]: spamd: clean message (-0.0/5.0) for plisken:1000 in 54.1 seconds, 957 bytes.
Jan  4 18:11:48 orion spamd[13130]: spamd: identified spam (25.1/5.0) for plisken:1000 in 0.1 seconds, 1869 bytes.
Jan  4 18:12:41 orion spamd[13130]: spamd: clean message (-99.3/5.0) for plisken:1000 in 0.1 seconds, 2518 bytes.
Jan  4 18:14:22 orion spamd[13130]: spamd: clean message (-97.6/5.0) for plisken:1000 in 0.0 seconds, 1893 bytes.
Jan  4 18:17:11 orion spamd[13130]: spamd: clean message (2.4/5.0) for plisken:1000 in 0.0 seconds, 1891 bytes.
Jan  4 18:19:29 orion spamd[13335]: spamd: clean message (2.4/5.0) for plisken:1000 in 0.1 seconds, 1889 bytes.
Jan  4 18:21:25 orion spamd[13335]: spamd: clean message (2.4/5.0) for plisken:1000 in 0.0 seconds, 1890 bytes.
Jan  4 18:22:35 orion spamd[13335]: spamd: clean message (-97.6/5.0) for plisken:1000 in 0.0 seconds, 1901 bytes.
Jan  4 18:25:07 orion spamd[13335]: spamd: identified spam (13.7/5.0) for plisken:1000 in 0.1 seconds, 911 bytes.
Jan  4 18:29:21 orion spamd[13335]: spamd: clean message (0.1/5.0) for thomas2:1002 in 54.1 seconds, 1905 bytes.
Jan  4 18:30:48 orion spamd[13335]: spamd: clean message (0.1/5.0) for thomas2:1002 in 0.0 seconds, 1894 bytes.
Jan  4 18:32:32 orion spamd[13335]: spamd: clean message (0.6/5.0) for thomas2:1002 in 0.0 seconds, 767 bytes.
Jan  4 18:43:46 orion spamd[13335]: spamd: clean message (-1.0/5.0) for plumper:1004 in 54.2 seconds, 813 bytes.
Jan  4 19:01:40 orion spamd[13335]: spamd: identified spam (6.1/5.0) for plisken:1000 in 54.4 seconds, 28867 bytes.
Jan  4 19:12:51 orion spamd[13335]: spamd: clean message (4.0/5.0) for plisken:1000 in 54.1 seconds, 739 bytes.
Jan  4 19:12:52 orion spamd[13335]: spamd: identified spam (24.3/5.0) for plisken:1000 in 0.1 seconds, 1883 bytes.

TenTenths · 01-06-2014, 03:03 AM

Check all your spamassassin recipes and look for any that make external calls to things like online blacklists etc. If there's a recipe that uses a blacklist that no longer exists then SA may be sitting waiting / retrying lookups that are timing out.