tracing bottlenecks ?

[Nick Howitt]

On 29/10/2021 11:18, Matus UHLAR - fantomas wrote:
> 
> On 29.10.21 15:56, lists at sbt.net.au wrote:
>> I've noticed some of my emails spend up to 5 minutes in amavis checks,
>> dumb question, how to figure out where is the bottleneck ?
> 
> hard to say, maybe you could feed the file into spamassassin -D which could
> show you more.
> 
>> should I try changing max_server = 10 ? or ?
> 
> I don't know what is your current setting and how much of memory you have,
> so it's really hard to guess what you have to change.
> 
>> grep amavis /var/log/maillog shows like '980 ms', '912 ms', BUT also:
>>
>> Oct 29 15:45:22 amavis[21973]: (21973-07) Passed CLEAN {RelayedInternal},
>> ORIGINATING LOCAL [147.111.222.333]:55095 [147.33.33.44] <ssss at aaaaa.com>
>> -> <fff at aaaa.com.au>, Queue-ID: 12EBGRT227, Message-ID:
>> <e4a4cec3-9215-6d92-89b3-41d107a336be at aaa.com>, mail_id: ffgfgarJu, Hits:
>> -2.898, size: 249274, queued_as: AAAAAA, 300681 ms
> 
> it's really too much for 250k mail, I've had problems with huge mails.
> 
> do you have any local spamassassin rules?
> 
>> 'insufficient server resources', or what can I tune ?
> 
> did you get this message or are you just guessing?
> 
I get far more info from amavis:
Oct 29 19:51:34 server amavis[23855]: (23855-04) ESMTP :10024 
/var/lib/amavis/tmp/amavis-20211029T195134-23855-OHqqsWGB: 
<samba-bounces at lists.samba.org> -> <nick at howitts.co.uk> SIZE=6147 
BODY=8BITMIME Received: from mailserver.howitts.co.uk ([127.0.0.1]) by 
localhost (server.howitts.co.uk [127.0.0.1]) (amavisd-new, port 10024) 
with ESMTP for <nick at howitts.co.uk>; Fri, 29 Oct 2021 19:51:34 +0100 (BST)
Oct 29 19:51:34 server amavis[23855]: (23855-04) dkim: VALID 
Author+Sender+MailFrom signature by d=lists.samba.org, From: 
<samba at lists.samba.org>, a=rsa-sha256, c=relaxed/relaxed, s=2954282, 
i=@lists.samba.org, ORIG [127.0.0.1]:43160, m.list(ml:samba.lists.samba.org)
Oct 29 19:51:34 server amavis[23855]: (23855-04) dkim: FAILED 
third-party signature by d=samba.org, From: <samba at lists.samba.org>, 
a=rsa-sha256, c=relaxed/relaxed, s=42, i=@samba.org, ORIG 
[127.0.0.1]:43160, m.list(ml:samba.lists.samba.org), fail (message has 
been altered)
Oct 29 19:51:34 server amavis[23855]: (23855-04) Checking: kZGNnm72Spa3 
[127.0.0.1] <samba-bounces at lists.samba.org> -> <nick at howitts.co.uk>
Oct 29 19:51:34 server amavis[23855]: (23855-04) p001 1 Content-Type: 
text/plain, size: 2277 B, name:
Oct 29 19:51:37 server amavis[23855]: (23855-04) spam-tag, 
<samba-bounces at lists.samba.org> -> <nick at howitts.co.uk>, No, score=-3.4 
tagged_above=-99 required=5 tests=[DKIMWL_WL_HIGH=-0.001, 
DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, 
MAILING_LIST_MULTI=-1, RCVD_IN_DNSWL_MED=-2.3, RCVD_IN_MSPIKE_H2=-0.001, 
SPF_HELO_NONE=0.001, URIBL_BLOCKED=0.001] autolearn=ham autolearn_force=no
Oct 29 19:51:37 server amavis[23855]: (23855-04) dkim: candidate 
originators: From:<samba at lists.samba.org>, 
Sender:<samba-bounces at lists.samba.org>
Oct 29 19:51:37 server amavis[23855]: (23855-04) dkim: not signing, 
empty signing domain, From: <samba at lists.samba.org>
Oct 29 19:51:37 server amavis[23855]: (23855-04) kZGNnm72Spa3 FWD from 
<samba-bounces at lists.samba.org> -> <nick at howitts.co.uk>, BODY=8BITMIME 
250 2.0.0 from MTA(smtp:[127.0.0.1]:10026): 250 2.0.0 Ok: queued as 
9D423C20E9FA
Oct 29 19:51:37 server amavis[23855]: (23855-04) Passed CLEAN 
{RelayedInternal}, LOCAL [127.0.0.1]:43160 [2a01:4f8:192:486::2:0] 
<samba-bounces at lists.samba.org> -> <nick at howitts.co.uk>, Queue-ID: 
4A7BCC20EA07, Message-ID: 
<6fd96eb9166e064fd05b00a1d0ba5d5863b988a1.camel at samba.org>, mail_id: 
kZGNnm72Spa3, Hits: -3.4, size: 6147, queued_as: 9D423C20E9FA, 
dkim_sd=2954282:lists.samba.org, 3293 ms
Oct 29 19:51:37 server amavis[23855]: (23855-04) TIMING-SA total 2967 ms 
- parse: 1.09 (0.0%), extract_message_metadata: 13 (0.4%), 
get_uri_detail_list: 2.6 (0.1%), tests_pri_-1000: 1.80 (0.1%), 
tests_pri_-950: 0.49 (0.0%), tests_pri_-900: 0.56 (0.0%), tests_pri_-90: 
0.40 (0.0%), tests_pri_0: 293 (9.9%), check_spf: 166 (5.6%), 
poll_dns_idle: 145 (4.9%), tests_pri_20: 2607 (87.9%), check_razor2: 
2604 (87.8%), tests_pri_30: 0.71 (0.0%), check_pyzor: 0.10 (0.0%), 
tests_pri_500: 3.2 (0.1%), learn: 30 (1.0%), b_learn: 28 (0.9%), 
b_count_change: 10 (0.3%), get_report: 1.36 (0.0%)
Oct 29 19:51:37 server amavis[23855]: (23855-04) size: 6147, TIMING 
[total 3296 ms] - SMTP greeting: 1.0 (0%)0, SMTP EHLO: 0.3 (0%)0, SMTP 
pre-MAIL: 0.3 (0%)0, mkdir tempdir: 0.6 (0%)0, create email.txt: 0.1 
(0%)0, SMTP pre-DATA-flush: 1.4 (0%)0, SMTP DATA: 38 (1%)1, check_init: 
0.4 (0%)1, digest_hdr: 2.7 (0%)1, digest_body_dkim: 200 (6%)7, 
collect_info: 2.9 (0%)7, mkdir parts: 1.0 (0%)8, mime_decode: 4.0 (0%)8, 
get-file-type1: 11 (0%)8, parts_decode: 0.1 (0%)8, check_header: 0.4 
(0%)8, AV-scan-1: 25 (1%)9, spam-wb-list: 0.4 (0%)9, SA msg read: 0.4 
(0%)9, SA parse: 1.6 (0%)9, SA check: 2963 (90%)99, decide_mail_destiny: 
4.0 (0%)99, notif-quar: 0.2 (0%)99, fwd-connect: 23 (1%)100, 
fwd-mail-pip: 1.9 (0%)100, fwd-rcpt-pip: 0.1 (0%)100, fwd-data-chkpnt: 
0.0 (0%)100, write-header: 1.0 (0%)100, fwd-data-contents: 0.0 (0%)100, 
fwd-end-chkpnt: 2.3 (0%)100, prepare-dsn: 0.9 (0%)100, report: 1.5 
(0%)100, main_log_entry: 3.9 (0%)100, update_snmp: 1.8 (0%)100, SMTP 
pre-response: 0.2 (0%)100, SMTP response: 0.1 (...
Oct 29 19:51:37 server amavis[23855]: (23855-04) ...0%)100, 
unlink-2-files: 0.2 (0%)100, rundown: 0.7 (0%)100

In amavisd.conf I have "$log_level = 2;" would that help diagnostics?

Nick