Subject: [sup-talk] sup-sync and xapian memory usage

From: [email-masked] (Andrew Pimlott)
Date: Mon, 7 Sep 2009 10:04:50 -0700

Last time I tried to use sup[1], I posted about sup-sync crashing with
various symptoms of memory exhaustion[2].  I've tried again (using git
mainline), with similar results, but now I have a bit more to say about
it.

I am running on a fairly low-memory virtual machine.  I think some of
the variability in what I was seeing before had to do with what other
things were running.  Sorry about not being aware of this before.  In
the following, I have pretty well controlled for other system memory
use.  All of these tests are done on the same mbox with all indices
cleared.

Some of the failures I see are out of memory when running gpg
("Errno::ENOMEM Exception: Cannot allocate memory - /usr/bin/gpg" ...).
I stopped at that point in the debugger and found that at this point,
the ruby backtick operator fails the same way on any command.  Using
strace, I saw a failure in clone:

20528 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7cb3908) = -1 ENOMEM (Cannot allocate memory)

top reports 2.5M of physical and 30M of swap free, so I don't really
know why clone fails, but I guess there's not much you can do about
that.

Other failures were the result of sup blowing up on messages with large
attachments.  sup's memory use is many times the attachment size.
Testing on an mbox with a single message with 4 ~5M (encoded size)
attachments (total file size ~21M), sup goes up to ~150M.  Accounting
for baseline, that's about 6 times the file size.  I hope that can be
improved.  FWIW, mutt never seems to try to load a whole attachment into
memory.

Using the ferret index, the memory (virtual as reported by Linux)
behaviour of sup-sync is pretty good.  It starts out 25M and levels out
around 31M.  It spikes from time to time, presumably because of large
messages, but it comes right back.  After processing the last message,
it uses another 10M to finish up.

Using the xapian index, things are different.  It starts at 32M and
steadily climbs to 77M after ~3500 messages, or around 1M every 100
messages.  It does seem to climb faster at first and then more slowly.
Either xapian is keeping a cache (but some searches suggest it doesn't),
it's leaking memory, or it's allocating memory in a way that the the
allocator can't reclaim the VM space.  Any ideas?

BTW, is there really no way to ask for ruby's heap size with (unpatched)
ruby 1.8?

Andrew

[1] This is about the fourth time.  I seem to be easily discouraged.
[2] http://rubyforge.org/pipermail/sup-talk/2009-May/002171.html

---

From: [email-masked] (Ben Walton)
Date: Mon, 07 Sep 2009 14:14:41 -0400

> the variability in what I was seeing before had to do with what

I'm running sup on real hardware w/1GB physical ram.

> strace, I saw a failure in clone:

I found sup crashed this morning too with an ENOMEM on a gpg
operation.  I thought I may actually have been at the memory
exhaustion point normally though as I run screen and tend to leave
lots of sessions going all the time.

> messages.  It does seem to climb faster at first and then more

I've never paid attention to this before, but currently, my sup
process (running for about 6 hours now) looks like it's using ~77M
virtual with 59 of that resident.

This has only happened to me once, but since you reported it, I
thought I'd chime in with some extra data.

HTH.
-Ben
-- 
Ben Walton
Systems Programmer - CHASS
University of Toronto
C:416.407.5610 | W:416.978.4302

GPG Key Id: 8E89F6D2; Key Server: pgp.mit.edu
Contact me to arrange for a CAcert assurance meeting.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090907/4318eb38/attachment.bin>

---

From: [email-masked] (Rich Lane)
Date: Mon, 07 Sep 2009 14:33:06 -0400

> allocator can't reclaim the VM space.  Any ideas?

Xapian keeps writes buffered in memory. Try setting the environment
variable XAPIAN_FLUSH_THRESHOLD to a smaller value (the default is 10000
documents) and see if that helps.

---

From: [email-masked] (Ben Walton)
Date: Mon, 07 Sep 2009 15:11:58 -0400

> documents) and see if that helps.

Does this explain the lag at shutdown?  Xapian is flushing writes to
disk?

-Ben

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090907/b8fec298/attachment.bin>

---

From: [email-masked] (Rich Lane)
Date: Mon, 07 Sep 2009 15:15:08 -0400

> Does this explain the lag at shutdown?  Xapian is flushing writes to

Yep.

---

From: [email-masked] (Andrew Pimlott)
Date: Mon, 7 Sep 2009 12:26:11 -0700

> documents) and see if that helps.

Thanks--it was hard for me to find that kind of information.  I first
tried setting XAPIAN_FLUSH_THRESHOLD to 1, and sup-sync ran slowly and
just kept getting slower:

## read 139m (about 7%) @ 9.2m/s. 0:00:15 elapsed, about 0:03:21 remaining
...
## read 1238m (about 35%) @ 3.1m/s. 0:06:36 elapsed, about 0:12:08 remaining

I stopped at this point because it was taking too long.  The memory use
seemed stable, but that could have been because it was making such slow
progress.  I guess xapian gets a lot slower writing as the db grows?
That's a bit discouraging.  Using ferret, sup-sync only dropped from
28.1m/s to 27.3m/s during its run.  For reference, when I didn't set
XAPIAN_FLUSH_THRESHOLD, I was getting 35-36m/s until it ran out of
memory.

I then set XAPIAN_FLUSH_THRESHOLD to 100 and got more reasonable
results.  It started at 25.6m/s and slowed to 17.8m/s.  It stabilized at
around 41M virtual memory used and finished successfuly.  I also note
that the memory use didn't jump during the finish-up phase ("Deleting
missing messages") as it had with ferret.

Finally, I set XAPIAN_FLUSH_THRESHOLD to 1000.  It started at 34.6m/s
and dropped to 29.8m/s., stabilized at around 51M virtual memory, and
finished successfully.  In this case, it stays faster than ferret, but
it sill bugs me that xapian still slows down while ferret doesn't.

So I conclude... I don't know what I conclude.  Letting xapian use a lot
of memory sure helps its performance.  And a big sup-sync should only
have to be done rarely.  So maybe just document that those on low-memory
systems should consider using XAPIAN_FLUSH_THRESHOLD during sup-sync.

Thanks again for your help!

Andrew

---

From: [email-masked] (William Morgan)
Date: Tue, 08 Sep 2009 06:15:49 -0700

Reformatted excerpts from Andrew Pimlott's message of 2009-09-07:
> various symptoms of memory exhaustion[2].

Excellent resolution to that thread.

> sup's memory use is many times the attachment size.  Testing on an
> mbox with a single message with 4 ~5M (encoded size) attachments
> (total file size ~21M), sup goes up to ~150M.  Accounting for
> baseline, that's about 6 times the file size.  I hope that can be
> improved.

Sup uses the unmaintained RubyMail for MIME handling. I'm sure this
behavior can be improved if you can find someone who wants to write some
MIME handling code. Personally that's near the bottom of my list.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (William Morgan)
Date: Tue, 08 Sep 2009 06:39:12 -0700

Reformatted excerpts from Rich Lane's message of 2009-09-07:
> > > Xapian keeps writes buffered in memory. Try setting the
> > > environment variable XAPIAN_FLUSH_THRESHOLD to a smaller value
> > > (the default is 10000 documents) and see if that helps.
> > 

Good to know. Is there a way to force a flush in Xapian? Just curious.
The delay is a little scary sometimes. Maybe it just needs an
appropriate message somewhere.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Ben Walton)
Date: Tue, 08 Sep 2009 09:58:15 -0400

> appropriate message somewhere.

...even just a message indicating that xapian is flushing the buffered
writes would be a good thing.

-Ben

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090908/fa461b0e/attachment.bin>

---

From: [email-masked] (Richard Heycock)
Date: Wed, 09 Sep 2009 00:27:10 +1000

> appropriate message somewhere.

Xapian, by default, flushes every 10 000 documents which in email terms
is a pretty long time! You can force a flush but it does increase your
IO significantly. Having said that emails are fairly small so flushing
every 10 or 20 emails might not be too bad.

Maybe it could be dynamic, if there is a high volume of incoming emails
flushing could be done after 50 or 100 emails or a timer based flush
might be easier.

rgh

---

From: [email-masked] (Nicolas Pouillard)
Date: Tue, 08 Sep 2009 17:14:22 +0200

> flushing could be done after 50 or 100 emails or a timer based flush

Should the '$' command, force a write of the Xapian database?

-- 
Nicolas Pouillard
http://nicolaspouillard.fr

---

From: [email-masked] (Rich Lane)
Date: Wed, 09 Sep 2009 02:18:09 -0400

> Should the '$' command, force a write of the Xapian database?

I think once we're saving label changes to the index immediately we
could re-purpose '$' for this. I've also been considering a timer, as
Richard suggests, which would trigger a flush once the user has been
idle for some time.

A fatal exception in Sup is still a clean exit as far as SWIG is
concerned and the Xapian database destructor will do the flush for us in
that case, so don't worry about random Sup exceptions causing data loss.