Re: out of memory on idle machine

[Gregor Zattler <telegraph@gmx.net>]

Hi David, notmuch and xapian developers,
* David Bremner <david@tethera.net> [03. Feb. 2021]:
> Gregor Zattler <telegraph@gmx.net> writes:
>>
>> Installed notmuch-dbgsym (0.28.4-1) and gdb.
>>
>> grfz@mic:/etc$ gdb --args notmuch new
>> [...]
>> (gdb) b notmuch-new.c:420
>> Breakpoint 1 at 0x10601: file notmuch-new.c, line 421.
>> (gdb) run
>> Starting program: /usr/bin/notmuch new
>> [Thread debugging using libthread_db enabled]
>> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
>> add_file: A Xapian exception occurred
>> A Xapian exception occurred finding message: Db block overwritten - are there multiple writers?.
>> Processed 24 total files in almost no time.
>> Added 23 new messages to the database.
>> Note: A fatal error was encountered: A Xapian exception occurred
>> [Inferior 1 (process 22756) exited with code 01]
>> (gdb)
>>
>> This time it's no OOM it's a xapian exeption again.
>>
>>
>
> I have included the Xapian list in copy in case that message rings a
> bell. I guess you know there are not multiple writers in your setup.

Absolutely.  This is an otherwise unused minimal debian
buster system, the emails are a static copy from from my
production system (laptop) some days ago on a mounted
filesystem.  There are no other writes to this file system
besides notmuch new.

When I do subsequent notmuch new, most of the files are
reindexed in the second and third run, in the fourth run
there is a OOM although the system has 16GB RAM, 16GB swap.
The fourth notmuch new invocation throws an exeption:

grfz@mic:~/Mail/.notmuch$ nice ionice -c 3 notmuch new
Welcome to a new version of notmuch! Your database will now be upgraded.
This process is safe to interrupt.
Backing up tags to /home/grfz/Mail/.notmuch/dump-20210202T075743.gz...
Your notmuch database has now been upgraded.
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607947606.8134_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607940473.9509_1.no:2,S
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607969276.21046_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607987211.1395_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607979988.4942_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607972847.4857_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607943993.24776_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607976389.23296_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607983586.19063_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/drafts.mbox
Note: Ignoring non-mail file: /home/grfz/Mail/postponed.mbox
Processed 1183682 total files in 11h 33m 56s (28 files/sec.).
Added 1091038 new messages to the database.
grfz@mic:~/Mail/.notmuch$ cp -a xapian xapian-1
grfz@mic:~/Mail/.notmuch$ nice ionice -c 3 notmuch new
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607947606.8134_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607940473.9509_1.no:2,S
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607969276.21046_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607987211.1395_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607979988.4942_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607972847.4857_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607943993.24776_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607976389.23296_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607983586.19063_1.no:2,
Processed 1169095 total files in 13h 13m 16s (24 files/sec.).
Added 1077686 new messages to the database.
grfz@mic:~/Mail/.notmuch$ cp -a xapian xapian-2
grfz@mic:~/Mail/.notmuch$ nice ionice -c 3 notmuch new
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607947606.8134_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607940473.9509_1.no:2,S
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607969276.21046_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607987211.1395_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607979988.4942_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607972847.4857_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607943993.24776_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607976389.23296_1.no:2,
Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607983586.19063_1.no:2,
Processed 1151900 total files in 12h 55m 51s (24 files/sec.).
Added 1050106 new messages to the database.
grfz@mic:~/Mail/.notmuch$ cp -a xapian xapian-3
grfz@mic:~/Mail/.notmuch$ nice ionice -c 3 notmuch new
add_file: Out of memory files/sec.).
Processed 205 total files in 4s (42 files/sec.).
Added 193 new messages to the database.
Note: A fatal error was encountered: Out of memory
grfz@mic:~/Mail/.notmuch$

htop shows no memory pressure.  I reboot, move xapian
directory away, copy xapian-3 back to xapian and try again:

grfz@mic:~/Mail/.notmuch$ mv xapian xapian-OOM2
grfz@mic:~/Mail/.notmuch$ cp -a xapian-3 xapian
grfz@mic:~/Mail/.notmuch$ nice ionice -c 3 notmuch new                                                                                                                                         add_file: Out of memory files/sec.).
Processed 205 total files in 10s (19 files/sec.).
Added 193 new messages to the database.
Note: A fatal error was encountered: Out of memory
grfz@mic:~/Mail/.notmuch$ free
total        used        free      shared  buff/cache   available
Mem:       16394744      234788      234400        8724    15925556    15815084
Swap:      15622140         512    15621628
grfz@mic:~/Mail/.notmuch$


> Olly Betts mentioned in a different thread that he will build a version
> of xapian 1.4.18 for buster backports, so trying with that is probably a
> good step when it is available.

I'll do so.

>> grfz@mic:~/Mail/.notmuch$ mv xapian xapian-corrupted
>> grfz@mic:~/Mail/.notmuch$ notmuch new
>> Welcome to a new version of notmuch! Your database will now be upgraded.
>> This process is safe to interrupt.
>> Backing up tags to /home/grfz/Mail/.notmuch/dump-20210130T170349.gz...
>> Your notmuch database has now been upgraded.
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607947606.8134_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607940473.9509_1.no:2,S
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607969276.21046_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607987211.1395_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607979988.4942_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607972847.4857_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607943993.24776_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607976389.23296_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/spam-old/cur/1607983586.19063_1.no:2,
>> Note: Ignoring non-mail file: /home/grfz/Mail/drafts.mbox
>> Note: Ignoring non-mail file: /home/grfz/Mail/postponed.mbox
>> Processed 1183682 total files in 13h 38m 31s (24 files/sec.).
>> Added 1091038 new messages to the database.
>>
>> I then installed xapian-tools amd64 1.4.11-1.
>>
>> grfz@mic:~/Mail/.notmuch$ stat --format "%Y"  ~/Mail/inbox/cur
>> 1611646289
>>
>> grfz@mic:~/Mail/.notmuch$ quest -bdir:XDIRECTORY -d ~/Mail/.notmuch/xapian/ dir:inbox/cur
>> Parsed Query: Query(0 * XDIRECTORYinbox/cur)
>> MSet:
>>
>> That's it, there is data missing in the database.
>>
>
> This could either be a logic error in Notmuch,
>
> You can get a complete list of all of the directory documents in the
> notmuch database with
>
> % xapian-delve -1 -A XDIRECTORY ~/Mail/.notmuch/xapian | sort -u > delve.txt
>
> You can get a list of the actual directories with
>
> % find ~/Mail -type d -not empty | sed s,/home/grfz/Mail/,XDIRECTORY, |sort -u  >find.txt
>
> Comparing those two lists may give you some hints. Any directory that
> shows up in the second list but not the first should have no files in it
> (but potentially other directories) or be ignored either implicitly
> (.notmuch, .notmuch/xapian) or explicitely by your configuration.


I tried this after the second OOM (see above):

grfz@mic:~/Mail/.notmuch$ rm -rf xapian
grfz@mic:~/Mail/.notmuch$ cp -a xapian-3 xapian

grfz@mic:~/Mail/.notmuch$ xapian-delve -1 -A XDIRECTORY ~/Mail/.notmuch/xapian | sort -u > /tmp/delve.txt
grfz@mic:~/Mail/.notmuch$ find ~/Mail/  -type d -not -empty | sed s,/home/grfz/Mail/,XDIRECTORY, |sort -u  >/tmp/find.txt

As expected the find.txt contains a huge amount of ../cur
directories.

I searched for the directories in find.txt, which are not in
delve.txt:

grfz@mic:~/Mail/.notmuch$ while read ; do grep -qF "$REPLY" /tmp/delve.txt 2>/dev/null || echo $REPLY ; done < /tmp/find.txt > /tmp/out

It contains a huge amount of ../cur directories.

I searched if some of these ../cur directories do not
contain files:

grfz@mic:~/Mail/.notmuch$ cat /tmp/out | grep "/cur$" | sed -e "s,XDIRECTORY,/home/grfz/Mail/," | while read ; do cd "$REPLY" ; test $(find -type f | wc -l) = 0 && echo "$REPLY" ; done
/home/grfz/Mail/findex/cur

This one directory only contains symbolic links to maildir
mail files.  It is populated by mairx.

Otherwise there are no empty ../cur directories.  This was
to be expected.

grfz@mic:~/Mail/.notmuch$ grep "/cur$" /tmp/find.txt | while read ; do grep -qa "$REPLY" /tmp/delve.txt || echo "$REPLY" ; done | wc -l
5258

grfz@mic:~/Mail/.notmuch$ grep "/cur$" /tmp/find.txt | while read ; do grep -qa "$REPLY" /tmp/delve.txt || echo "$REPLY" ; done | sed -e "s,^XDIRECTORY,/home/grfz/Mail/," | while read ; do test $(find "$REPLY" | wc -l) -gt 1 || echo "$REPLY" ; done
find: ‘Binary file /tmp/find.txt matches’: No such file or directory
Binary file /tmp/find.txt matches
grfz@mic:~/Mail/.notmuch$


So there are 5258 directories which are in find.txt but not
in delve.txt and all of them at the same time have files in
them.

I don't really grasp the details, but to me it seems that a)
5288 directories are not indexed; and b) there is no
explanation for why almost all files were re-indexed several
times.


Ciao, Gregor\r