Memory usage with 1.1 on OS X Leopard Server

[Mike Czepiel]

Out of curiosity has anybody seen excessive memory usage with beanstalkd on OS X Leopard Server.

We're running 1.1 and seeing the memory footprint up around 760+MB with 2.07GB of virtual memory after a few hours of running.

I'm working with my system admin to revert back to an older beanstalkd to see if it was a problem then as well and they just hadn't noticed it.

We're launching beanstalkd with launchd set to keep-alive. Initially there is only 400KB of memory wired but after a few hours with minimal jobs submitted the memory use for the process is well above 700MB. We're running beanstalkd without the -d argument so launchd handles the daemon stuff.

Any suggestions? Things to try?

Thank you,

mike

[rezedit]

Aforementioned system admin here. We actually see the memory usage
double every time it goes up. So far it seems to correspond to when
jobs are submitted.

[Keith Rarick]

On Thu, Nov 13, 2008 at 9:30 AM, Mike Czepiel <cze...@gmail.com> wrote:
> Any suggestions? Things to try?

Can you send the output of a "stats" command on one of these overgrown
beanstalkd instances?

I'm trying to reproduce it here. I'm submitting one job per second
without deleting any. Does this resemble your use patterns? I'll let
it run overnight and see what happens.

kr

[Andreas Fuchs]

On Nov 14, 10:31 am, "Keith Rarick" <k...@xph.us> wrote:
> Can you send the output of a "stats" command on one of these overgrown
> beanstalkd instances?
>
> I'm trying to reproduce it here. I'm submitting one job per second
> without deleting any. Does this resemble your use patterns? I'll let
> it run overnight and see what happens.

I'm seeing something very similar on an OS X 10.5 desktop system; we
submit very few delayed background jobs to be processed by one worker
instance (it's a development system (-:). The memory usage quickly
grows to around 700MB.

Stats output of one server that has grown to about 740MB is as
follows:
stats
OK 711
---
current-jobs-urgent: 0
current-jobs-ready: 0
current-jobs-reserved: 0
current-jobs-delayed: 3
current-jobs-buried: 0
cmd-put: 118
cmd-peek: 0
cmd-peek-ready: 0
cmd-peek-delayed: 0
cmd-peek-buried: 0
cmd-reserve: 116
cmd-reserve-with-timeout: 0
cmd-delete: 115
cmd-release: 0
cmd-use: 2
cmd-watch: 1
cmd-ignore: 0
cmd-bury: 0
cmd-kick: 0
cmd-stats: 2
cmd-stats-job: 115
cmd-stats-tube: 0
cmd-list-tubes: 0
cmd-list-tube-used: 0
cmd-list-tubes-watched: 2
job-timeouts: 0
total-jobs: 118
max-job-size: 65535
current-tubes: 2
current-connections: 3
current-producers: 2
current-workers: 1
current-waiting: 1
total-connections: 4
pid: 31198
version: 1.1
rusage-utime: 0.544487
rusage-stime: 0.876544
uptime: 441

^]
telnet> quit
$ ps aux | grep '[b]eanstalk'
asf 31198 0.0 35.9 2174260 752204 ?? Ss 11:51PM
0:01.42 /Users/asf/Documents/hack/Soupsie/build/Release/Soupsie.app/
Contents/MacOS/beanstalkd

This doesn't look quite right. On our production linux box, where lots
(around 12k) more delayed requests are in the queue, we're seeing
similar memory usage (about 700MB there as well), but on the
development machine, this number looks implausibly big for the queue
size.

We're using async_observer to submit and handle jobs; On the dev
machine, beanstalkd is running in the foreground.

Thanks in advance,
Andreas.

[Keith Rarick]

On Tue, Nov 25, 2008 at 4:01 PM, Andreas Fuchs <anti...@gmail.com> wrote:
> total-jobs: 118
> ...

>
> asf 31198 0.0 35.9 2174260 752204 ?? Ss 11:51PM
> 0:01.42 /Users/asf/Documents/hack/Soupsie/build/Release/Soupsie.app/
> Contents/MacOS/beanstalkd

That's insane memory use, even on OS X. I just tested beanstalkd on OS
X 10.5 (with no updates; 32-bit) and libevent 1.4.8 stable, after
submitting about 1,500 jobs RSS is less than 600KiB.

Someone who sees this problem: can you give more details of which
version of Mac OS and libevent you're using? Are you running 64-bit?
Is anyone willing to run beanstalkd under valgrind (either memcheck or
massif)? That would be incredibly helpful, since I'm so far unable to
reproduce it.

kr

[Andreas Fuchs]

On Nov 26, 8:48 pm, "Keith Rarick" <k...@xph.us> wrote:

> On Tue, Nov 25, 2008 at 4:01 PM, Andreas Fuchs <antifu...@gmail.com> wrote:
> > total-jobs: 118
> > ...
>
> > asf      31198   0.0 35.9  2174260 752204   ??  Ss   11:51PM
> > 0:01.42 /Users/asf/Documents/hack/Soupsie/build/Release/Soupsie.app/
> > Contents/MacOS/beanstalkd
>
> That's insane memory use, even on OS X. I just tested beanstalkd on OS
> X 10.5 (with no updates; 32-bit) and libevent 1.4.8 stable, after
> submitting about 1,500 jobs RSS is less than 600KiB.

This is the odd part: If I start submitting jobs like mad (about 9000
in a few seconds), beanstalkd grows to about 2MB. There might be
something in our usage that differs from how you test, maybe?

What I did to get this memory usage was to submit a job with priority
10, and in the worker that accepted the job, submit another job that
does the same, delayed for 60 seconds, at priority 1024+, wait for 60
sec for the worker to do its thing again (at this point, it was at
220MB already) then do this two more times: submit that job at prio
10, wait a bit.

> Someone who sees this problem: can you give more details of which
> version of Mac OS and libevent you're using? Are you running 64-bit?
> Is anyone willing to run beanstalkd under valgrind (either memcheck or
> massif)? That would be incredibly helpful, since I'm so far unable to
> reproduce it.

uname -a output from the system in question:
Darwin jubjub.local 9.5.0 Darwin Kernel Version 9.5.0: Wed Sep 3
11:29:43 PDT 2008; root:xnu-1228.7.58~1/RELEASE_I386 i386

I'm running libevent 1.4.8 from macports, the portfile says:
# $Id: Portfile 40321 2008-09-29 15:58:33Z br...@macports.org $

The system is 64-bit Leopard, beanstalkd and libevent are built as 32-
bit executables:

$ file beanstalkd
beanstalkd: Mach-O executable i386
$ file /opt/local/lib/libevent.dylib
/opt/local/lib/libevent.dylib: Mach-O dynamically linked shared
library i386

I'll try and run it under valgrind tomorrow. Maybe the description of
our job submission pattern and the library info an help you a bit
already.

Thanks & good night,
Andreas

[Andreas Fuchs]

On Nov 26, 11:53 pm, Andreas Fuchs <antifu...@gmail.com> wrote:
> > Someone who sees this problem: can you give more details of which
> > version of Mac OS and libevent you're using? Are you running 64-bit?
> > Is anyone willing to run beanstalkd under valgrind (either memcheck or
> > massif)? That would be incredibly helpful, since I'm so far unable to
> > reproduce it.

[...]

> I'll try and run it under valgrind tomorrow. Maybe the description of
> our job submission pattern and the library info an help you a bit
> already.

Well, ha ha. Valgrind is not entirely ported to OS X, and the beta
patch for running on OS X (at http://www.sealiesoftware.com/valgrind/)
makes it crash when invoked with beanstalkd. )-:

I tried running with MallocStackLogging=1 (to run with leaks(1)), and
that reports:

$ ps aux | grep [b]eanstalkd
asf 31582 0.0 9.4 993380 197188 ?? Ss 8:39PM
0:00.33 ./beanstalkd
$ leaks beanstalkd
Process 31582: 42 nodes malloced for 393620 KB
Process 31582: 0 leaks for 0 total leaked bytes.

Well, erm. What? Also, I slowed things down a bit, and it looks like
memory usage doubles every time a request is enqueued. This doesn't
appear to affect /all/ requests, though.

Any other insights or debugging aids on OS X that could help?

Cheers,
Andreas.

[gmb...@gmail.com]

On Nov 26, 2008 5:53pm, Andreas Fuchs <anti...@gmail.com> wrote:
> I'll try and run it under valgrind tomorrow. Maybe the description of
> our job submission pattern and the library info an help you a bit
> already.

Today I did find a memory leak when tubes are freed. So if you cause
tubes to get created and freed on a regular basis you would see memory
grow.

I have a couple of other small fixes too. github is down right now, but I
will push them as soon as I see it up.

Graham.

[Andreas Fuchs]

On Nov 27, 9:31 pm, gmb...@gmail.com wrote:

> On Nov 26, 2008 5:53pm, Andreas Fuchs <antifu...@gmail.com> wrote:
>
> > I'll try and run it under valgrind tomorrow. Maybe the description of
> > our job submission pattern and the library info an help you a bit
> > already.
>
> Today I did find a memory leak when tubes are freed. So if you cause
> tubes to get created and freed on a regular basis you would see memory
> grow.

That's great news! However, I have only one permanent non-default
tube, just putting jobs into it. (See the stats output above, my
current-tubes is 2).

> I have a couple of other small fixes too. github is down right now, but I
> will push them as soon as I see it up.

Great stuff. Looking forward to your fixes,
Andreas.

[Graham Barr]

On Thu, Nov 27, 2008 at 5:15 PM, Andreas Fuchs <anti...@gmail.com> wrote:
>
>
> On Nov 27, 9:31 pm, gmb...@gmail.com wrote:
>> On Nov 26, 2008 5:53pm, Andreas Fuchs <antifu...@gmail.com> wrote:
>>
>> > I'll try and run it under valgrind tomorrow. Maybe the description of
>> > our job submission pattern and the library info an help you a bit
>> > already.
>>
>> Today I did find a memory leak when tubes are freed. So if you cause
>> tubes to get created and freed on a regular basis you would see memory
>> grow.
>
> That's great news! However, I have only one permanent non-default
> tube, just putting jobs into it. (See the stats output above, my
> current-tubes is 2).

yeah, it seems like you are putting them in and taking them out.

you also seem to be calling stats-job. Is that the worker or the producer
doing that ?

what is your average/max job size ?

do you have binlog turned on ?

>> I have a couple of other small fixes too. github is down right now, but I
>> will push them as soon as I see it up.
>
> Great stuff. Looking forward to your fixes,

github is back and they are at

http://github.com/gbarr/beanstalkd/commits/memleak

Graham.

[Andreas Fuchs]

On Nov 28, 2:28 am, "Graham Barr" <gmb...@gmail.com> wrote:

> On Thu, Nov 27, 2008 at 5:15 PM, Andreas Fuchs <antifu...@gmail.com> wrote:
> > That's great news! However, I have only one permanent non-default
> > tube, just putting jobs into it. (See the stats output above, my
> > current-tubes is 2).
>
> yeah, it seems like you are putting them in and taking them out.

What Async_observer does (plus putting them back), basically.

> you also seem to be calling stats-job. Is that the worker or the producer
> doing that ?

I would never have spotted this. That was async_observer's logging
function. Commenting that chunk out from async_observer seems to make
the leak go away: After a few of these job things (where it would
previously consume hundreds of MB), beanstalkd now consumes only about
444 kBytes, according to ps (-:

So it seems like stats-job is leaking somewhere...

> what is your average/max job size ?

Default setting: Looking at the code, it's ((1 << 16) - 1) (-:

> do you have binlog turned on ?

Don't know how to do that, so that's at the default setting (guessing
off).

Thanks so much for diagnosing this! To us, the individual job stats
aren't very important, so we'll just comment them out in our copy of
the async_observer plugin; it would be good to fix the underlying
cause, though.

Cheers,
Andreas.

[Dustin]

On Nov 27, 6:28 pm, "Graham Barr" <gmb...@gmail.com> wrote:

> yeah, it seems like you are putting them in and taking them out.
>
> you also seem to be calling stats-job. Is that the worker or the producer
> doing that ?
>
> what is your average/max job size ?
>
> do you have binlog turned on ?

I just ran into this problem with binlog turned on.

leaks says:

Process 162: 39 nodes malloced for 1574500 KB
Process 162: 0 leaks for 0 total leaked bytes.

stats says:

current-jobs-urgent: 0
current-jobs-ready: 0
current-jobs-reserved: 0

current-jobs-delayed: 0
current-jobs-buried: 0
cmd-put: 31

cmd-peek: 0
cmd-peek-ready: 0
cmd-peek-delayed: 0
cmd-peek-buried: 0

cmd-reserve: 61
cmd-reserve-with-timeout: 0
cmd-delete: 31
cmd-release: 0
cmd-use: 31
cmd-watch: 30
cmd-ignore: 30
cmd-bury: 0
cmd-kick: 0
cmd-touch: 0
cmd-stats: 1
cmd-stats-job: 0

cmd-stats-tube: 0
cmd-list-tubes: 0
cmd-list-tube-used: 0

cmd-list-tubes-watched: 31
job-timeouts: 0
total-jobs: 31
max-job-size: 65535
current-tubes: 1
current-connections: 1
current-producers: 0
current-workers: 0
current-waiting: 0
total-connections: 65
pid: 162
version: v1.1-45-gb637898
rusage-utime: 0.848163
rusage-stime: 0.808622
uptime: 389618

killing 162 made my machine much happier. :)

[Andreas Fuchs]

On Nov 29, 1:04 am, Andreas Fuchs <antifu...@gmail.com> wrote:
> On Nov 28, 2:28 am, "Graham Barr" <gmb...@gmail.com> wrote:
> I would never have spotted this. That was async_observer's logging
> function. Commenting that chunk out from async_observer seems to make
> the leak go away: After a few of these job things (where it would
> previously consume hundreds of MB), beanstalkd now consumes only about
> 444 kBytes, according to ps (-:
>
> So it seems like stats-job is leaking somewhere...

A little clarification. I have just done a few experiments "on the
wire", and it seems that mem usage for this usage pattern in 1.1 grows
if a worker has reserved a job, and does stats-job on it, which is
exactly the usage pattern that async_observer exhibits. Here's a test
case using the ruby beanstalk-client library:

In one ruby process, do:

require 'beanstalk-client'
bs = Beanstalk::Pool.new(['localhost:11300'])
while true; bs.yput({:oink => 'foo'}) ; sleep 1 ; end

In another ruby process:

require 'beanstalk-client'
while (j = bs.reserve) ; puts j.stats.inspect ; j.delete; true ; end

After a short while, you'll notice memory consumption growing by a
lot; the first few seconds, it's not very much, then it grows into the
hundreds of MB very quickly. The same behavior can be seen by using
peek_ready instead of reserve.

Hope this helps track down the stats-job leak.

Thanks,
Andreas.

[Graham Barr]

On Sat, Nov 29, 2008 at 5:18 AM, Andreas Fuchs <anti...@gmail.com> wrote:
> A little clarification. I have just done a few experiments "on the
> wire", and it seems that mem usage for this usage pattern in 1.1 grows
> if a worker has reserved a job, and does stats-job on it, which is
> exactly the usage pattern that async_observer exhibits. Here's a test
> case using the ruby beanstalk-client library:

Hah, I fixed this one without even knowing it :-)

My commit to keep all_jobs_used consistent fixes the problem

http://github.com/gbarr/beanstalkd/commits/memleak

Graham.

[Keith Rarick]

On Sat, Nov 29, 2008 at 5:40 AM, Graham Barr <gmb...@gmail.com> wrote:
> My commit to keep all_jobs_used consistent fixes the problem

That makes sense. The only "doubling" behavior in beanstalkd is when
the job hash table grows to accommodate more jobs at a time.
Decrementing all_jobs_used incorrectly caused it to become 2^32 - 1,
which caused the hash table to grow every time a job was inserted.

Thank you! I'll push this change to my master branch momentarily.

kr

[rezedit]

> That makes sense. The only "doubling" behavior in beanstalkd is when
> the job hash table grows to accommodate more jobs at a time.
> Decrementing all_jobs_used incorrectly caused it to become 2^32 - 1,
> which caused the hash table to grow every time a job was inserted.
>
> Thank you! I'll push this change to my master branch momentarily.
>
> kr

Mike C. grabbed source from master today and we installed it. Memory
use is very stable now and it no longer grows larger with every job
submitted. We've had more than 20 jobs go through and the memory use
has not budged.

Thanks!

[Fritz]

On Nov 13 2008, 12:30 pm, "Mike Czepiel" <czep...@gmail.com> wrote:

> Out of curiosity has anybody seen excessive memory usage with beanstalkd on

> OS X Leopard Server.We're running 1.1 and seeing the memory footprint up

> around 760+MB with 2.07GB of virtual memory after a few hours of running.

Just a note that we're seeing something similar on a RHEL 4 server
(for 1.1, but not 0.9 or the latest from github). Physical memory
stays low, but virtual memory increases by leaps and bounds.

We're running 0.9 at the moment and plan to move to 1.2 when it's
released.