Hi,
We're migrating our mailboxes from Zimbra to dovecot, running on FreeBSD 12.2. We're using mdbox and solr for fts. dovecot version 2.3.17.
One of our mailboxes gets a bcc of every outgoing mail from our system and it currently holds ~4.5 million messages taking 30 GB.
One of the ways we use the mailbox is that when outgoing mail is sent,
we store the Message-ID in our database, and in our admin interface we
can open the mail and it's fetched from IMAP by doing a 'SEARCH HEADER
Message-ID
In Zimbra this was reasonably fast, but after migrating the mailbox to dovecot it's 30 seconds which I think we can reduce.
After turning on mail_debug I see this in our log https://pastebin.com/kP9H7gSB
Looks like solr finishes searching instantly, then there's ~30 seconds of silence in the logs, and then more log lines about fetching data from mail cache.
The same thing happens if I use telnet and just issue a 'SEARCH HEADER...' command.
How can I find out what dovecot is doing in those 30 seconds?
.einar
On 1. Dec 2021, at 0.30, Einar Bjarni Halldórsson einar@isnic.is wrote:
Hi,
We're migrating our mailboxes from Zimbra to dovecot, running on FreeBSD 12.2. We're using mdbox and solr for fts. dovecot version 2.3.17.
One of our mailboxes gets a bcc of every outgoing mail from our system and it currently holds ~4.5 million messages taking 30 GB.
One of the ways we use the mailbox is that when outgoing mail is sent, we store the Message-ID in our database, and in our admin interface we can open the mail and it's fetched from IMAP by doing a 'SEARCH HEADER Message-ID
'. In Zimbra this was reasonably fast, but after migrating the mailbox to dovecot it's 30 seconds which I think we can reduce.
After turning on mail_debug I see this in our log https://pastebin.com/kP9H7gSB
Looks like solr finishes searching instantly, then there's ~30 seconds of silence in the logs, and then more log lines about fetching data from mail cache.
The same thing happens if I use telnet and just issue a 'SEARCH HEADER...' command.
How can I find out what dovecot is doing in those 30 seconds?
Did you have Messsage-ID listed in mail_always_cache_fields when you imported the mailbox? Do you have it now?
If not, please add it and then use doveadm fetch to populate that in cache.
I think the correct setting is
mail_always_cache_fields = hdr.message-id
But you also might want to add some other fields
Sami
Did you have Messsage-ID listed in mail_always_cache_fields when you imported the mailbox? Do you have it now?
If not, please add it and then use doveadm fetch to populate that in cache.
I think the correct setting is
mail_always_cache_fields = hdr.message-id
But you also might want to add some other fields I didn't have it in mail_always_cache_fields, but I had looked at doveadm mailbox cache decision and seen the fields mentioned in the log as being in cache as temp.
I just tried adding hdr.MESSAGE-ID to mail_always_cache_fields and tried to fetch but with the same result. Good idea though. doveadm cache decision only tells me what dovecot will try to keep in cache, is there some why of inspecting the cache itself to know what is stored there? I've had to raise vsz_limit because of out of memory situations, so maybe the cache is corrupt? Nothing about it in logs though.
.einar
On 1. Dec 2021, at 10.59, Einar Bjarni Halldórsson einar@isnic.is wrote:
Did you have Messsage-ID listed in mail_always_cache_fields when you imported the mailbox? Do you have it now?
If not, please add it and then use doveadm fetch to populate that in cache.
I think the correct setting is
mail_always_cache_fields = hdr.message-id
But you also might want to add some other fields I didn't have it in mail_always_cache_fields, but I had looked at doveadm mailbox cache decision and seen the fields mentioned in the log as being in cache as temp.
I just tried adding hdr.MESSAGE-ID to mail_always_cache_fields and tried to fetch but with the same result. Good idea though. doveadm cache decision only tells me what dovecot will try to keep in cache, is there some why of inspecting the cache itself to know what is stored there? I've had to raise vsz_limit because of out of memory situations, so maybe the cache is corrupt? Nothing about it in logs though.
Adding it to mail_always_cache_fields does not miraculously make cache updated. Each mail needs to be accessed for that to happen. Ie. With doveadm fetch.
You can inspect the index files with doveadm dump to check what is cached. Not sure how it went with mdbox storage driver.
Sami
Adding it to mail_always_cache_fields does not miraculously make cache updated. Each mail needs to be accessed for that to happen. Ie. With doveadm fetch. I couldn't figure out the doveadm fetch syntax for searching so I just ran the search manually twice. I assume that would update the cache? You can inspect the index files with doveadm dump to check what is cached. Not sure how it went with mdbox storage driver. According to
man doveadm-dumpit just seems to dump index files. I tried dumping the cache file but it complains that it can't auto detect the file type.
.einar
On 01/12/2021 13:05 Einar Bjarni Halldórsson einar@isnic.is wrote:
Adding it to mail_always_cache_fields does not miraculously make cache updated. Each mail needs to be accessed for that to happen. Ie. With doveadm fetch. I couldn't figure out the doveadm fetch syntax for searching so I just ran the search manually twice. I assume that would update the cache? You can inspect the index files with doveadm dump to check what is cached. Not sure how it went with mdbox storage driver. According to
man doveadm-dumpit just seems to dump index files. I tried dumping the cache file but it complains that it can't auto detect the file type..einar
doveadm fetch -u username hdr.message-id all
Aki
Adding it to mail_always_cache_fields does not miraculously make cache updated. Each mail needs to be accessed for that to happen. Ie. With doveadm fetch.
doveadm fetch -u username hdr.message-id all
Tried that and also tried deleting the dovecot.index.cache and running again, same result.
The cache file is around 1 G 1070635444 Dec 1 12:06 dovecot.index.cache
It could be hitting the 1 GB limit on cache file size, but I assume this would show in the logs? If this is the reason, is there any way around it?
.einar
On 1. Dec 2021, at 13.05, Einar Bjarni Halldórsson einar@isnic.is wrote:
Adding it to mail_always_cache_fields does not miraculously make cache updated. Each mail needs to be accessed for that to happen. Ie. With doveadm fetch. I couldn't figure out the doveadm fetch syntax for searching so I just ran the search manually twice. I assume that would update the cache? You can inspect the index files with doveadm dump to check what is cached. Not sure how it went with mdbox storage driver. According to
man doveadm-dumpit just seems to dump index files. I tried dumping the cache file but it complains that it can't auto detect the file type.
Try this:
[root@ketola .INBOX]# pwd /vmail/sami@ketola.io/index/.INBOX [root@ketola .INBOX]# doveadm dump . | grep -c hdr.message-id 11007
This is Maildir, but it should work the same way with mdbox.
Sami
You can inspect the index files with doveadm dump to check what is cached. Not sure how it went with mdbox storage driver. According to
man doveadm-dumpit just seems to dump index files. I tried dumping the cache file but it complains that it can't auto detect the file type.Try this:
[root@ketola .INBOX]# pwd /vmail/sami@ketola.io/index/.INBOX [root@ketola .INBOX]# doveadm dump . | grep -c hdr.message-id 11007
root@ht-mailstore01:/data/mail/hostmasterlog/mdbox/mailboxes/INBOX/dbox-Mails # doveadm dump . | grep -c hdr.MESSAGE-ID 4464736
In dovecot config I have fts_enforced = yes and after the search for
Message-ID finishes and returns UID, I can do a FETCH .. ENVELOPE on it
and it responds immediately.
I was under the impression that fts_enforced forces all searches,
headers and body, to go to solr. Then all dovecot would have to do was
to return the UID returned by solr.
Unless solr doesn't return UID and dovecot has to take the result from
solr and lookup the UID, and with a full 1 GB cache file it always has
to scan the whole index?
Nothing seems to be completely broken, I always receive a result, it's just that it takes 30 seconds when I really want it to be ~5 seconds at most.
I guess if we can't find a solution and 30 seconds becomes a real problem, we'll split the mailbox up by years. It should help with the size of the cache. It makes the searching code a little more complicated since it has to figure out the sent date before it can search, but it's doable.
.einar
On 2. Dec 2021, at 10.57, Einar Bjarni Halldórsson einar@isnic.is wrote: root@ht-mailstore01:/data/mail/hostmasterlog/mdbox/mailboxes/INBOX/dbox-Mails # doveadm dump . | grep -c hdr.MESSAGE-ID 4464736
In dovecot config I have
fts_enforced = yesand after the search for Message-ID finishes and returns UID, I can do a FETCH .. ENVELOPE on it and it responds immediately. I was under the impression that fts_enforced forces all searches, headers and body, to go to solr. Then all dovecot would have to do was to return the UID returned by solr. Unless solr doesn't return UID and dovecot has to take the result from solr and lookup the UID, and with a full 1 GB cache file it always has to scan the whole index?Nothing seems to be completely broken, I always receive a result, it's just that it takes 30 seconds when I really want it to be ~5 seconds at most.
I guess if we can't find a solution and 30 seconds becomes a real problem, we'll split the mailbox up by years. It should help with the size of the cache. It makes the searching code a little more complicated since it has to figure out the sent date before it can search, but it's doable.
If you have fts_enforced = yes then that SEARCH probably goes to solr even if message-id is found from cache. So the delay is probably on solr side.
Can you try to remove fts_enforced for that one particular user?
Sami
If you have fts_enforced = yes then that SEARCH probably goes to solr even if message-id is found from cache. So the delay is probably on solr side.
Can you try to remove fts_enforced for that one particular user?
I only added fts_enforced yesterday. When I sent the original post I wasn't running with fts_enforced.
I did finally manage to query solr with curl with the query dovecot issues and I get this response:
<?xml version="1.0" encoding="UTF-8"?>
<response>
<lst name="responseHeader"> <int name="status">0</int> <int name="QTime">1</int> <lst name="params"> <str name="json">{ "params": { "q": "{!lucene q.op=AND} hdr:<64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg@min.isnic.is>", "fl": "uid,score", "sort": "uid asc", "fq": "+box:c92f64f79f0d1ed01e6d5b314f04886c +user:hostmasterlog", "rows": 5327110, "wt": xml }}</str> </lst> </lst> <result name="response" numFound="1" start="0" maxScore="131.64821" numFoundExact="true"> <doc> <long name="uid">5166713</long> <float name="score">131.64821</float></doc> </result> </response>
--
If I search for the UID I get
-- 3 fetch 5166713 ENVELOPE 3 BAD Error in IMAP command FETCH: Invalid messageset (0.001 + 0.000 secs).
If I run the search in IMAP I get
-- 4 SEARCH HEADER Messgage-ID 64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg@min.isnic.is
- SEARCH
- 4465180 EXISTS
88 RECENT 4 OK Search completed (29.674 + 0.000 + 29.523 secs).
Isn't it likely that the dovecot index and solr index are out of sync? Solr seems to point to a UID that doesn't exist in dovecot. If so, how can I fix it?
.einar
If I search for the UID I get
-- 3 fetch 5166713 ENVELOPE 3 BAD Error in IMAP command FETCH: Invalid messageset (0.001 + 0.000 secs).
If I run the search in IMAP I get
-- 4 SEARCH HEADER Messgage-ID 64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg@min.isnic.is
- SEARCH
- 4465180 EXISTS
88 RECENT 4 OK Search completed (29.674 + 0.000 + 29.523 secs).
I just realised I'm misreading the return from the search. Redid it and this is from telnet
-- 3 search header MESSAGE-ID 64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg
SEARCH 4327049 3 OK Search completed (28.955 + 0.000 + 28.837 secs).
Same search from command line
-- doveadm search -u hostmasterlog mailbox INBOX HEADER MESSAGE-ID 64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg c92f64f79f0d1ed01e6d5b314f04886c 5166713
.einar
Why are you still going through Dovecot for this ?
@ 4.5 million messages you could just reprogram your app to search solr directly, it will return the uid of the message and you can use that directly in imap uid fetch.
Scott
-----Original Message----- From: dovecot dovecot-bounces@dovecot.org On Behalf Of Einar Bjarni Halldórsson Sent: Thursday, December 2, 2021 7:47 AM To: dovecot@dovecot.org Subject: Re: Searching 30 GB mailbox
If I search for the UID I get
-- 3 fetch 5166713 ENVELOPE 3 BAD Error in IMAP command FETCH: Invalid messageset (0.001 + 0.000 secs).
If I run the search in IMAP I get
-- 4 SEARCH HEADER Messgage-ID 64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg@min.isnic.is
- SEARCH
- 4465180 EXISTS
88 RECENT 4 OK Search completed (29.674 + 0.000 + 29.523 secs).
I just realised I'm misreading the return from the search. Redid it and this is from telnet
-- 3 search header MESSAGE-ID 64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg
SEARCH 4327049 3 OK Search completed (28.955 + 0.000 + 28.837 secs).
Same search from command line
-- doveadm search -u hostmasterlog mailbox INBOX HEADER MESSAGE-ID 64jf4CStuxzUvATjBbRVP3IbJnMbEguVXzOa1OSmjIg c92f64f79f0d1ed01e6d5b314f04886c 5166713
.einar
Why are you still going through Dovecot for this ?
@ 4.5 million messages you could just reprogram your app to search solr directly, it will return the uid of the message and you can use that directly in imap uid fetch. That is a good idea. If this becomes a showstopper, that's one way we could solve this.
.einar
Am 03.12.21 um 13:34 schrieb Einar Bjarni Halldórsson:
Why are you still going through Dovecot for this ?
@ 4.5 million messages you could just reprogram your app to search solr directly, it will return the uid of the message and you can use that directly in imap uid fetch.
That is a good idea. If this becomes a showstopper, that's one way we could solve this.
Below link to a javascript "app", that does it this way. When dovecot caches are warm, it is very quick. That on a not so big a number of mails, but still quite impressive :)
https://gist.github.com/hungerburg/00d582bf1a6bf3c622797bf5e759f75b
-- peter
participants (5)
-
Aki Tuomi
-
Einar Bjarni Halldórsson
-
Peter
-
Sami Ketola
-
Scott