As some of you may have experienced, god has a slow memory leak. Since
my informal techniques have so far been fruitless, it's time to bust
out the scientific method. I will use this thread to document the
process and hopefully we can solve this problem.
Let's begin. I ask "Why is god leaking?"
Looking at /proc/<pid>/status for a god process (ruby 1.8.5
(2006-12-25 patchlevel 12) [x86_64-linux]) that is obviously leaking,
I see the following:
The stack size is small and the data size is large, which means that
the leak is on the heap.
Ruby can leak to the heap in two ways. By not garbage collecting from
the Ruby heap or by leaking memory to the C heap. I always assume it
is my own code that is broken, so my hypothesis is that I am somehow
causing Ruby heap objects to stick around and not be GC'ed. To test
this hypothesis I will use the excellent BleakHouse from Evan Weaver.
It produces a dump of the Ruby heap on demand and can then analyze the
frame dumps to calculate how many objects are never collected.
The test is against god 0.7.3 on ruby 1.8.5 (2006-12-25 patchlevel 12)
[i686-darwin8.9.1]. The config file contains a single watch with
interval = 0 (meaning it will run the condition continuously) that
runs a process_running condition. Heap snapshots are taken at the
beginning and end of the driver loop.
After several seconds, god holds steady at around 9150kb for ten
minutes or so. Then it starts leaking. When I finally stop god about
20 minutes later, it is up to around 9500kb. This test run produces a
20GB! dump file. An overnight analysis gives me this:
-----------------------------------
88733 full frames. Removing 15 frames from each end of the run to
account for
startup overhead and GC lag.
5220649 total births, 5220403 total deaths, 611 uncollected objects.
Tags sorted by persistent uncollected objects. These objects did not
exist at
startup, were instantiated by the associated tags, and were never
garbage
collected:
end-driver leaked (over 44350 requests):
178 String
146 Array
111 Time
4 MatchData
3 God::DriverEvent
1 IO
1 Float
1 God::System::Process
1 File
1 Process::Status
begin-driver leaked (over 44355 requests):
29 String
3 Array
1 NoMethodError
-----------------------------------
The analysis shows that no unexpected Ruby heap leaks are occurring.
God is set to hold on to the last 100 log lines (which are stored as
[text, time]) accounting for 100 Array objects, 100 String objects,
and 100 Time objects. The remaining objects represent the working set
that god uses during a normal driver cycle and are within my
expectations.
I conclude that under this setup, uncollectable objects do not account
for the memory leak. This leaves C heap leaks as the likely culprit.
My next experiment will formalize this hypothesis.
I know that the memory leak isn't caused by leaking Ruby objects and I
know that a basic looping Ruby program does not leak memory. There
must, then, be some part of the code that causes Ruby to leak memory
internally. Since the memory leak seems to be related to how
frequently the driver loop executes, I hypothesize that most or all of
the memory leak is contained within the driver loop handlers.
Experiment B
In this experiment I will disable the handler part of the driver loop,
instead rescheduling the condition immediately. The code for this test
can be found at
For these memory leak tests, I will consider god NOT leaking if it
does not vary significantly from the startup memory usage after 10,000
seconds. Here are the test results:
This is running under ruby 1.8.5 (2006-12-25 patchlevel 12) [i686-
darwin8.9.1].
I conclude that the memory leak is caused by code within the driver
handlers. Some Ruby call or calls must be leaking memory within that
code. Isolating the offending code should hopefully allow me to work
around it.
Over the 17 hour test, memory increased by 1.1 MB. This represents
perhaps 1,000,000 times through the driver loop (the test used 100% of
both cores on my MBP).
I'm not sure what to make of this data right now. It appears to be
leaking, albeit very very slowly. I'm also not sure why initial memory
usage is higher. More investigation needs to go into 1.8.6 behavior,
but for the moment I will concentrate on 1.8.5 as it shows no memory
leak for this test which should make it easier to isolate the leaking
code.
Rubinius is almost the point where it can run god. I will keep an eye
on their progress and once a test run can be done against Rubinius I
will do an experiment under that environment.
Experiment B showed that god does not leak memory under 1.8.5 if the
main processing logic is removed. This is for a single Watch. It's
possible that thread interactions will cause the leak to manifest. I
hypothesize that configuring 10 watches (one driver thread per watch)
will also NOT leak. I will perform a 10,000 second experiment to test
this.
So it looks like a slow leak. Memory usage after 10,000 seconds (2.78
hours) was 188kb higher than initially. While I'd say this is a real
leak, it would only count as a tiny portion of the problem and so I
will shelve it for later inspection. If the main leak is not caused by
threaded interactions at this level, then it is time to delve into the
handler code and see if I can isolate the memory leaking code.
This experiment will act as the control, showing the memory leak in
god 0.7.2 (at full speed). A 10,000 second test with one Watch will be
performed if my machine can hold on that long.
Intuition tells me that the logging subsystem is a likely candidate
for memory leaks. There's a lot of data being pushed around in there.
I hypothesize that this will at least reduce the memory leak.
Experiment E
I will disable all logging from within the handlers.
Further testing shows that it's the condition.base_name part of the
line that is responsible. Here's the code:
def base_name
self.class.name.split('::').last
end
Amazingly, this seemingly benign method rings a very familiar bell.
Another developer at Powerset had identified a piece of code in his
app that looked very much like this and resulted in a HUGE memory leak
as well. The odd but functional fix that we identified was to create a
local scope by declaring a local variable. Here's the diff that I will
try for this test run:
def base_name
+ x = 1
self.class.name.split('::').last
end
I can't tell you how glad I am to have finally solved this problem.
The fun isn't over yet, though. I'll now confirm the fix for 10
watches and on 1.8.6. Stay tuned!
Holy crap, It would interesting to figure out how the F defining a local variable prevents the leak... It almost makes me more frustrated that this is the fix :)
> Further testing shows that it's the condition.base_name part of the > line that is responsible. Here's the code:
> def base_name > self.class.name.split('::').last > end
> Amazingly, this seemingly benign method rings a very familiar bell. > Another developer at Powerset had identified a piece of code in his > app that looked very much like this and resulted in a HUGE memory leak > as well. The odd but functional fix that we identified was to create a > local scope by declaring a local variable. Here's the diff that I will > try for this test run:
> def base_name > + x = 1 > self.class.name.split('::').last > end
> I can't tell you how glad I am to have finally solved this problem. > The fun isn't over yet, though. I'll now confirm the fix for 10 > watches and on 1.8.6. Stay tuned!
> Further testing shows that it's the condition.base_name part of the > line that is responsible. Here's the code:
> def base_name > self.class.name.split('::').last > end
Well done for isolating this; a triumph of empirical legwork.
> Amazingly, this seemingly benign method rings a very familiar bell. > Another developer at Powerset had identified a piece of code in his > app that looked very much like this and resulted in a HUGE memory leak > as well. The odd but functional fix that we identified was to create a > local scope by declaring a local variable. Here's the diff that I will > try for this test run:
> def base_name > + x = 1 > self.class.name.split('::').last > end
Odd indeed. This looks like a bug in Ruby. Would Ruby Talk be the best place to raise this in the hope of solving the problem at source?
> I can't tell you how glad I am to have finally solved this problem. > The fun isn't over yet, though. I'll now confirm the fix for 10 > watches and on 1.8.6. Stay tuned!
Well done!
Here's a test case that demonstrates what is surely a bug. If you want, you can post on ruby-talk or someplace more efficient to get some attention and a fix. Make sure you post the test case.
module Play class Toy def peek_at_proc puts `ps u -p #{Process.pid}` end
def base_name #x = 1 # <<<<<< REMOVE COMMENT TO FIX MEM LEAK "a,b".split(',') end
This is interesting. I'm not sure whether this represents a long term
leak or not. Memory usage increased by 4k for 3 of the 4 last samples
above. Considering that each 50,000 second sample represents about 75
million times through the driver loop, that would be an awfully slow
leak. I am happy to see that it plateaus in 1.8.6, even if that
plateau is not completely flat. That's good enough for now and I'll
put aside some time in the future to investigate further. The fact
that 1.8.6 settles on about twice the memory usage of 1.8.5 is a bit
curious and also deserves more attention.
In order to get a better understanding of the situation, I'm going to
do a set of runs with various numbers of watches to see how memory
usage compares between them. This may shed some light on where the
problem is situated.
Test runs will be 1000 seconds each for 1, 2, 4 and 8 watches. All
values are in kilobytes.
1 watch
7520..7524
2 watches
7940..40312
4 watches
7696..46300
8 watches
14704..41140
The results show that for a single watch there is no memory leak, as
I've already concluded. Adding just one more watch causes memory to
explode. I want to verify again that removing the driver handler will
stop the leak.
8 watches (no driver handlers)
7916..7388
Oh look, memory usage actually decreased! Isn't that a sight to
behold! So the leak is somewhere within the handler, once again.
This wraps up this set of tests. Next I'll dig into the even handler
and start narrowing the field.
This is a standard 10000 second test on Ruby 1.8.5 with 8 watches.
14240 (1)
...
13104 (10000)
So the leak is caused somewhere in applog, but only for multiple
watches. Curious indeed. Here is the specific line that causes the
leak (and does not when commented out):
Digging around in the internals of the god logger have allowed me to
isolate the leak inside the Ruby's Logger class. To verify that it
leaks in a multi-threaded setup I wrote the following simple case:
-------------------------------
require 'logger'
log = Logger.new(STDOUT)
threads = []
10.times do
threads << Thread.new do
loop do
log.info("foo")
end
end
end
threads.each { |t| t.join }
---------------------------
Which does indeed leak like mad under 1.8.5 and 1.8.6 and is confirmed
by several people. This test, then, involves writing a very simple
logger to replace Ruby's Logger and see if that will eliminate the
leak. The version I am testing can be found here:
There appears to be a leak at a rate of about 200k per 10,000 seconds
with the simple logger. I'm going to flesh out the rest of the simple
logger and then release a version with the fix. While a leak seems to
persist, it is 3 orders of magnitude smaller now. That will please
many users.
Maybe I'll even work on some new features for once. =)
While this code is almost exactly the same as Loggy (the simple log I
wrote on the science branch), it now leaks again. In isolating the
leak, I narrowed it down to a change I had made in the assignment of
severity level constants. Loggy had
DEBUG = 4
INFO = 3
WARN = 2
ERROR = 1
FATAL = 0
which was backwards from what the Ruby Logger has, which is
DEBUG = 0
INFO = 1
WARN = 2
ERROR = 3
FATAL = 4
It turns out that the problem is in assigning the value 1 to INFO. If
that constant is changed to any other integer, it does not leak nearly
as fast (it still has that 200k/10,000 leak though). This is totally
incomprehensible to me, but if you'd like to try to replicate it, here
are the two git commits that represent the fast leak and slow leak
versions.
diff --git a/lib/god/logger.rb b/lib/god/logger.rb
index 7150fca..6f55d1c 100644
--- a/lib/god/logger.rb
+++ b/lib/god/logger.rb
@@ -1,7 +1,7 @@
module God
class Loggy
DEBUG = 0
- INFO = 1
+ INFO = 3
WARN = 2
ERROR = 3
FATAL = 4
I may go into this a bit more later as I discovered some other things
about this weirdness, but for now, let's move on. Simply changing the
constant values so that none of them are 1 gets us back to the slow
leak.
Once again, here is the 200k/10,000 second leak that we had in the
science branch with the hackish logger. Next, let's discover where
this 200k leak is coming from!
> It turns out that the problem is in assigning the value 1 to INFO. If > that constant is changed to any other integer, it does not leak nearly > as fast (it still has that 200k/10,000 leak though). This is totally > incomprehensible to me, ....
This is like Alice in Wonderland. Curiouser and curiouser....
This is pretty interesting stuff. I've noticed there haven't been any
updates for a week, though. Is this still progressing? Any workarounds
(Can god be made to monitor and restart god?) Anything I can do to
help?
Thanks for the in-depth approach. Noticed my God process had got up to
400mb and googled and got straight here - refreshing to be given such
an in-depth analysis - keep up the good work!
Any new updates on this issue? It makes me a little nervous that my
monitor leaks (few hundred meg in 10 days). After reading this
thread, I a;so really interesting in hearing what the problem is.
<ch...@thewebfellas.com> wrote:
> Thanks for the in-depth approach. Noticed my God process had got up to
> 400mb and googled and got straight here - refreshing to be given such
> an in-depth analysis - keep up the good work!
> Any new updates on this issue? It makes me a little nervous that my
> monitor leaks (few hundred meg in 10 days). After reading this
> thread, I a;so really interesting in hearing what the problem is.
> On Mar 6, 9:31 pm, "chris [at] thewebfellas.com"
> <ch...@thewebfellas.com> wrote:
> > Thanks for the in-depth approach. Noticed my God process had got up to
> > 400mb and googled and got straight here - refreshing to be given such
> > an in-depth analysis - keep up the good work!
> On Apr 9, 5:19 pm, gobigdave <gobigd...@gmail.com> wrote:
> > Any new updates on this issue? It makes me a little nervous that my
> > monitor leaks (few hundred meg in 10 days). After reading this
> > thread, I a;so really interesting in hearing what the problem is.
> > On Mar 6, 9:31 pm, "chris [at] thewebfellas.com"
> > <ch...@thewebfellas.com> wrote:
> > > Thanks for the in-depth approach. Noticed my God process had got up to
> > > 400mb and googled and got straight here - refreshing to be given such
> > > an in-depth analysis - keep up the good work!
