Tracking down a garbage collection problem

Ruby
1

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/

2

On 21.04.2007 13:23, Wincent C. wrote:

I would expect garbage collection to kick in along the way but it
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

3

Wincent C. wrote:

I would expect garbage collection to kick in along the way but it
garbage collected when I move on to the next file; the cache itself
Wincent

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

Well … where to begin?? :slight_smile:

  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. :slight_smile: 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.

–
M. Edward (Ed) Borasky, FBG, AB, PTA, PGS, MS, MNLP, NST, ACMC(P)
http://borasky-research.net/

If God had meant for carrots to be eaten cooked, He would have given
rabbits fire.

4

“W” == Wincent C. [email protected] writes:

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

5

Wincent C. wrote:

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:
Software Tools | Software Verify

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

Devin

6

On 21 abr, 16:50, Robert K. [email protected] wrote:

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

7

On 23.04.2007 11:03, Wincent C. wrote:

do more stuff

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

8

On 23 abr, 15:24, Robert K. [email protected] wrote:

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

9

On 23.04.2007 19:10, Wincent C. wrote:

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

10

On 23.04.2007 22:47, Wincent C. wrote:

end
lambda { puts “finalizer for #{thing}” }

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.

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. :slight_smile:

robert

11

On 23 abr, 20:49, Robert K. [email protected] wrote:

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

12

“W” == Wincent C. [email protected] writes:

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