1

Topic: Slow mail processing (big delays)

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.6 MARIADB edition.
- Linux/BSD distribution name and version: Linux mail 4.4.0-66-generic #87-Ubuntu SMP Fri Mar 3 15:29:05 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MariaDB
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? no
- Related log if you're reporting an issue:
====
For some reasons i have very slow mail processing, every hour im sending about 1500 emails, but they can't be process in one hour, they are staying in active queue. I look into log and see bit delays, how could i fix it?

Mar 26 15:46:35 mail postfix/10025/smtpd[23608]: 1AE2340536: client=localhost[127.0.0.1]
Mar 26 15:46:35 mail postfix/cleanup[25067]: 1AE2340536: message-id=<8aa7499f78ef16c3ef1674ade72eaa32@swift.generated>
Mar 26 15:46:35 mail postfix/qmgr[23600]: 1AE2340536: from=<root@example.com>, size=6276, nrcpt=1 (queue active)
Mar 26 15:46:35 mail amavis[25126]: (25126-06) Passed CLEAN {RelayedInternal}, ORIGINATING LOCAL [127.0.0.1] <root@example.com> -> <dorensky@mail.ru>, Message-ID: <8aa7499f78ef16c3ef1674ade72eaa32@swift.generated>, mail_id: 5xL4wMYP3VqH, Hits: 1.801, size: 5222, queued_as: 1AE2340536, dkim_new=dkim:example.com, 6473 ms, Tests: [DKIM_ADSP_ALL=1.1,HTML_IMAGE_ONLY_20=0.7,HTML_MESSAGE=0.001,NO_RELAYS=-0.001,URIBL_BLOCKED=0.001]
Mar 26 15:46:35 mail postfix/smtp-amavis/smtp[25125]: E373442854: to=<dorensky@mail.ru>, relay=127.0.0.1[127.0.0.1]:10026, delay=2633, delays=2136/491/0.01/6.5, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1AE2340536)
Mar 26 15:46:35 mail postfix/qmgr[23600]: E373442854: removed
Mar 26 15:46:35 mail postfix/smtp[23605]: Trusted TLS connection established to mxs.mail.ru[217.69.139.150]:25: TLSv1.2 with cipher AES256-GCM-SHA384 (256/256 bits)
Mar 26 15:46:36 mail postfix/smtp[23605]: 1AE2340536: to=<dorensky@mail.ru>, relay=mxs.mail.ru[217.69.139.150]:25, delay=1, delays=0.03/0.02/0.33/0.66, dsn=2.0.0, status=sent (250 OK id=1csANH-0007pU-MB)
Mar 26 15:46:36 mail postfix/qmgr[23600]: 1AE2340536: removed

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2

Re: Slow mail processing (big delays)

Try to disable spam/virus scanning for outgoing emails:
http://www.iredmail.org/docs/disable.sp … mails.html

3

Re: Slow mail processing (big delays)

ZhangHuangbin wrote:

Try to disable spam/virus scanning for outgoing emails:
http://www.iredmail.org/docs/disable.sp … mails.html

i don't want to disable. I want to make delays smaller.

4

Re: Slow mail processing (big delays)

This is a conflict: spam/virus scanning takes a lot time, and you want to speed up mail flow without disabling them.

Some other things you should check:

*) Figure out why mails delayed first. Is it caused by spam/virus scanning?
*) Make sure you're using a fast DNS server (about "fast", i mean fast query response).

5 (edited by krich.al.vl 2017-03-28 01:52:50)

Re: Slow mail processing (big delays)

ZhangHuangbin wrote:

This is a conflict: spam/virus scanning takes a lot time, and you want to speed up mail flow without disabling them.

Some other things you should check:

*) Figure out why mails delayed first. Is it caused by spam/virus scanning?
*) Make sure you're using a fast DNS server (about "fast", i mean fast query response).

i could resolve one part of issue with installing dnsmasq. I becomes 2 times faster.
The last part of issue, i think, relates to dkim (for incoming and outgoing mails):

___________________________
Mar 27 17:39:46 mail amavis[9363]: (09363-09) Passed CLEAN {RelayedInbound}, [94.100.181.110]:49365 [94.100.188.20] <> -> <root@example.com>, Queue-ID: F19804051D, Message-ID: <E1csY9f-000645-0S@mx130.mail.ru>, mail_id: hE7UWn-j3ouS, Hits: -0.8, size: 11930, queued_as: AD1154051E, dkim_sd=mail:corp.mail.ru, 7537 ms, Tests: [DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,RCVD_IN_DNSWL_LOW=-0.7,SPF_HELO_PASS=-0.001,URIBL_BLOCKED=0.001]
___________________________

what can produce this issue?

6

Re: Slow mail processing (big delays)

Turn on debug mode in Amavisd, it will log each operation and the time it costs.
FYI: http://www.iredmail.org/docs/debug.amavisd.html

7 (edited by krich.al.vl 2017-03-28 15:52:50)

Re: Slow mail processing (big delays)

ZhangHuangbin wrote:

Turn on debug mode in Amavisd, it will log each operation and the time it costs.
FYI: http://www.iredmail.org/docs/debug.amavisd.html

Mar 28 07:34:16 mail amavis[23697]: (23697-01) TIMING-SA total 1354 ms - parse: 12 (0.9%), extract_message_metaMar 28 07:34:16 mail amavis[23697]: (23697-01) ...update: 26 (1%)99, update_snmp: 7 (0%)99, SMTP pre-response: 11 (0%)100, SMTP response: 1.9 (0%)100, unlink-3-files: 2.0 (0%)100, rundown: 2.6 (0%)100data: 163 (12.1%), get_uri_detail_list: 2.1 (0.2%), tests_pri_-1000: 219 (16.2%), tests_pri_-950: 7 (0.6%), tests_pri_-900: 22 (1.6%), tests_pri_-400: 20 (1.5%), tests_pri_0: 680 (50.2%), check_spf: 170 (12.5%), poll_dns_idle: 16 (1.2%), check_pyzor: 9 (0.7%), tests_pri_500: 55 (4.0%), get_report: 3.6 (0.3%)
Mar 28 07:34:16 mail amavis[23697]: (23697-01) size: 8007, TIMING [total 2254 ms] - sql-prepare: 32 (1%)1, SMTP greeting: 15 (1%)2, SMTP EHLO: 14 (1%)3, SMTP pre-MAIL: 11 (1%)3, mkdir tempdir: 7 (0%)3, create email.txt: 3.5 (0%)4, sql-connect: 35 (2%)5, lookup_sql: 2.7 (0%)5, SMTP pre-DATA-flush: 11 (0%)6, SMTP DATA: 3.4 (0%)6, check_init: 3.0 (0%)6, digest_hdr: 16 (1%)7, digest_body_dkim: 40 (2%)9, collect_info: 40 (2%)10, gen_mail_id: 25 (1%)11, mkdir parts: 10 (0%)12, mime_decode: 93 (4%)16, get-file-type3: 102 (5%)21, parts_decode: 1.5 (0%)21, check_header: 6 (0%)21, AV-scan-1: 105 (5%)26, spam-wb-list: 9 (0%)26, SA msg read: 1.7 (0%)26, SA parse: 17 (1%)27, SA check: 1327 (59%)86, decide_mail_destiny: 43 (2%)88, notif-quar: 3.3 (0%)88, fwd-connect: 79 (4%)91, fwd-mail-pip: 26 (1%)92, fwd-rcpt-pip: 0.5 (0%)92, fwd-data-chkpnt: 0.1 (0%)92, write-header: 1.0 (0%)92, fwd-data-contents: 0.2 (0%)92, fwd-end-chkpnt: 13 (1%)93, prepare-dsn: 14 (1%)94, report: 33 (1%)95, main_log_entry: 58 (3%)98, sql-...

Mar 28 07:34:16 mail amavis[23697]: (23697-01) ...update: 26 (1%)99, update_snmp: 7 (0%)99, SMTP pre-response: 11 (0%)100, SMTP response: 1.9 (0%)100, unlink-3-files: 2.0 (0%)100, rundown: 2.6 (0%)100
Mar 28 07:34:16 mail amavis[23697]: (23697-01) idle_proc, 6: was busy, 2144.1 ms, total idle 0.004 s, busy 2.262 s
Mar 28 07:34:16 mail amavis[23697]: (23697-01) idle_proc, 5: was idle, 3.8 ms, total idle 0.008 s, busy 2.262 s
Mar 28 07:34:16 mail amavis[23697]: (23697-01) ESMTP< QUIT\r\n
Mar 28 07:34:16 mail amavis[23697]: (23697-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Mar 28 07:34:16 mail amavis[23697]: (23697-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Mar 28 07:34:16 mail amavis[23697]: (23697-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Mar 28 07:34:16 mail amavis[23697]: (23697-01) switch_to_client_time 480 s, smtp response sent
Mar 28 07:34:16 mail amavis[23697]: (23697-01) SMTP session over, timer stopped
Mar 28 07:34:17 mail amavis[23697]: (23697-01) exiting process_request
Mar 28 07:34:17 mail amavis[23697]: (23697-01) idle_proc, bye: was busy, 32.4 ms, total idle 0.008 s, busy 2.295 s
Mar 28 07:34:17 mail amavis[23697]: (23697-01) load: 100 %, total idle 0.008 s, busy 2.295 s
Mar 28 07:34:17 mail postfix/pipe[24991]: C003D3F97E: to=<fbl@example.com>, relay=dovecot, delay=0.31, delays=0.02/0.08/0/0.22, dsn=2.0.0, status=sent (delivered via dovecot service)
Mar 28 07:34:17 mail postfix/qmgr[24917]: C003D3F97E: removed
Mar 28 07:37:34 mail postfix/anvil[24984]: statistics: max connection rate 1/60s for (smtpd:185.5.137.4) at Mar 28 07:34:14
Mar 28 07:37:34 mail postfix/anvil[24984]: statistics: max connection count 1 for (smtpd:185.5.137.4) at Mar 28 07:34:14
Mar 28 07:37:34 mail postfix/anvil[24984]: statistics: max cache size 1 at Mar 28 07:34:14
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: aborted 2 remaining lookups
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.018 . askdns:TXT:corp.mail.ru._vouch.dwl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.046 . DNSBL:4.27.159.162:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.051 . DNSBL:4.26.159.162:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.051 . DNSBL:4.26.159.162:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.052 . DNSBL:4.25.159.162:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.059 . DNSBL:4.24.159.162:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.061 . DNSBL:4.24.159.162:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.062 . DNSBL:10.36.239.216:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.065 . DNSBL:10.36.239.216:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.069 . DNSBL:10.38.239.216:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.071 . DNSBL:10.38.239.216:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.076 . DNSBL:10.34.239.216:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.077 . DNSBL:10.34.239.216:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.083 . DNSBL:10.32.239.216:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.084 . DNSBL:10.32.239.216:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.116 . DNSBL:147.23.85.95:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.118 . A:ns1.somedns.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.119 . DNSBL:4.25.159.162:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.123 . A:ns2.somedns.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.127 . A:ns3.somedns.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.130 . A:ns1.google.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.133 . A:ns4.somedns.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.138 . A:ns2.google.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.144 . A:ns4.google.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.148 . DNSBL:147.23.85.95:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.152 . A:ns3.google.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.172 . dns:A:200.172.140.128.psbl.surriel.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.174 . dns:A:corp.mail.ru
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.176 . dns:MX:corp.mail.ru
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.183 . dns:A:0.0.0.0.dnsbl.sorbs.net
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.185 . DNSBL:78.17.217.172:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.196 . DNSBL:78.17.217.172:sbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.199 . dns:TXT:200.172.140.128.sa-trusted.bondedsender.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.200 . dns:A:200.172.140.128.wl.mailspike.net
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.202 . NS:google-analytics.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.202 . DNSBL:google-analytics.com:multi.surbl.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.203 . DNSBL:google-analytics.com:dbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.204 . DNSBL:google-analytics.com:multi.uribl.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.206 . DNSBL:google-analytics.com:dob.sibl.support-intelligence.net
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.213 . dns:A:200.172.140.128.zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.218 . A:www.google-analytics.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.220 . dns:A:0.0.0.0.zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.221 . NS:example.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.222 . dns:A:200.172.140.128.list.dnswl.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.226 . DNSBL:example.com:multi.uribl.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.227 . DNSBL:example.com:dob.sibl.support-intelligence.net
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.230 . dns:A:200.172.140.128.bl.score.senderscore.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.232 . dns:TXT:200.172.140.128.bl.spamcop.net
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.238 . dns:TXT:0.0.0.0.bl.spamcop.net
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.243 . DNSBL:example.com:multi.surbl.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.244 . dns:TXT:200.172.140.128.sa-accredit.habeas.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.245 . dns:A:200.172.140.128.dnsbl.sorbs.net
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.246 . A:example.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.253 . DNSBL:example.com:dbl.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.263 . dns:A:200.172.140.128.bb.barracudacentral.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 0.286 . dns:A:200.172.140.128.iadb.isipp.com
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 3.815 X DNSBL:4.27.159.162:zen.spamhaus.org
Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: async: timing: 4.167 X dns:A:200.172.140.128.bl.mailspike.net

Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: timing: total 4405 ms - parse: 10 (0.2%), extract_message_metadata: 153 (3.5%), get_uri_detail_list: 1.97 (0.0%), tests_pri_-1000: 395 (9.0%), tests_pri_-950: 8 (0.2%), tests_pri_-900: 11 (0.3%), tests_pri_-400: 4.8 (0.1%), tests_pri_0: 546 (12.4%), check_spf: 136 (3.1%), poll_dns_idle: 3158 (71.7%), check_pyzor: 3.8 (0.1%), tests_pri_500: 3145 (71.4%)

8

Re: Slow mail processing (big delays)

krich.al.vl wrote:

Mar 28 07:34:16 mail amavis[23697]: (23697-01) size: 8007, TIMING [total 2254 ms] - sql-prepare: 32 (1%)1, SMTP greeting: 15 (1%)2, SMTP EHLO: 14 (1%)3, SMTP pre-MAIL: 11 (1%)3, mkdir tempdir: 7 (0%)3, create email.txt: 3.5 (0%)4, sql-connect: 35 (2%)5, lookup_sql: 2.7 (0%)5, SMTP pre-DATA-flush: 11 (0%)6, SMTP DATA: 3.4 (0%)6, check_init: 3.0 (0%)6, digest_hdr: 16 (1%)7, digest_body_dkim: 40 (2%)9, collect_info: 40 (2%)10, gen_mail_id: 25 (1%)11, mkdir parts: 10 (0%)12, mime_decode: 93 (4%)16, get-file-type3: 102 (5%)21, parts_decode: 1.5 (0%)21, check_header: 6 (0%)21, AV-scan-1: 105 (5%)26, spam-wb-list: 9 (0%)26, SA msg read: 1.7 (0%)26, SA parse: 17 (1%)27, SA check: 1327 (59%)86, decide_mail_destiny: 43 (2%)88, notif-quar: 3.3 (0%)88, fwd-connect: 79 (4%)91, fwd-mail-pip: 26 (1%)92, fwd-rcpt-pip: 0.5 (0%)92, fwd-data-chkpnt: 0.1 (0%)92, write-header: 1.0 (0%)92, fwd-data-contents: 0.2 (0%)92, fwd-end-chkpnt: 13 (1%)93, prepare-dsn: 14 (1%)94, report: 33 (1%)95, main_log_entry: 58 (3%)98, sql-...

Mar 28 07:49:32 mail amavis[23697]: (23697-03) SA dbg: timing: total 4405 ms - parse: 10 (0.2%), extract_message_metadata: 153 (3.5%), get_uri_detail_list: 1.97 (0.0%), tests_pri_-1000: 395 (9.0%), tests_pri_-950: 8 (0.2%), tests_pri_-900: 11 (0.3%), tests_pri_-400: 4.8 (0.1%), tests_pri_0: 546 (12.4%), check_spf: 136 (3.1%), poll_dns_idle: 3158 (71.7%), check_pyzor: 3.8 (0.1%), tests_pri_500: 3145 (71.4%)

Check the operations with long time.

9

Re: Slow mail processing (big delays)

BTW, try to run 'sa-compile', it will compile sa rules and it speeds up a lot.