alexus,
> SpamAssassin is EXTREMLY slow
> mx1# /usr/local/bin/spamd --allow-tell --vpopmail --username=spamd
> [96985] dbg: message: main message type: text/plain
> [96985] dbg: message: ---- MIME PARSER START ----
> [96985] dbg: message: parsing normal part
[...]
Find out what is taking most of the time,
provide some timestamps on the log.
Here is one way, pipe the log output from spamassassin -D
or from a non-daemonized spamd through a timestamping program
like the following function in my .bashrc:
timestamp ()
{
perl -MPOSIX -MTime::HiRes -n -e '
BEGIN {$|=1; $dp=0; $t0=Time::HiRes::time};
$t=Time::HiRes::time; $dt=$t-$t0; printf("%s%06.3f %4.3f %4.3f %s",
POSIX::strftime("%H:%M:",localtime($t)), $t-int($t/60)*60,
$dt, $dt-$dp, $_); $dp=$dt' $*
}
E.g. (assuming sh or bash):
spamd -D 2>&1 | timestamp
or:
spamassassin -D <0.msg 2>&1 | timestamp
Another way is to use SpamAssassin 3.3 (from CVS), which can provide
timing breakdown of actions, e.g.:
[1073] dbg: timing: total 19157 ms - init: 7290 (38.1%), parse: 6 (0.0%),
extract_message_metadata: 286 (1.5%), get_uri_detail_list: 9 (0.0%),
tests_pri_-1000: 44 (0.2%), compile_gen: 8144 (42.5%),
compile_eval: 37 (0.2%), tests_pri_-950: 9 (0.0%), tests_pri_-900: 6 (0.0%),
tests_pri_-400: 64 (0.3%), check_bayes: 57 (0.3%), tests_pri_0: 10888 (56.8%),
dkim_load_modules: 33 (0.2%), check_dkim_signature: 1.31 (0.0%),
check_dkim_adsp: 3 (0.0%), check_spf: 46 (0.2%), poll_dns_idle: 0.06 (0.0%),
check_razor2: 552 (2.9%), check_dcc: 157 (0.8%), check_pyzor: 0.14 (0.0%),
tests_pri_500: 232 (1.2%), tests_pri_899: 155 (0.8%),
check_crm114: 148 (0.8%), tests_pri_1000: 110 (0.6%), total_awl: 104 (0.5%),
check_awl: 4 (0.0%), update_awl: 74 (0.4%)
(also visible in the amavisd log at log level 2 or above, if using it with SA
3.3)
> [97034] dbg: async: timing: 0.515 . dns:A:106.67.10.69.iadb.isipp.com.
> [97034] dbg: async: timing: 2.564 .
> dns:TXT:106.67.10.69.sa-trusted.bondedsender.org.
> [97034] dbg: async: timing: 5.125 . dns:A:106.67.10.69.list.dnswl.org.
> [97034] dbg: async: timing: 6.405 . dns:A:106.67.10.69.sa-accredit.habeas.com.
> [97034] dbg: async: timing: 7.431 . dns:TXT:106.67.10.69.list.dsbl.org.
> [97034] dbg: async: timing: 9.223 . dns:A:106.67.10.69.dnsbl.sorbs.net.
> [97034] dbg: async: timing: 10.504 . dns:A:106.67.10.69.zen.spamhaus.org.
> [97034] dbg: async: timing: 11.784 . dns:TXT:106.67.10.69.bl.spamcop.net.
> [97034] dbg: async: timing: 13.065 . dns:A:106.67.10.69.combined.njabl.org.
> [97034] dbg: async: timing: 14.345 . dns:A:106.67.10.69.plus.bondedsender.org.
Your DNS lookups are very slow. Use a caching DNS server on your LAN or host,
and consider reducing your rbl_timeout.
Mark
