amavis p5-Mail-SpamAssasin delay issues

[Andrei Brezan via amavis-users]

On 02/19/14 23:29, Andrei Brezan wrote:
> Hello list,
>
> Recently I'm having issues with delays due to 
> amavisd-new/spamassassin. With log level increased to 5 in 
> amavisd.conf I get this out of the logs:
>
> Feb 19 22:55:17 hostname amavis[1215]: (01215-01) p001 1 Content-Type: 
> text/plain, size: 7 B, name:
> *snip*
> Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) _WARN: bayes: 
> expire_old_tokens: __alarm__ignore__(79)
> Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) SA info: check: 
> exceeded time limit in 
> Mail::SpamAssassin::Plugin::Check::_eval_tests_type11_prineg400_set3, 
> skipping further tests
> Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) _WARN: Use of 
> uninitialized value in concatenation (.) or string at 
> /usr/local/lib/perl5/site_perl/5.16/Mail/SpamAssassin/PerMsgStatus.pm 
> line 1258.
> Feb 19 23:00:17 tilaa1 amavis[1215]: (01215-01) _WARN: Use of 
> uninitialized value in numeric eq (==) at 
> /usr/local/lib/perl5/site_perl/5.16/Mail/SpamAssassin/PerMsgStatus.pm 
> line 424.
> *snip*
> Feb 19 23:00:18 tilaa1 amavis[1215]: (01215-01) TIMING-SA total 300188 
> ms - parse: 3 (0.0%), extract_message_metadata: 18 (0.0%), 
> poll_dns_idle: 2 (0.0%), get_uri_detail_list: 0.60 (0.0%), 
> tests_pri_-1000: 17 (0.0%), tests_pri_
> -950: 1.89 (0.0%), tests_pri_-900: 1.91 (0.0%), tests_pri_-400: 300094 
> (100.0%), check_bayes: 300088 (100.0%), expire_bayes: 298067 (99.3%), 
> get_report: 0.81 (0.0%)
> Feb 19 23:00:18 tilaa1 amavis[1215]: (01215-01) size: 1980, TIMING 
> [total 301147 ms] - SMTP greeting: 7 (0%)0, SMTP EHLO: 3 (0%)0, SMTP 
> pre-MAIL: 1 (0%)0, mkdir tempdir: 2 (0%)0, create email.txt: 1 (0%)0, 
> SMTP pre-DATA-flush:
> 6 (0%)0, SMTP DATA: 100 (0%)0, check_init: 1 (0%)0, digest_hdr: 6 
> (0%)0, digest_body_dkim: 35 (0%)0, mkdir parts: 5 (0%)0, mime_decode: 
> 9 (0%)0, get-file-type1: 174 (0%)0, parts_decode: 0 (0%)0, 
> check_header: 1 (0%)0, AV-scan-1
> : 32 (0%)0, spam-wb-list: 4 (0%)0, SA msg read: 1 (0%)0, SA parse: 6 
> (0%)0, SA check: 300179 (100%)100, decide_mail_destiny: 9 (0%)100, 
> notif-quar: 1 (0%)100, fwd-connect: 33 (0%)100, fwd-mail-pip: 325 
> (0%)100, fwd-rcpt-pip: 0
> (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1 (0%)100, 
> fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 178 (0%)100, 
> prepare-dsn: 2 (0%)100, main_log_entry: 15 (0%)100, update_snmp: 5 
> (0%)100, SMTP pre-response: 1 (0%)100,
> SMTP response: 2 (0%)100, unlink-2-files: 1 (0%)100, rundown: 1 (0%)100
> Feb 19 23:00:18 tilaa1 amavis[1215]: (01215-01) extra modules loaded: 
> unicore/lib/Gc/Nd.pl
>
> Can anyone shed some light into what _eval_tests_type11_prineg400_set3 
> means and where does it come from?
>
> Not all e-mails get the same treatment, some that reach same 01215-01 
> process get through without delays and then even a plain text e-mail 
> induces this delay.
>
> I'm running this postfix/amavisd-new under FreeBSD 9.1-RELEASE.
>
> Thank you,
> Andrei

For the record, the issue seems it was the bayes database which I didn't 
tend to previously, at least from my understanding. This fixed the 
timeout issue:

% sudo su - vscan
Password:
$ sa-learn --force-expire --rebuild
The --rebuild option has been deprecated.  Please use --sync instead.
bayes: synced databases from journal in 0 seconds: 258 unique entries (259 total entries)

load: 1.54  cmd: perl 29288 [runnable] 147.32r 62.20u 0.08s 100% 35872k
load: 1.67  cmd: perl 29288 [runnable] 165.25r 75.96u 0.08s 100% 35872k
load: 1.37  cmd: perl 29288 [runnable] 225.48r 120.76u 0.11s 100% 35872k
load: 1.61  cmd: perl 29288 [runnable] 309.96r 176.72u 0.21s 78% 36100k
load: 1.34  cmd: perl 29288 [runnable] 388.33r 224.64u 0.32s 93% 36100k
load: 1.24  cmd: perl 29288 [runnable] 405.48r 236.96u 0.35s 96% 36100k
expired old bayes database entries in 423 seconds
161948 entries kept, 2257326 deleted
token frequency: 1-occurrence tokens: 61.18%
token frequency: less than 8 occurrences: 12.56%

Regards,
Andrei