tracing bottlenecks ?

[lists at sbt.net.au]

On Wed, December 1, 2021 1:58 am, Matus UHLAR - fantomas wrote:
>> On Sun, October 31, 2021 4:02 am, Matus UHLAR - fantomas wrote:
>>
>>>> On Fri, October 29, 2021 9:18 pm, Matus UHLAR - fantomas wrote:
>>>>
>>>>
>>>>> hard to say, maybe you could feed the file into spamassassin -D
>>>>> which could show you more.
>>>
>>> On 30.10.21 12:31, lists at sbt.net.au wrote:
>>>
>>>
>>>> do you mean feed such an email file that took long time ? is it
>>>> like:
>>>> spamassassin -D < mail.file
>>>
>>> precisely. You should do that as amavis user, redirecting error
>>> output so something like
>>>
>>> su amavis -c 'spamassassin -D' < /tmp/input >/tmp/output 2>&1
>
> sorry completely forgot this one
>
> On 31.10.21 11:32, lists at sbt.net.au wrote:
>
>> thanks. I'll go step by step, in case I'm doing it wrong:
>
>
>> I've searched recent maillog for example of 'delayed' email, found one:
>>
>>
>> Oct 25 12:56:13 amavis[18958]: (18958-14) Passed CLEAN
>> {RelayedInbound},
>> [54.240.7.42]:37159 [54.240.7.42]
>> <0102017cb524e543-695815fb-86de-4f18-b7f0-64487ae071f3-000000 at eu-west-1.
>> amazonses.com> -> <aaa at bbb.au>, Queue-ID: 5BA8241E1CB0, Message-ID:
>> <0102017cb524e543-695815fb-86de-4f18-b7f0-64487ae071f3-000000 at eu-west-1.
>> amazonses.com>,
>> mail_id: rKaBituAo6su, Hits: -1.898, size: 28444, queued_as:
>> E949341DFFD9,
>> 300397 ms
>>
>>
>> found same 'queued' string in an email file, email file copied to new
>> file 'delayedemail'
>>
>>
>> # grep E949341DFFD9 delayedmail
>> by sbt.net.au (Postfix) with ESMTP id E949341DFFD9
>>
>> old]# su amavis -c 'spamassassin -D' < delayedmail > output 2>&1
>
> you should see timing info in the "output" file. there you can find wht
> took so long.
>
>> takes maybe 5 secs to run. so far haven't noticed anything in 'output'
>> file
>>

Matus,

thanks for your reply!

looking at the results from that one test:

from original mail header:
Received: from [127.0.0.1])  Mon, 25 Oct 2021 12:56:13 +1100
X-Virus-Scanned: amavisd-new at sbt.net.au
Received: from ([127.0.0.1]) by [127.0.0.1]) (amavisd-new, port 10024)   
Mon, 25 Oct 2021 12:51:13 +1100 (AEDT)

from file 'output'
# head output
Oct 31 11:24:13.242 [14714] dbg: logger: adding facilities: all
Oct 31 11:24:13.242 [14714] dbg: logger: logging level is DBG
Oct 31 11:24:13.242 [14714] dbg: generic: SpamAssassin version 3.4.0
Oct 31 11:24:13.242 [14714] dbg: generic: Perl 5.016003, PREFIX=/usr,
DEF_RULES_DIR=/usr/share/spamassassin,
LOCAL_RULES_DIR=/etc/mail/spamassassin,
LOCAL_STATE_DIR=/var/lib/spamassassin
Oct 31 11:24:13.242 [14714] dbg: config: timing enabled
Oct 31 11:24:13.243 [14714] dbg: config: score set 0 chosen.
Oct 31 11:24:13.244 [14714] dbg: util: running in taint mode? yes
...
...
Oct 31 11:24:16.887 [14714] dbg: plugin:
Mail::SpamAssassin::Plugin::MIMEHeader=HASH(0x2d861d8) implements
'finish_tests', priority 0
Oct 31 11:24:16.887 [14714] dbg: plugin:
Mail::SpamAssassin::Plugin::Check=HASH(0x2ec0bc8) implements
'finish_tests', priority 0
Oct 31 11:24:16.895 [14714] dbg: netset: cache trusted_networks
hits/attempts: 11/12, 91.7 %

so, on the test I've done, it only took ~ 5 seconds, yes ?
but, at the actual time email was processed, about 5 minutes ?

I'll look in the email log for other 'delayed' emails, and, do some more
of these tests - but, is that telling the issue is not with amavis/sa
processing ?

thanks again for all your help

V