[SOLVED] Performance Issues with pmg-smtp-filter

Apr 21, 2021
2
1
3
22
Hello,

we have 2 PMGs in a cluster in use.

Both with the following configuration:

2 CPU cores (virtual)
16 GB RAM
Avg. load between 0,14 and 0,18
40 GB hard disk
Host system: VMware
Version: pmg-api/6.4-3/225ecb80 (running kernel: 5.4.106-1-pve)

Since March 18 we see an avg. Mail Processing time higher than 8 seconds. There are no special events in the log on or around this day.
To me it looks like this behavior only happens with incoming mails and the problem occures in the pmg-smtp-filter:

Code:
Apr 21 12:12:34 pmg-pub-01 postfix/smtpd[1246]: connect from **removed**
Apr 21 12:12:34 pmg-pub-01 postfix/smtpd[1246]: Anonymous TLS connection established from **removed**:
TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
Apr 21 12:12:40 pmg-pub-01 postfix/smtpd[1246]: 9C85E61D6F: client=**removed**
Apr 21 12:12:40 pmg-pub-01 postfix/cleanup[31757]: 9C85E61D6F: message-id=<**removed**>
Apr 21 12:12:40 pmg-pub-01 postfix/smtpd[1246]: disconnect from **removed** ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Apr 21 12:12:40 pmg-pub-01 postfix/qmgr[17101]: 9C85E61D6F: from=<**removed**>, size=5256, nrcpt=1 (queue active)
Apr 21 12:12:40 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: new mail message-id=<**removed**>#012
Apr 21 12:12:55 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: SA score=0/5 time=15.023 bayes=0.00 autolearn=no autolearn_force=no hits=AWL(0.324),BAYES_00(-1.9),DKIM_INVALID(0.1),DKIM_SIGNED(0.1),HTML_MESSAGE(0.001),KAM_DMARC_STATUS(0.01),SPF_PASS(-0.001),T_SPF_HELO_TEMPERROR(0.01)
Apr 21 12:12:55 pmg-pub-01 postfix/smtpd[32057]: connect from localhost.localdomain[127.0.0.1]
Apr 21 12:12:55 pmg-pub-01 postfix/smtpd[32057]: B9E4C61E01: client=localhost.localdomain[127.0.0.1], orig_client=**removed**
Apr 21 12:12:55 pmg-pub-01 postfix/cleanup[28769]: B9E4C61E01: message-id=**removed**>
Apr 21 12:12:55 pmg-pub-01 postfix/qmgr[17101]: B9E4C61E01: from=<**removed**>, size=6131, nrcpt=1 (queue active)
Apr 21 12:12:55 pmg-pub-01 postfix/smtpd[32057]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
Apr 21 12:12:55 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: accept mail to <**removed**> (B9E4C61E01) (rule: Whitelist)
Apr 21 12:12:55 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: processing time: 15.095 seconds (15.023, 0.041, 0)
Apr 21 12:12:55 pmg-pub-01 postfix/lmtp[27677]: 9C85E61D6F: to=<**removed**>, relay=127.0.0.1[127.0.0.1]:10024, delay=21, delays=5.7/0/0/15, dsn=2.5.0, status=sent (250 2.5.0 OK (61D70608016B8A4067))
Apr 21 12:12:55 pmg-pub-01 postfix/qmgr[17101]: 9C85E61D6F: removed
Apr 21 12:13:21 pmg-pub-01 postfix/smtp[32501]: B9E4C61E01: to=<**removed**>, relay=**removed**:25, delay=25, delays=0/0/25/0.26, dsn=2.6.0, status=sent (250 2.6.0 <**removed**>
InternalId=105918188486884, Hostname=**removed** 7424 bytes in 0.246, 29.383 KB/sec Queued mail for delivery)
Apr 21 12:13:21 pmg-pub-01 postfix/qmgr[17101]: B9E4C61E01: removed

Code:
Apr 21 13:46:28 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: new mail message-id=<**removed**>
Apr 21 13:46:46 pmg-pub-01 pmg-smtp-filter[25420]: 2021/04/21-13:46:46 CONNECT TCP Peer: "[127.0.0.1]:34522" Local: "[127.0.0.1]:10024"
Apr 21 13:46:46 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: new mail message-id=<**removed**>
Apr 21 13:46:49 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: SA score=0/5 time=20.497 bayes=0.00 autolearn=no autolearn_force=no hits=AWL(0.304),BAYES_00(-1.9),DKIM_INVALID(0.1)
Apr 21 13:46:49 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: accept mail to <**removed**> (5BD342BFEF) (rule: default-accept)
Apr 21 13:46:49 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: processing time: 20.629 seconds (20.497, 0.054, 0)
Apr 21 13:47:00 pmg-pub-01 pmg-smtp-filter[24766]: 2021/04/21-13:47:00 CONNECT TCP Peer: "[127.0.0.1]:34536" Local: "[127.0.0.1]:10024"
Apr 21 13:47:00 pmg-pub-01 pmg-smtp-filter[24766]: 2C02260802CD4B6D61: new mail message-id=<**removed**>
Apr 21 13:47:04 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: SA score=0/5 time=17.410 bayes=0.00 autolearn=no autolearn_force=no hits=BAYES_00(-1.9),DKIM_INVALID(0.1),DKIM_SIGNE
Apr 21 13:47:04 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: accept mail to <**removed**> (06D392BFFC) (rule: default-accept)
Apr 21 13:47:04 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: processing time: 17.503 seconds (17.41, 0.061, 0)

These are only examples. We see this high delay with every incoming mail.

Code:
sudo pmgperf

# First node:

CPU BOGOMIPS:      9577.50
REGEX/SECOND:      2917935
HD SIZE:           40.00 GB (rpool/ROOT/pmg-1)
FSYNCS/SECOND:     3023.25
DNS EXT:           361.67 ms
DNS INT:           338.58 ms (**removed**)

# Second node:

CPU BOGOMIPS:      9577.50
REGEX/SECOND:      2671338
HD SIZE:           40.00 GB (rpool/ROOT/pmg-1)
FSYNCS/SECOND:     2756.89
DNS EXT:           367.46 ms
DNS INT:           339.18 ms (**removed**)

I tried many things but I did not find any articels about troubleshooting the smtp filter daemon, maybe somebody has an idea or a point at which we can start again.

Best regards,
Jan
 
Last edited:

Stoiko Ivanov

Proxmox Staff Member
Staff member
May 2, 2018
6,649
985
163
`
Apr 21 13:47:04 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: processing time: 17.503 seconds (17.41, 0.061, 0)
and
Apr 21 12:12:55 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: SA score=0/5 time=15.023 bayes=0.00 autolearn=no autolearn_force=no hits=AWL(0.324),BAYES_00(-1.9),DKIM_INVALID(0.1),DKIM_SIGNED(0.1),HTML_MESSAGE(0.001),KAM_DMARC_STATUS(0.01),SPF_PASS(-0.001),T_SPF_HELO_TEMPERROR(0.01)
would indicate a problem with the DNS-server configuration on the PMG (the DNS timings of pmgperf would also support this)

check your '/etc/resolv.conf' - make sure that the first listed DNS server is working properly and providing answers fast! (SpamAssassin (sadly) only uses the first configured server)

I hope this helps!
 
Apr 21, 2021
2
1
3
22
It is always DNS...

Thanks for the hint. The PMGs have 3 DNS Servers and the first one wasn't working correct. Changed that entry and booom... everything back normal...

Best regards,
Jan
 
  • Like
Reactions: Stoiko Ivanov

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get your own in 60 seconds.

Buy now!