Debug Timmings

[Mark Martinec]

Nuno,

> Hum.. my doesn't  turn 100% cpu, but as i have spamassassin >= 3.3.0, i've
> checked the logs and found:
> 
> Apr 18 17:32:19 etmx1 amavis[19306]: (19306-10) TIMING-SA total 12614 ms -
> parse: 3 (0.0%), extract_message_metadata: 145 (1.1%), get_uri_detail_list:
> 1.24 (0.0%), tests_pri_-1000: 23 (0.2%), tests_pri_-950: 1.51 (0.0%),
> tests_pri_-900: 3 (0.0%), tests_pri_-400: 26 (0.2%), check_bayes: 23
> (0.2%), tests_pri_0: 12357 (98.0%), check_dkim_adsp: 58 (0.5%), check_spf:
> 261 (2.1%), poll_dns_idle: 240 (1.9%), check_razor2: 907 (7.2%),
> check_dcc: 478 (3.8%), check_pyzor: 185 (1.5%), tests_pri_500: 18 (0.1%),
> tests_pri_1000: 6 (0.0%), total_awl: 4 (0.0%), check_awl: 0.97 (0.0%),
> update_awl: 0.36 (0.0%), tests_pri_2000: 1.62 (0.0%), get_report: 1.21
> (0.0%)
> 
> Aparently is that tests_pri in spamassassin that is taking 98% of the
> time.. Does anyone know what it is?

SpamAssassin tests at priority 0 (tests_pri_0) consist of the vast majority
of SA rules, mostly regexp-based, but also some 3rd party plugins.

The only practical way that I have found so far to drill further down to
a level of a SA rule is to use a plugin HitFreqsRuleTiming.pm, that comes
with a SpamAssassin package. It is called at the end of each message
check and writes a sorted list of elapsed times by a rule name
to a file timing.log in a current working directory (if it is writable).
It is a bit clumsy, but does the job alright if used in a command-line
spamassassin call. For this you'd need to isolate a sample message
and pass it to spamassassin, e.g.:

1. copy HitFreqsRuleTiming.pm to some place where SA could find it,
like /usr/local/etc/mail/spamassassin/

2. let SA load this plugin - add to local.pre (one line):

loadplugin HitFreqsRuleTiming /usr/local/etc/mail/spamassassin/HitFreqsRuleTiming.pm

3. invoke spamassassin giving it a sample message:

$ spamassassin -t <test.msg

4. examine the file timing.log


Make sure to run spamassassin under the same username as amavisd runs.
One way to do so and to make sure the file timing.log is writable is:

# rm timing.log    (if any)
# touch timing.log
# chown vscan timing.log
# su vscan -c 'spamassassin -t <test.msg'

  Mark