Tracking down a garbage collection problem

[Wincent Colaiuta]

I'm trying to work out ways to reduce the memory use of one of my
projects, but I don't know what methods are available to the Ruby
programmer for profiling memory use and tracking down garbage
collection problems.

The short version:

I have a project where processing a file can consume dozens of
megabytes of memory; if I process many files in a single run then
total memory usage can reach hundreds of megabytes or more than a gig.
I would expect garbage collection to kick in along the way but it
doesn't seem to be happening, memory usage grows and grows, and I
don't know where to start zeroing in on the problem.

The long version:

I've written an object-oriented templating system[1] that incorporates
a memoizing packrat parser. As each file is parsed the parser
"memoizes" the partial results for speed. In a lengthy file the size
of the memoizing cache can grow quite large (dozens of megabytes). But
I would expect the entire contents of the memoization cache to get
garbage collected when I move on to the next file; the cache itself
has definitely fallen out of scope by that time. But garbage
collection doesn't seem to be happen, as memory use grows linearly as
I batch process input files.

As this is a largish, complicated project I don't even know where to
begin to start investigating this. So really, I am looking for general
information on techniques for measuring and exploring memory use and
garbage collection in Ruby.

Thanks in advance for the advice!
Wincent

[1] http://walrus.wincent.com/

 

[Robert Klemme]

I'm trying to work out ways to reduce the memory use of one of my
projects, but I don't know what methods are available to the Ruby
programmer for profiling memory use and tracking down garbage
collection problems.

The short version:

I have a project where processing a file can consume dozens of
megabytes of memory; if I process many files in a single run then
total memory usage can reach hundreds of megabytes or more than a gig.
I would expect garbage collection to kick in along the way but it
doesn't seem to be happening, memory usage grows and grows, and I
don't know where to start zeroing in on the problem.

The long version:

I've written an object-oriented templating system[1] that incorporates
a memoizing packrat parser. As each file is parsed the parser
"memoizes" the partial results for speed. In a lengthy file the size
of the memoizing cache can grow quite large (dozens of megabytes). But
I would expect the entire contents of the memoization cache to get
garbage collected when I move on to the next file; the cache itself
has definitely fallen out of scope by that time. But garbage
collection doesn't seem to be happen, as memory use grows linearly as
I batch process input files.

I don't know what techniques exactly you employ but it seems indeed that
the cached data is held on to longer than intended.

As this is a largish, complicated project I don't even know where to
begin to start investigating this. So really, I am looking for general
information on techniques for measuring and exploring memory use and
garbage collection in Ruby.

I am not sure, there might be an extension around. Did you check with
the RAA?

What I'd do here is a) code inspection b) create a finalizer with some
debugging output for your cache instance and see whether you see the
output. If not, you know that your cache instance is still referred to.

Kind regards

robert

 

[M. Edward (Ed) Borasky]

I'm trying to work out ways to reduce the memory use of one of my
projects, but I don't know what methods are available to the Ruby
programmer for profiling memory use and tracking down garbage
collection problems.

The short version:

I have a project where processing a file can consume dozens of
megabytes of memory; if I process many files in a single run then
total memory usage can reach hundreds of megabytes or more than a gig.
I would expect garbage collection to kick in along the way but it
doesn't seem to be happening, memory usage grows and grows, and I
don't know where to start zeroing in on the problem.

The long version:

I've written an object-oriented templating system[1] that incorporates
a memoizing packrat parser. As each file is parsed the parser
"memoizes" the partial results for speed. In a lengthy file the size
of the memoizing cache can grow quite large (dozens of megabytes). But
I would expect the entire contents of the memoization cache to get
garbage collected when I move on to the next file; the cache itself
has definitely fallen out of scope by that time. But garbage
collection doesn't seem to be happen, as memory use grows linearly as
I batch process input files.

As this is a largish, complicated project I don't even know where to
begin to start investigating this. So really, I am looking for general
information on techniques for measuring and exploring memory use and
garbage collection in Ruby.

Thanks in advance for the advice!
Wincent

[1] http://walrus.wincent.com/

Well ... where to begin??

1. First of all, get the notion that "premature optimization is the root
of all evil" out of your head. The only sense in which that maxim is
valid is when the word "premature" is strongly emphasized. Part of the
practice of software engineering, and what separates software
engineering from "mere coding" is knowing what the algorithms of choice
are for the problem you are trying to solve -- and their resource
requirements -- and using them. Dijkstra may have said the premature
optimization thing, but it's obviously been taken out of the context of
his *massive* output of practical computer science and software
engineering teachings. Read *everything* he wrote!

2. In general, to reduce memory usage, you must do one or both of two
things: recompute things rather than storing them in memory, or write
things explicitly out to "backing store" and read them back in.

3. Languages without explicit object destructors need to be fixed,
including Ruby. However, part of software engineering in the absence
of them is to make sure there are no references to objects you no longer
want, and then explicitly call the garbage collector. I do a lot of
coding in R, which is a dynamic, garbage collected language for
scientific and statistical computing. I've got a 1 GB workstation, and
still I have "normal sized problems" that can overflow memory. A simple
delete of unused objects (R has "rm", which will delete an object from
the workspace) followed by a call to the garbage collector usually gets
me going again.

4. Relational databases are your friend. They are designed and optimized
for dealing with large and complicated datasets, and object-relational
mappings like ActiveRecord and Og (Object Graph) exist in Ruby to make
working with them as simple as possible. How do you define "large"? For
a single-user system like a laptop or workstation, figure you have
something like half of the installed RAM to run your applications. At
least on Linux workstations, things like I/O buffers will take up the
other half. If you're only running this one application, anything bigger
than half of your installed RAM is too big and ought to be redesigned to
use a database.

 

[Wincent Colaiuta]

I don't know what techniques exactly you employ but it seems indeed that
the cached data is held on to longer than intended.


I am not sure, there might be an extension around. Did you check with
the RAA?

What I'd do here is a) code inspection b) create a finalizer with some
debugging output for your cache instance and see whether you see the
output. If not, you know that your cache instance is still referred to.

Thanks, Robert. That is excellent advice. The method in question looks
basically like this:

def parse
# do stuff
cache = MemoizingCache.new
# do more stuff
end

I changed this to read as follows:

def parse
# do stuff
cache = MemoizingCache.new
$stderr.print "New cache id #{cache.object_id}\n"
ObjectSpace.define_finalizer(cache, lambda { |id| $stderr.print
"Finalizer for id #{id}\n"})
# do more stuff
end

And have confirmed that the cache finalizers are not being called. I
haven't found out how the reference to the local "cache" variable is
being kept alive even after it falls out of scope, but you've given me
the tool necessary to at least find out what's happening.

Thanks a lot!
Cheers,
Wincent

 

[ts]

W> def parse
W> # do stuff
W> cache = MemoizingCache.new
^^^^^
W> $stderr.print "New cache id #{cache.object_id}\n"
W> ObjectSpace.define_finalizer(cache, lambda { |id| $stderr.print
^^^^^^
W> "Finalizer for id #{id}\n"})
W> # do more stuff
W> end

W> And have confirmed that the cache finalizers are not being called. I
W> haven't found out how the reference to the local "cache" variable is
W> being kept alive even after it falls out of scope, but you've given me
W> the tool necessary to at least find out what's happening.

The closure (lambda) has a reference to the variable cache

Here a stupid example

moulon% cat b.rb
#!/usr/bin/ruby

class A
def parse
cache = Array.new(100)
ObjectSpace.define_finalizer(cache, lambda {|i| $stderr.puts "obj_id #{i}" })
end
end

ARGV[0].to_i.times { A.new.parse }
$stderr.puts "gc"
GC.start
$stderr.puts "at end"
moulon%

moulon% ./b.rb 2
gc
at end
obj_id -605590758
obj_id -605590688
moulon%

Now if I change this to

moulon% cat b.rb
#!/usr/bin/ruby

class A
def self.x
lambda {|i| $stderr.puts "obj_id #{i}" }
end

def parse
cache = Array.new(100)
ObjectSpace.define_finalizer(cache, A.x)
end
end

ARGV[0].to_i.times { A.new.parse }
$stderr.puts "gc"
GC.start
$stderr.puts "at end"
moulon%

moulon% ./b.rb 2
gc
obj_id -605498718
at end
obj_id -605498798
moulon%

only one object is freed when GC.start run and you can see it with this case

moulon% ./b.rb 1
gc
at end
obj_id -605640028
moulon%


ruby call the finalizer at the end only, because when GC.start run it
find a reference to the object (in cache) on the stack and mark it


Guy Decoux

 

[Devin Mullins]

I'm trying to work out ways to reduce the memory use of one of my
projects, but I don't know what methods are available to the Ruby
programmer for profiling memory use and tracking down garbage
collection problems.

There's a commercial option for Windows:
http://www.softwareverify.com/productsRuby.html

Never tried it, though Stefan Kaes has raved about the call graph
profiler, IIRC.

Devin

 

[Robert Klemme]

Thanks, Robert. That is excellent advice. The method in question looks
basically like this:

def parse
# do stuff
cache = MemoizingCache.new
# do more stuff
end

I changed this to read as follows:

def parse
# do stuff
cache = MemoizingCache.new
$stderr.print "New cache id #{cache.object_id}\n"
ObjectSpace.define_finalizer(cache, lambda { |id| $stderr.print
"Finalizer for id #{id}\n"})
# do more stuff
end

And have confirmed that the cache finalizers are not being called. I
haven't found out how the reference to the local "cache" variable is
being kept alive even after it falls out of scope, but you've given me
the tool necessary to at least find out what's happening.

Careful! As Guy pointed out your code basically locks cache in memory
itself.

You should rather do something like this:

def create_finalizer_for(id)
lambda { puts "Final #{id}" }
end

and use that method to create the finalizer lambda.

def parse
# do stuff
cache = MemoizingCache.new
$stderr.print "New cache id #{cache.object_id}\n"
ObjectSpace.define_finalizer(cache, create_finalizer(cache.object_id))
# do more stuff
end

HTH

robert

 

[Wincent Colaiuta]

Careful! As Guy pointed out your code basically locks cache in memory
itself.

Whoops, just copied it out of the Pickaxe (p 557) without thinking.
Very silly on my part, as it was only this morning that I had read a
thread about lambda vs GC.

I've now corrected it and am seeing the following... basically, given
a bunch of calls to the parse method, the finalizer ends up getting
called only some of the time... as you can see, the behavior is
intermittent, so could be tricky to figure out what's going on....
will continue researching...

New cache id 8678420
New cache id 10593850
New cache id 48994460
New cache id 48866440
Finalizer for id: 48866440
New cache id 80838620
New cache id 78949240
New cache id 136249000
New cache id 136172780
Finalizer for id: 136172780
New cache id 133839600
New cache id 131776570
New cache id 237020660
New cache id 237898220
New cache id 230110170
New cache id 231098300
New cache id 227400170
New cache id 226363890
New cache id 225338080
New cache id 224079680
New cache id 415597520
New cache id 416817550
Finalizer for id: 416817550
etc...

Cheers,
Wincent

 

[Robert Klemme]

Whoops, just copied it out of the Pickaxe (p 557) without thinking.
Very silly on my part, as it was only this morning that I had read a
thread about lambda vs GC.

I've now corrected it and am seeing the following... basically, given
a bunch of calls to the parse method, the finalizer ends up getting
called only some of the time... as you can see, the behavior is
intermittent, so could be tricky to figure out what's going on....
will continue researching...

Maybe you leak only under certain conditions. Dunno how complex your
code in parse is but this seems to be an option. Maybe you can print
more along with the cache's id so as to get an idea in which cases you
don't see finalization.

robert

 

[Wincent Colaiuta]

Maybe you leak only under certain conditions. Dunno how complex your
code in parse is but this seems to be an option. Maybe you can print
more along with the cache's id so as to get an idea in which cases you
don't see finalization.

I'll do that.

One thing which is puzzling me in the meantime is why GC doesn't seem
to work in the following example:

# start example

def finalizer(thing)
puts "setting up finalizer for #{thing}"
lambda { puts "finalizer for #{thing}" }
end

def meth
foo = "hello, world!"
ObjectSpace.define_finalizer(foo, finalizer(foo.object_id))
end

puts "about to call meth"
meth
puts "did call meth"

puts "about to start GC"
GC.start
puts "did start GC"
def finalizer(thing)
puts "setting up finalizer for #{thing}"
lambda { puts "finalizer for #{thing}" }
end

def meth
foo = "hello, world!"
ObjectSpace.define_finalizer(foo, finalizer(foo.object_id))
end

puts "about to call meth"
meth
puts "did call meth"

puts "about to start GC"
GC.start
puts "did start GC"

# end example

On my system the output:

about to call meth
setting up finalizer for 1005330
did call meth
about to start GC
did start GC
finalizer for 1005330

I would have thought that the explicit GC would cause foo's finalizer
to be called immediately, but no, it only gets called just before the
process exits.

This isn't the only case in which GC doesn't perform as I would
expect... As another example, the WeakRef code listing on page 732 of
the Pickaxe doesn't work either. It's supposed to print:

Initial object is fol de rol
Weak reference is fol de rol
prog.rb:8: Illegal Reference - probably recycled (WeakRef::RefError)

But for me it prints:

Initial object is fol de rol
Weak reference is fol de rol
Initial object is fol de rol

So either something is awry with the listing, with my understanding of
GC, or with my local Ruby install (1.8.6 on Mac OS X 10.4.9).

Cheers,
Wincent

 

[Robert Klemme]

I'll do that.

One thing which is puzzling me in the meantime is why GC doesn't seem
to work in the following example:

# start example

def finalizer(thing)
puts "setting up finalizer for #{thing}"
lambda { puts "finalizer for #{thing}" }
end

def meth
foo = "hello, world!"
ObjectSpace.define_finalizer(foo, finalizer(foo.object_id))
end

puts "about to call meth"
meth
puts "did call meth"

puts "about to start GC"
GC.start
puts "did start GC"
def finalizer(thing)
puts "setting up finalizer for #{thing}"
lambda { puts "finalizer for #{thing}" }
end

def meth
foo = "hello, world!"
ObjectSpace.define_finalizer(foo, finalizer(foo.object_id))
end

puts "about to call meth"
meth
puts "did call meth"

puts "about to start GC"
GC.start
puts "did start GC"

# end example

On my system the output:

about to call meth
setting up finalizer for 1005330
did call meth
about to start GC
did start GC
finalizer for 1005330

I would have thought that the explicit GC would cause foo's finalizer
to be called immediately, but no, it only gets called just before the
process exits.

You have wrong expectations about GC. Whenever a garbage collected
language offers explicit start of GC there is usually no guarantee that
actually all space will be reclaimed at that time. It's rather a hint
to the GC that it might be a good idea to start collecting. Whether
that actually happens and how much is collected is completely at the
discretion of the GC's implementation.

This isn't the only case in which GC doesn't perform as I would
expect... As another example, the WeakRef code listing on page 732 of
the Pickaxe doesn't work either. It's supposed to print:

Initial object is fol de rol
Weak reference is fol de rol
prog.rb:8: Illegal Reference - probably recycled (WeakRef::RefError)

But for me it prints:

Initial object is fol de rol
Weak reference is fol de rol
Initial object is fol de rol

So either something is awry with the listing, with my understanding of
GC, or with my local Ruby install (1.8.6 on Mac OS X 10.4.9).

The second option.

robert

 

[ts]

W> One thing which is puzzling me in the meantime is why GC doesn't seem
W> to work in the following example:

Well, you must understand that the GC is conservative, this mean that it
can mark object which are not used any more by ruby, and more it work at
assembler level (sort of) when you look at ruby level.

Here your example on *my* system

moulon% cat b.rb
#!/usr/bin/ruby
def finalizer(thing)
puts "setting up finalizer for #{thing}"
lambda { puts "finalizer for #{thing}" }
end

def meth
foo = "hello, world!"
ObjectSpace.define_finalizer(foo, finalizer(foo.object_id))
end

meth
puts "about to start GC"
GC.start
puts "did start GC"

meth
puts "about to start GC"
GC.start
puts "did start GC"

moulon%

moulon% ./b.rb
setting up finalizer for -605724018
about to start GC
did start GC
setting up finalizer for -605722868
about to start GC
did start GC
finalizer for -605724018
finalizer for -605722868
moulon%

When the GC run, it find the 2 objects on the C stack and mark it, now if
it write it like this

moulon% diff -u b.rb~ b.rb
--- b.rb~ 2007-04-24 11:34:04.000000000 +0200
+++ b.rb 2007-04-24 11:34:21.000000000 +0200
@@ -9,12 +9,12 @@
ObjectSpace.define_finalizer(foo, finalizer(foo.object_id))
end

-meth
+1.times { meth }
puts "about to start GC"
GC.start
puts "did start GC"

-meth
+1.times { meth }
puts "about to start GC"
GC.start
puts "did start GC"
moulon%

moulon% ./b.rb
setting up finalizer for -605810148
about to start GC
did start GC
setting up finalizer for -605808898
about to start GC
finalizer for -605810148
did start GC
finalizer for -605808898
moulon%

and worst

moulon% diff -u b.rb~ b.rb
--- b.rb~ 2007-04-24 11:34:04.000000000 +0200
+++ b.rb 2007-04-24 11:35:15.000000000 +0200
@@ -9,12 +9,12 @@
ObjectSpace.define_finalizer(foo, finalizer(foo.object_id))
end

-meth
+1.times { 1.times { meth } }
puts "about to start GC"
GC.start
puts "did start GC"

-meth
+1.times { 1.times { meth } }
puts "about to start GC"
GC.start
puts "did start GC"
moulon%

moulon% ./b.rb
setting up finalizer for -605462098
about to start GC
finalizer for -605462098
did start GC
setting up finalizer for -605461048
about to start GC
finalizer for -605461048
did start GC
moulon%

I've just made in sort to call #meth with enough stack to make in sort
that the GC don't find the variable in the stack.when it run.

But remember this is on *my* system and it can give different results on
*your* system and *this is NOT important*


Guy Decoux