search

grosjo / fts-xapian

Dovecot FTS plugin based on Xapian
GNU Lesser General Public License v2.1
97 stars 21 forks source link

Starting the indexing stops Mail delivery #89

Closed LuftschloesserUser closed 3 years ago

LuftschloesserUser commented 3 years ago

Hello and thanks for your work!

I just tried to implement fts-xapian. But had to stop as I am doing this on a production server.

I installed from a fresh clone on a Ubuntu Bionic with dovecot 1:2.2.33.2-1ubuntu4.7 Symptoms are: If I enable fts and restart dovecot mail delivery still works and load is fine. As I start the indexing with this: doveadm fts rescan -u username Mails the are not longer received by dovecot and load goes up to 4 from 0.20 something. I have users here with big inboxes from about 20Gb

Any hints on what I am doing wrong?

If this is noct the right place to discuss this, please let me know.

Thanks

Martin

iredmail commented 3 years ago

I didn't have such issue with a 28GB mailbox. Maybe turn on debug mode while running 'doveadm' and check again? Also, any related error/warning in Dovecot log file?

doveadm -D ...
LuftschloesserUser commented 3 years ago

No warnings in the logfiles as far as I have seen. I will try debugmode on the weekend with less impact on users. Thanks for the hint!

iredmail commented 3 years ago

btw, how did you install fts-xapian on Ubuntu bionic? Compile from source package?

LuftschloesserUser commented 3 years ago

I compiled from source and used this howto: https://b4d.sablun.org/blog/2020-08-18-dovecot-full-text-search/

grosjo commented 3 years ago

A log file with "verbose=2" would help indeed

LuftschloesserUser commented 3 years ago

Thanks! I will try this tomorrow and will report back.

grosjo commented 3 years ago

any news ?

LuftschloesserUser commented 3 years ago

Sorry for the delay. I had to postpone the test until today. first mail delivery was working after enabling fts_xapian. Then i launched the rescan and it was still working, but I had enabled verbose=1 before and I saw it was bumping into the memory limit of dovecot. I upped it to 2 G and ran again. I ran the rescan again and it did not show up in top after that which I did not quite understood why. After running a search via my phone with fairmail client, I saw the indexer in top and got a timeout via phone search. Mail is now queuing since 10min. so no delivery. I will be back in an hour or so and let it run like this, maybe it just needs some time?

LuftschloesserUser commented 3 years ago

Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_index_text Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: NGRAM(body,XBDY) -> 728 items, max length=16, (total 4 KB) Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_update_unset_build_key Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Memory stats : Used = 529 MB (25%) (4312 pushes), Limit = 2048 MB, Free = 6931 MB, Additional data 0 KB, Estimated required = 1059 MB Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_index_hdr Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Ngram(S) -> 53 items (total 0 KB) Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_update_unset_build_key Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Memory stats : Used = 529 MB (25%) (4313 pushes), Limit = 2048 MB, Free = 6931 MB, Additional data 0 KB, Estimated required = 1059 MB Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_index_hdr Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Ngram(XTO) -> 165 items (total 1 KB) Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_update_unset_build_key Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Memory stats : Used = 529 MB (25%) (4314 pushes), Limit = 2048 MB, Free = 6931 MB, Additional data 0 KB, Estimated required = 1059 MB Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_index_hdr Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Ngram(A) -> 67 items (total 0 KB) Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_update_unset_build_key Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Memory stats : Used = 529 MB (25%) (4315 pushes), Limit = 2048 MB, Free = 6931 MB, Additional data 0 KB, Estimated required = 1059 MB Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_index_hdr Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Ngram(XMID) -> 4 items (total 0 KB) Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_update_unset_build_key Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: Memory stats : Used = 529 MB (25%) (4316 pushes), Limit = 2048 MB, Free = 6931 MB, Additional data 5 KB, Estimated required = 1059 MB Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: fts_backend_xapian_index_text Jul 4 18:14:35 cloud dovecot: indexer-worker(username): FTS Xapian: NGRAM(body,XBDY) -> 5458 items, max length=22, (total 37 KB)

LuftschloesserUser commented 3 years ago

btw: outgoing mail is working. Just incoming is deferred.

grosjo commented 3 years ago

Can you run "ps aux | grep dovecot" ? Do you see the same behavior with "doveadm index -A -q *" ?

LuftschloesserUser commented 3 years ago 
root     32357  0.0  0.0  18528  3308 ?        Ss   18:51   0:00 /usr/sbin/dovecot -F
dovecot  32359  0.0  0.0   9880  1080 ?        S    18:51   0:00 dovecot/anvil
root     32360  0.4  0.0  10012  2540 ?        S    18:51   0:01 dovecot/log
root     32362  0.0  0.0  25820  4096 ?        S    18:51   0:00 dovecot/config
dovenull 32366  0.0  0.0  22160  5824 ?        S    18:51   0:00 dovecot/imap-login
dovecot  32367  0.0  0.0  23120  3196 ?        S    18:51   0:00 dovecot/auth
dovenull 32369  0.0  0.0  22160  5696 ?        S    18:51   0:00 dovecot/imap-login
ule      32371  0.0  0.0  92036  8348 ?        S    18:51   0:00 dovecot/imap
ule      32372  0.0  0.0  92040  8276 ?        S    18:51   0:00 dovecot/imap
dovecot  32380  0.0  0.0   9884  1136 ?        S    18:51   0:00 dovecot/indexer
martin   32381 28.6  1.6 371552 273376 ?       D    18:51   1:18 dovecot/indexer-worker
martin   32390  0.0  0.0  95260 10220 pts/0    S    18:51   0:00 /usr/lib/dovecot/deliver -e -d martin
martin   32441  0.0  0.0  92784  9728 ?        S    18:52   0:00 dovecot/imap
dovenull 32442  0.0  0.0  22160  5828 ?        S    18:52   0:00 dovecot/imap-login
martin   32443  0.0  0.0  92032  8220 ?        S    18:52   0:00 dovecot/imap
dovenull 32444  0.0  0.0  22160  5716 ?        S    18:52   0:00 dovecot/imap-login
martin   32445  0.0  0.0  92108  9156 ?        S    18:52   0:00 dovecot/imap
dovenull 32446  0.0  0.0  22160  5660 ?        S    18:52   0:00 dovecot/imap-login
martin   32447  0.0  0.0  92180  9112 ?        S    18:52   0:00 dovecot/imap
dovenull 32465  0.0  0.0  22160  5856 ?        S    18:52   0:00 dovecot/imap-login
manuel   32466  0.0  0.0  92524  9396 ?        S    18:52   0:00 dovecot/imap
martin   32507  0.0  0.0  92784  9744 ?        S    18:53   0:00 dovecot/imap
dovenull 32510  0.0  0.0  22160  5832 ?        S    18:54   0:00 dovecot/imap-login
martin   32511  0.0  0.0  92932  9996 ?        S    18:54   0:00 dovecot/imap
dovenull 32539  0.0  0.0  22160  5720 ?        S    18:55   0:00 dovecot/imap-login
root     32540  0.0  0.0   9876  1084 ?        S    18:55   0:00 dovecot/ssl-params
root     32541  0.0  0.0  35972  4224 ?        S    18:55   0:00 dovecot/auth -w
martin   32542  0.0  0.0  92784  9636 ?        S    18:55   0:00 dovecot/imap
root     32546  0.0  0.0  13472  1084 pts/0    S+   18:56   0:00 grep --color=auto dovecot
LuftschloesserUser commented 3 years ago

after running doveadm index -A -q *

root     32357  0.0  0.0  18528  3308 ?        Ss   18:51   0:00 /usr/sbin/dovecot -F
dovecot  32359  0.0  0.0   9880  1080 ?        S    18:51   0:00 dovecot/anvil
root     32360  0.2  0.0  10012  2540 ?        S    18:51   0:01 dovecot/log
root     32362  0.0  0.0  26000  4224 ?        S    18:51   0:00 dovecot/config
dovenull 32366  0.0  0.0  22160  5824 ?        S    18:51   0:00 dovecot/imap-login
dovecot  32367  0.0  0.0  23120  3196 ?        S    18:51   0:00 dovecot/auth
dovenull 32369  0.0  0.0  22160  5696 ?        S    18:51   0:00 dovecot/imap-login
ule      32371  0.0  0.0  92036  8348 ?        S    18:51   0:00 dovecot/imap
ule      32372  0.0  0.0  92040  8276 ?        S    18:51   0:00 dovecot/imap
dovecot  32380  0.0  0.0  10016  1136 ?        S    18:51   0:00 dovecot/indexer
martin   32381 14.2  1.6 371552 273396 ?       D    18:51   1:21 dovecot/indexer-worker
dovenull 32442  0.0  0.0  22160  5828 ?        S    18:52   0:00 dovecot/imap-login
martin   32443  0.0  0.0  92032  8220 ?        S    18:52   0:00 dovecot/imap
dovenull 32444  0.0  0.0  22160  5716 ?        S    18:52   0:00 dovecot/imap-login
martin   32445  0.0  0.0  92108  9156 ?        S    18:52   0:00 dovecot/imap
martin   32551  0.0  0.0  92784  9728 ?        S    18:57   0:00 dovecot/imap
root     32623  0.0  0.0  38128  4224 ?        S    18:59   0:00 dovecot/auth -w
emu      32624  2.8  0.1  98816 19796 ?        D    18:59   0:03 dovecot/indexer-worker
danielf+ 32625  0.0  0.0  89708  8216 ?        S    18:59   0:00 dovecot/indexer-worker
flo      32626  1.0  0.0  95100 16036 ?        D    18:59   0:01 dovecot/indexer-worker
hussein  32627  3.6  0.2 118696 39684 ?        D    18:59   0:04 dovecot/indexer-worker
manuel   32628  3.5  0.1 101388 22316 ?        D    18:59   0:04 dovecot/indexer-worker
ule      32629  0.8  0.0  94928 15916 ?        D    18:59   0:01 dovecot/indexer-worker
dovenull 32636  0.0  0.0  22160  5708 ?        S    19:00   0:00 dovecot/imap-login
martin   32637  0.0  0.0  92784  9332 ?        S    19:00   0:00 dovecot/imap
LuftschloesserUser commented 3 years ago 
Jul  4 19:03:11 cloud dovecot: indexer-worker(manuel): FTS Xapian: Memory stats : Used = 121 MB (2%) (1 pushes), Limit = 4096 MB, Free = 188 MB, Additional data 7 KB, Estimated required = 242 MB
Jul  4 19:03:11 cloud dovecot: indexer-worker(manuel): FTS Xapian: Warning Low memory
Jul  4 19:03:11 cloud dovecot: indexer-worker(manuel): FTS Xapian: fts_backend_xapian_release (Low memory indexing)
Jul  4 19:03:12 cloud dovecot: indexer-worker(flo): FTS Xapian: Committed 'Low memory indexing' in 1001 ms

Why is there a low memory warning?

LuftschloesserUser commented 3 years ago

running doveadm index -A -q *

gets the same outcome. Load is currently at about 7. maybe the disks are just slow old disks?

LuftschloesserUser commented 3 years ago

thats what exim is saying:

R=localuser T=dovecot_delivery defer (0): Child process of dovecot_delivery transport returned 75 (
could mean temporary error) from command: /usr/lib/dovecot/deliver
grosjo commented 3 years ago

thats what exim is saying:

R=localuser T=dovecot_delivery defer (0): Child process of dovecot_delivery transport returned 75 (
could mean temporary error) from command: /usr/lib/dovecot/deliver

And do you see the related error in dovecot log ?

LuftschloesserUser commented 3 years ago

So i found this in my sieve log:

 msgid=<grosjo/fts-xapian/issues/89/873632783@github.com>: failed to store into mailbox 'INBOX': Timeout while waiting for lock.

Still searching....

LuftschloesserUser commented 3 years ago

It seems to be IO-related. iotop shows the indexing processes at 99%

is it possible to see how much of an Inbox is already indexed?

grosjo commented 3 years ago

Please use latest git, and grep for "docs" in the logs (provided you have verbose=1)

grosjo commented 3 years ago 
Jul  4 19:03:11 cloud dovecot: indexer-worker(manuel): FTS Xapian: Memory stats : Used = 121 MB (2%) (1 pushes), Limit = 4096 MB, Free = 188 MB, Additional data 7 KB, Estimated required = 242 MB
Jul  4 19:03:11 cloud dovecot: indexer-worker(manuel): FTS Xapian: Warning Low memory
Jul  4 19:03:11 cloud dovecot: indexer-worker(manuel): FTS Xapian: fts_backend_xapian_release (Low memory indexing)
Jul  4 19:03:12 cloud dovecot: indexer-worker(flo): FTS Xapian: Committed 'Low memory indexing' in 1001 ms

Why is there a low memory warning?

What are your server specs (in terms of RAM) ?

LuftschloesserUser commented 3 years ago 
free -h
              total        used        free      shared  buff/cache   available
Mem:            15G        1.6G        302M         68M         13G         13G
Swap:          8.0G         16M        8.0G
grosjo commented 3 years ago 
free -h
              total        used        free      shared  buff/cache   available
Mem:            15G        1.6G        302M         68M         13G         13G
Swap:          8.0G         16M        8.0G

Can you type "cat /proc/meminfo" ?

LuftschloesserUser commented 3 years ago

cat /proc/meminfo MemTotal: 16126948 kB MemFree: 205580 kB MemAvailable: 14232248 kB Buffers: 964196 kB Cached: 11738240 kB SwapCached: 4344 kB Active: 4995048 kB Inactive: 9023540 kB Active(anon): 891180 kB Inactive(anon): 499308 kB Active(file): 4103868 kB Inactive(file): 8524232 kB Unevictable: 9956 kB Mlocked: 9956 kB SwapTotal: 8380412 kB SwapFree: 8363248 kB Dirty: 1392 kB Writeback: 12752 kB AnonPages: 1321892 kB Mapped: 178360 kB Shmem: 69804 kB Slab: 1786900 kB SReclaimable: 1728416 kB SUnreclaim: 58484 kB KernelStack: 5376 kB PageTables: 24768 kB NFS_Unstable: 0 kB Bounce: 0 kB WritebackTmp: 0 kB CommitLimit: 16443884 kB Committed_AS: 2656420 kB VmallocTotal: 34359738367 kB VmallocUsed: 0 kB VmallocChunk: 0 kB HardwareCorrupted: 0 kB AnonHugePages: 0 kB ShmemHugePages: 0 kB ShmemPmdMapped: 0 kB CmaTotal: 0 kB CmaFree: 0 kB HugePages_Total: 0 HugePages_Free: 0 HugePages_Rsvd: 0 HugePages_Surp: 0 Hugepagesize: 2048 kB DirectMap4k: 1007132 kB DirectMap2M: 15468544 kB

LuftschloesserUser commented 3 years ago

did not find "docs" in the logfile until now. i used ionice to put it down to "idle" but it did noct help.

grosjo commented 3 years ago

did not find "docs" in the logfile until now. i used ionice to put it down to "idle" but it did noct help.

Are you compiling from git (I made updates just now) ?

LuftschloesserUser commented 3 years ago

i did, but just do again

LuftschloesserUser commented 3 years ago

ok, so i was to early. building with changes now

LuftschloesserUser commented 3 years ago 
Jul  4 22:05:47 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5034 docs in the index
Jul  4 22:05:47 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5034 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5034 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5035 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5035 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5035 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5035 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(manuel): FTS Xapian: fts_backend_xapian_update_unset_build_key with 1096 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5035 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5036 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5036 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5036 docs in the index
Jul  4 22:05:48 cloud dovecot: indexer-worker(emu): FTS Xapian: fts_backend_xapian_update_unset_build_key with 5036 docs in the index
LuftschloesserUser commented 3 years ago

So i recompiled, started all again and still have high load, but mail is delivered.!

LuftschloesserUser commented 3 years ago

IO went down. iotop still shows some, but not as high as before. Now I see the indexing processes at 100%cpu, which was not the case before.

grosjo commented 3 years ago

Yes, it seems the detection of the free memory was buggy, and the plugin kept flushing on disk, which destroyed the performance

LuftschloesserUser commented 3 years ago

Great! Thanks a lot for this support! Can I spend you a beer or something ?

LuftschloesserUser commented 3 years ago

send me a paypal or patreon or something please.

grosjo commented 3 years ago

send me a paypal or patreon or something please.

Just promote the plugin around, that would be much more usefull :)

LuftschloesserUser commented 3 years ago

Ok, will do :)

To see if it works, I guess i have to wait until the indexing is finished right?

grosjo commented 3 years ago

Yes. Initial indexing takes some time (scan of all existing emails), then indexing is done on the fly

grosjo commented 3 years ago

Are things going well ? if yes, let's close the issue

LuftschloesserUser commented 3 years ago

Thanks so much! Search is incredibly fast now and very reliable. It even finds German ö :)