Thanks for your reply!

The server is a dedicated virtual machine.

As previously mentioned, CPU or I/O was not a limiting factor.
There was plenty spare CPU resources available.

I can monitor iredapd and its child processes with following command:

watch pstree -lap $(pgrep -f iredapd)

So next time many emails are arriving and iRedAPD is at 100% CPU, I should see many childs, correct?

Is there anything else I can do in order to further track down possible root causes when the issue happens next?

I checked for threads using

top -H -p <pid>

As you can see in attached screenshot, only one thread is shown while many emails were sent to that server.

Hopefully I am wrong but from what I can see iredapd is running with one single thread only.
This explains the bottleneck we experience on the server.

Dear Zhang,

I'd like to bring this topic up again because it causes still issues on my iredmail installation in times of heavy email traffic (e.g. hundreds of emails being received):

- iredapd consumes 100% CPU (1 core only)
- email reception is delayed
- email sending of customers is delayed (it takes a long time until email is actually accepted by the server, in the meantime thunderbird shows a progress bar..)

I've read the documentation of asyncore (which is deprecated BTW since python 3.6) and it clearly states:

"that lets you have nearly all the advantages of multi-threading, without actually using multiple threads."

I understand that I/O is asynchronous but actual iredapd policy processing is not.

This explains why there are no visible threads in "top -H" and why iredapd is never using more than one CPU core.

I am not yet seeking for a solution or fix but I hope that we both understand the root cause.

The successor ot asyncore has a well written documentation about blocking code:

https://docs.python.org/3/library/asyncio-dev.html

So as a baseline all I/O can be handled by that library and processing of the received commands/emails/messages will have to be done in a separate thread.

This will ensure that all server ressources are used in cases of high load.

Feedback welcome ^_^

Take care!
Cheers,
Bernhard

Hi Broth,

- Could you please share the details of how you produce the 100% CPU usage in a local testing machine?
- I understand the situation that asyncore/asynchat modules are deprecated since Python 3.6, just need time to migrate it to asyncio, or wait for PR contribution.
- Maybe you can try this "gevent" edition too: https://github.com/iredmail/iRedAPD/blo … -gevent.py

Note: above link is the latest revision of gevent module support, it may not work by simply replacing the "iredapd.py" file, some tweaks are required.

If i want to rewrite iRedAPD, i may rewrite it with Golang.

Try these tunings to avoid DNS queries first.

- Add settings in iRedAPD config file /opt/iredapd/settings.py:

CHECK_SPF_IF_LOGIN_MISMATCH = False

- Disable greylisting plugin.

Let's see how it goes.

ok, try one more setting in /opt/iredapd/settings.py:

GREYLISTING_BYPASS_SPF = False

It's used by greylisting plugin too.

Note: a fast (upstream) DNS server helps a lot for mail server.

I made following modification:

- let SQL return lowercase results
- using sets for whitelists and _wls

This improved the performance by some percent.

    whitelists = set()

    for tbl in ['greylisting_whitelist_domain_spf', 'greylisting_whitelists']:
        # query whitelists based on recipient
        sql = """SELECT LOWER(sender)
                   FROM %s
                  WHERE account IN %s""" % (tbl, sqlquote(recipients))

        logger.debug('[SQL] Query greylisting whitelists from `{}`: \n{}'.format(tbl, sql))
        qr = conn.execute(sql)
        records = qr.fetchall()

        _wls = {v[0] for v in records}

        # check whether sender (email/domain/ip) is explicitly whitelisted
        if client_address in _wls:
            logger.info('[%s] Client IP is explictly whitelisted for greylisting service.' % (client_address))
            return True

        _wl_senders = set(senders) & set(_wls)
        if _wl_senders:
            logger.info('[{}] Sender address is explictly whitelisted for greylisting service: {}'.format(
                client_address, ', '.join(_wl_senders)))
            return True

        whitelists.update(_wls)

Currently, as "greylisting_whitelists' has many records (CSA whitelist), this is the main cause for qr.fetchall() to spend so much time.

Maybe I have to disable the big whitelist because thinkable workarounds are too complicated to implement:

- let SQL return only matching records
- using SQL stored procedures (depending on SQL server might be difficult)

Am I the only iRedAPD user with many whitelisted servers?

At least the bottleneck has been identified ^_^

Dear Zhang,

in "graylisting_whitelists" I have around 138.054 elements.
SQL dump of greylisting_whitelists table is attached.

This allows you to check the performance figure.

Here is your diff:

--- greylisting.py.org    2021-05-10 05:20:10.294292798 +0200
+++ greylisting.py    2021-05-10 05:20:40.261923972 +0200
@@ -45,11 +45,11 @@
     @ip_object -- object of IP address type (get by ipaddress.ip_address())
     """
 
-    whitelists = []
+    whitelists = set()
 
     for tbl in ['greylisting_whitelist_domain_spf', 'greylisting_whitelists']:
         # query whitelists based on recipient
-        sql = """SELECT sender
+        sql = """SELECT LOWER(sender)
                    FROM %s
                   WHERE account IN %s""" % (tbl, sqlquote(recipients))
 
@@ -57,7 +57,7 @@
         qr = conn.execute(sql)
         records = qr.fetchall()
 
-        _wls = [str(v[0]).lower() for v in records]
+        _wls = {v[0] for v in records}
 
         # check whether sender (email/domain/ip) is explicitly whitelisted
         if client_address in _wls:
@@ -70,7 +70,7 @@
                 client_address, ', '.join(_wl_senders)))
             return True
 
-        whitelists += _wls
+        whitelists.update(_wls)
 
     logger.debug('[%s] Client is not explictly whitelisted.' % (client_address))

From the log you can clearly see that it takes very long to get processed.

May 10 05:21:17 mail iredapd [1xx.6x.1x.1x] RCPT, xxxx@gmail.com -> xxxx@example.com, DUNNO [sasl_username=, sender=xxxx@gmail.com, client_name=xxx.xxxxxx.net, reverse_client_name=xxx.xxxxxx.net, helo=xxx.xxxxxx.net, encryption_protocol=, encryption_cipher=, server_port=25, process_time=1.1399s]

While iRedAPD is busy, processing of other messages is delayed (e.g. sending an email in thunderbird)

I totally agree, I wasn't expecting this either

Best regards,
Bernhard

Yes I did. _wls has a length of more than 130 thousand elements.

I don't think this is a problem with the database:

MariaDB [iredapd]> select lower(sender) from greylisting_whitelists where account in ('user@example.com', '@example.com', '@.', '@.example.com', '@.com');

..
..
..
138066 rows in set (0.095 sec)

As you see, execution time of the query is 95ms
(the lower(sender) costs around 18ms but saves looping through the list in python)

IMHO the man problem is the time required for python to fetch the complete result set into memory (fetchall call).

There are several options to solve the issue:

1. get rid of so many whitelist records
-> easy workaround without actually fixing the root cause

2. enhance iredapd so that whitelist checking is done in SQL instead of python
-> this will probably give the best performance at the cost of development and test effort

3. check my small modifications as seen in the patch and keep the basic structure, documentation/warning to make user aware about potential performance impacts when using many whitelist records
-> reasonable

Have you tried to import my SQL dump into your database?

Thank you very much for implementing the patch in iRedAPD - I feel very honored ^_^

I added some debug code:

        start = time.clock()
        qr = conn.execute(sql)
        end = time.clock()
        logger.info("%s -> %.2gs" % (sql, end-start))

The result shows that conn.execute is a bit slow.

When putting the same SQL statement in mysql, the query takes much less time.

Here is the log:

May 20 06:07:06 mail iredapd SELECT LOWER(sender)#012                   FROM greylisting_whitelist_domain_spf#012                  WHERE account IN ('user@example.com, '@example.com', '@.', '@.example.com', '@.com') -> 0.0018s
May 20 06:07:07 mail iredapd SELECT LOWER(sender)#012                   FROM greylisting_whitelists#012                  WHERE account IN ('user@example.com', '@example.com', '@.', '@.example.com', '@.com') -> 0.85s
May 20 06:07:07 mail iredapd [1xx.xx.xx.xx] Sender address is explictly whitelisted for greylisting service: 1
May 20 06:07:07 mail iredapd [1xx.xx.xx.xx] RCPT, sender@otherdomain.com -> user@example.com, DUNNO [sasl_username=, sender=sender@otherdomain.com, client_name=xxx.xxx.net, reverse_client_name=xxx.xxx.net, helo=xxx.xxx.net, encryption_protocol=, encryption_cipher=, server_port=25, process_time=1.0044s]

The slow query from the log directly in mysql commandline:

MariaDB [iredapd]> SELECT LOWER(sender)                   FROM greylisting_whitelists                  WHERE account IN ('user@example.com', '@example.com', '@.', '@.example.com', '@.com');
...
138095 rows in set (0.089 sec)

MariaDB [iredapd]> 

I will read pymysql documentation, maybe I find the reason why

Any idea from your side?

"DESCRIBE query" show that an index is used:

...
|    1 | SIMPLE      | greylisting_whitelists | range | account       | account | 302     | NULL | 69051 | Using where; Using index |
...

This will show available indices:

show indexes from greylisting_whitelists;

With mysql CLI the exact same query from iredapd is fast.

I will play around with new indices.