Gnu sieve vs Dovecot sieve-filter - sieve-filter extremely slow at lda (writing emails to local mbox files)

To: debian-user@lists.debian.org
Subject: Gnu sieve vs Dovecot sieve-filter - sieve-filter extremely slow at lda (writing emails to local mbox files)
From: Zenaan Harkness <zenaan@freedbms.net>
Date: Thu, 12 Sep 2019 07:55:23 +1000
Message-id: <[🔎] 20190911215523.lkgetellkicljy5i@eye>

Why is Gnu sieve so extremely fast to batch process an mbox file, but
while Dovecot's sieve-filter is an order of magnitude slower?

Sequence:

 - mpop or getmail to pipeline download emails into temp mbox file
 - filter that file

Gnu sieve just flies through a local mbox file and saving emails to
other local mbox files.

Gnu sieve rejects too many emails with "malformed" errors, so after a
few years I bit the bullet and upgraded to Dovecot's sieve-filter.

Dovecot's sieve-filter, at present, is an order of magnitude slower.

Here's my filter command (one line):

/usr/bin/sieve-filter -veW -c $HOME/etc/email/sieve-dovecot-config.conf -o mail_location=mbox:~/mail:INBOX=~/mail/Inbox:INDEX=:UTF-8:VOLATILEDIR=/tmp/dovecot-volatile/%2.256Nu/%u:SUBSCRIPTIONS=dovecot_subscriptions ~/etc/email/sieve.rc email-incoming-unsorted

The sieve script is fine now that I have the correct "require"
clauses (hint: "capability strings").

File ~/etc/email/sieve-dovecot-config.conf:

  protocols = pop
  lda_mailbox_autocreate = yes
  lda_mailbox_autosubscribe = yes
  mail_fsync = never

There's no re-sending of emails into my local Postfix SMTP server - I
checked the system logs and confirmed this (journalctl -f).

I suspect that Gnu sieve was directly writing each email to the
appropriate sieve-determined mbox file (perhaps with only a sync at
the end of a single batch process - what I've attempted to achieve
above with sieve-filter), and that sieve-filter is instead passing
each email through some (dovecot) lda?

Here's the output for a sieve-filter batch processing of 11 emails:

$ /usr/bin/sieve-filter -veW -c /home/zen/etc/email/sieve-dovecot-config.conf -o mail_location=mbox:/home/zen/mail:INBOX=/home/zen/mail/Inbox:INDEX=:UTF-8:VOLATILEDIR=/tmp/dovecot-volatile/%2.256Nu/%u:SUBSCRIPTIONS=dovecot_subscriptions /home/zen/etc/email/sieve.rc email-incoming-unsorted
# PS0 Timestamp: 20190912@07:02:23
info: filtering: [Tue, 3 Sep 2019 05:17:16 -0500; 10240 bytes] `Re: VentureBeat: The death of disk? H...'.
info: msgid=<CAMjeLr91T9R7APsuxQVuM3WbqDsxAfwn4=OYDeDX4FMcoRdGdQ@mail.gmail.com>: stored mail into mailbox 'l/cp/cp'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 07:29:53 -0400; 12968 bytes] `[zfs-devel] xattr naming format in Zo...'.
info: msgid=<15675101930.d5ba2E.12322@composer.zfsonlinux.topicbox.com>: stored mail into mailbox 'l/z/zdev'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 03 Sep 2019 15:29:09 +0300; 20461 bytes] `Re: [zfs-devel] xattr naming format i...'.
info: msgid=<23955051567513749@sas1-02732547ccc0.qloud-c.yandex.net>: stored mail into mailbox 'l/z/zdev'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 18:20:42 +0530; 18065 bytes] `Re: [Gluster-users] Issues with Geo-r...'.
info: msgid=<CADmkyZMxrfOANrAP+_URAHJcMqCqh=iGdajTSzkfQ5PCZsUfyg@mail.gmail.com>: stored mail into mailbox 'l/gl/user'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 09:34:20 -0400; 13342 bytes] `Re: tasksel'.
info: msgid=<[🔎] 20190903133420.GS6166@eeg.ccf.org>: stored mail into mailbox 'l/deb/user'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 06:56:07 -0700 (PDT); 12390 bytes] `[awx-project] Re: AWX on Kubernetes m...'.
info: msgid=<0715adb7-540f-4cff-9282-e1252c53c2e8@googlegroups.com>: stored mail into mailbox 'l/ansible/awx'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 07:01:27 -0700 (PDT); 12220 bytes] `[awx-project] Re: AWX on Kubernetes m...'.
info: msgid=<949b2c17-4254-49f1-83b4-cd54d15aa17d@googlegroups.com>: stored mail into mailbox 'l/ansible/awx'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 10:14:58 -0400; 25313 bytes] `Re: [zfs-devel] xattr naming format i...'.
info: msgid=<CAB5c7xpHCdFx1w3yA9FyRL-KQ8BUiCr4JbiDQRuFJj9nOgKxTg@mail.gmail.com>: stored mail into mailbox 'l/z/zdev'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 17:10:22 +0200; 7567 bytes] `Re: [asterisk-users] Playing MP3's in...'.
info: msgid=<20190903151022.354xpe6ds2vglher@red.localdomain>: stored mail into mailbox 'l/as/users'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 01:04:49 +0900; 14858 bytes] `Re: [Hyperledger Fabric] a primitive ...'.
info: msgid=<160901d8-b903-9e9a-91ac-267571b0e24d@gmx.com>: stored mail into mailbox 'l/hl/fabric'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 09:55:22 -0700 (PDT); 13337 bytes] `[awx-project] Re: AWX on Kubernetes m...'.
info: msgid=<f9bc4e6a-8445-4b34-927a-35f577ffcc07@googlegroups.com>: stored mail into mailbox 'l/ansible/awx'.
info: message expunged from source mailbox upon successful move.
2 ▶︎️ zen@eye 20190912@07:02:30 ~ $


So about 3/4 of a second is spent by dovecot's sieve-filter, on each
email that it processes - watching it is painful given how fast Gnu
sieve has been for the last few years - it's almost (but not quite)
as slow as my previous fetchmail email download per-email time.

Attached is a -D debug run of sieve-filter on 20 emails - slightly
longer than the above, and took roughly 15 seconds to run.

Any help appreciated...

sieve-filter(zen): Debug: sieve: Pigeonhole version 0.5.4 () initializing
sieve-filter(zen): Debug: sieve: include: sieve_global is not set; it is currently not possible to include `:global' scripts.
debug: file storage: Using Sieve script path: /home/zen/etc/email/sieve.rc.
debug: file script: Opened script `sieve.rc' from `/home/zen/etc/email/sieve.rc'.
debug: Script binary /home/zen/etc/email/sieve.rc.svbin successfully loaded.
debug: binary save: not saving binary /home/zen/etc/email/sieve.rc.svbin, because it is already stored.
info: filtering: [Tue, 03 Sep 2019 22:30:31 +0200; 11609 bytes] `Re: AMD Vega 6 on Debian 10'.
info: msgid=<[🔎] 87h85t2kd4.fsf@turtle.gmx.de>: stored mail into mailbox 'l/deb/user'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 03 Sep 2019 21:14:09 +0000; 7815 bytes] `[Xfce-bugs] [Bug 15917] Thunar SendTo...'.
info: msgid=<bug-15917-521-VMobV3KAzY@https.bugzilla.xfce.org/>: stored mail into mailbox 'l/xfce-bugs'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 03 Sep 2019 21:39:23 +0000; 7016 bytes] `[Xfce-bugs] [Bug 15917] Thunar SendTo...'.
info: msgid=<bug-15917-521-hgmtigEEJu@https.bugzilla.xfce.org/>: stored mail into mailbox 'l/xfce-bugs'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 17:16:29 -0600; 14428 bytes] `[Freeswitch-users] Register-transport...'.
info: msgid=<CA+wj8uYcotMAAig_2suoy7Pz9oMR5wCVPcZ-v5WuSetZerLFfA@mail.gmail.com>: stored mail into mailbox 'l/fs/users'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 03 Sep 2019 23:53:52 +0000; 8738 bytes] `[Xfce-bugs] [Bug 15172] Clicking on M...'.
info: msgid=<bug-15172-521-82B3nkrJ1C@https.bugzilla.xfce.org/>: stored mail into mailbox 'l/xfce-bugs'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Tue, 3 Sep 2019 19:07:47 -0500; 19469 bytes] `Re: [zfs-devel] xattr naming format i...'.
info: msgid=<922dfa0b-77e6-1037-2e81-94fb772eac7b@wiktel.com>: stored mail into mailbox 'l/z/zdev'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 03:09:43 +0000; 51294 bytes] `=?utf-8?Q?Your=20Weekly=20Dose=20Of=2...'.
info: msgid=<fca99a20c3621371bc4cf1f36.84251c9f9e.20190904030912.951596549c.4bb7cbe5@mail24.atl11.rsgsv.net>: left message in mailbox 'email-incoming-unsorted'.
info: message kept in source mailbox.
info: filtering: [Tue, 03 Sep 2019 21:09:52 -0700; 11180 bytes] `911TrutherFunnies: Forklift hits WTC ...'.
info: msgid=<CB9B673C-19D7-442C-8900-EA30C896363B@riseup.net>: stored mail into mailbox 'l/cp/cp'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 01:27:54 -0300; 7792 bytes] `Re: 911TrutherFunnies: Forklift hits ...'.
info: msgid=<20190904042541.6BFA092C1D723@cock.li>: stored mail into mailbox 'l/cp/cp'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 16:10:44 +0900; 19913 bytes] `Re: [Freeswitch-users] Register-trans...'.
info: msgid=<CAGJLwFj66Jfymu36KujTgFe8LP+LCFpBjoZSBZR3_QWr1uLHnA@mail.gmail.com>: stored mail into mailbox 'l/fs/users'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 04 Sep 2019 07:28:38 +0000; 10366 bytes] `[Xfce-bugs] [Bug 15917] Thunar SendTo...'.
info: msgid=<bug-15917-521-jc3wdnpESM@https.bugzilla.xfce.org/>: stored mail into mailbox 'l/xfce-bugs'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 11:32:11 +0300; 10377 bytes] `Re: [OSGeo Oceania] membership - elec...'.
info: msgid=<CAHY5hn_OhgaH==GV0Y47xZ84rVJjpZf-XCfWe_nk0t-z29RvmQ@mail.gmail.com>: stored mail into mailbox 'l/wireless.aust-nz'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 09:01:05 +0000 (UTC); 28831 bytes] `[asterisk-users] SIP trunk problem: M...'.
info: msgid=<637726953.2368317.1567587665434@mail.yahoo.com>: stored mail into mailbox 'l/as/users'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 04 Sep 2019 12:21:04 +0300; 13976 bytes] `Re: [Gluster-users] Geo-Replication w...'.
info: msgid=<v7xug17438ljasvk9va93drv.1567588864248@email.android.com>: stored mail into mailbox 'l/gl/user'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 04 Sep 2019 12:20:18 +0300; 8163 bytes] `Re: [Gluster-users] Geo-Replication  ...'.
info: msgid=<04c8bl33p672akyja74s7dd4.1567588818703@email.android.com>: stored mail into mailbox 'l/gl/user'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 12:47:16 +0300; 14199 bytes] `Re: [Hyperledger Fabric] a primitive ...'.
info: msgid=<CAPg-4YUpmdU2VcXdPgm0di9CtG9rB0oeeYytKgJy36ciSckGDA@mail.gmail.com>: stored mail into mailbox 'l/hl/fabric'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 05:59:44 -0400; 15433 bytes] `Re: [Hyperledger Fabric] a primitive ...'.
info: msgid=<CAE6nKwQ-Kyn8xLo6+x+p3hqDeeVP_T_UJE79686u-otyESGfoQ@mail.gmail.com>: stored mail into mailbox 'l/hl/fabric'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 12:01:37 +0200; 48853 bytes] `Re: [GRASS-user] sample a strds at sp...'.
info: msgid=<CABa=8QrL9GDF8p2dTsaAxHRbz0SnOqGp3=DhUYW2og_+3yvQvg@mail.gmail.com>: stored mail into mailbox 'l/grass-user'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 04 Sep 2019 06:43:43 -0300; 11311 bytes] `Re: [asterisk-users]? =?utf-8?q?SIP_t...'.
info: msgid=<4b5d55c8-b3f5-4084-a2f0-42453a139b5b@www.fastmail.com>: stored mail into mailbox 'l/as/users'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 03:42:04 -0700 (PDT); 149741 bytes] `[awx-project] Re: AWX on Kubernetes m...'.
info: msgid=<e1ad68c7-0263-40f7-8fd0-903ce3f5769e@googlegroups.com>: stored mail into mailbox 'l/ansible/awx'.
info: message expunged from source mailbox upon successful move.
info: filtering: [Wed, 4 Sep 2019 21:28:01 +1000; 12360 bytes] `Re: [OSGeo Oceania] membership - elec...'.
info: msgid=<13f401c2-7f97-44e8-32e5-868d150f153e@gmail.com>: stored mail into mailbox 'l/wireless.aust-nz'.
info: message expunged from source mailbox upon successful move.

Reply to:

Follow-Ups:
- Re: Gnu sieve vs Dovecot sieve-filter - sieve-filter extremely slow at lda (writing emails to local mbox files)
  - From: Zenaan Harkness <zenaan@freedbms.net>

Prev by Date: Re: Problem enabling IOMMU with Buster and Xen
Next by Date: Re: Gnu sieve vs Dovecot sieve-filter - sieve-filter extremely slow at lda (writing emails to local mbox files)
Previous by thread: Re: Trapped in Gnome
Next by thread: Re: Gnu sieve vs Dovecot sieve-filter - sieve-filter extremely slow at lda (writing emails to local mbox files)
Index(es):
- Date
- Thread