Memory leak profiling with Rails
Posted by Scott Laird Fri, 18 Aug 2006 04:57:38 GMT
One of my long-running problems with Rails (and Ruby in general) is that it’s difficult to debug memory leaks. I’ve had a number of cases where I’ve stuck something into a long-lived array or hash and discovered much later that my Ruby process was eating over 100 MB of RAM. While ps makes it easy to see when Ruby’s using lots of RAM, actually figuring out where it went is a lot harder.
Several people have been working on memory leak debuggers for Rails, and for Typo in general, including Steve Longdo, but I didn’t have a lot of luck actually finding leaks with their tools. I asked the Seattle Ruby Group for help, and Ryan Davis gave me a quick little memory leak spotter that he uses. I made a few additions to it, and it helped me discover that my Typo development tree was leaking 1-3 strings per hit, but it didn’t help me figure out where the leak was happening. After playing with a few options, I settled on dumping all strings to a file once per memory profiler loop, and then I diffed the files that showed my problem. It took about 15 seconds to discover a bug in my route cache code, and about 30 seconds more to fix it.
I’ll package this up as a Rails plugin eventually, but I thought it might be worth sharing here for now. Just load this code and then call MemoryProfiler.start. By default it logs a record of the 20 classes with the biggest changes over the last 10 seconds; you can change the cycle speed by adding :delay => 20 to the start command, and you can dump all strings to a file on each loop by adding :string_debug => true. Don’t leave string debugging on for too long; it’ll eat a ton of disk space.
class MemoryProfiler
DEFAULTS = {:delay => 10, :string_debug => false}
def self.start(opt={})
opt = DEFAULTS.dup.merge(opt)
Thread.new do
prev = Hash.new(0)
curr = Hash.new(0)
curr_strings = []
delta = Hash.new(0)
file = File.open('log/memory_profiler.log','w')
loop do
begin
GC.start
curr.clear
curr_strings = [] if opt[:string_debug]
ObjectSpace.each_object do |o|
curr[o.class] += 1 #Marshal.dump(o).size rescue 1
if opt[:string_debug] and o.class == String
curr_strings.push o
end
end
if opt[:string_debug]
File.open("log/memory_profiler_strings.log.#{Time.now.to_i}",'w') do |f|
curr_strings.sort.each do |s|
f.puts s
end
end
curr_strings.clear
end
delta.clear
(curr.keys + delta.keys).uniq.each do |k,v|
delta[k] = curr[k]-prev[k]
end
file.puts "Top 20"
delta.sort_by { |k,v| -v.abs }[0..19].sort_by { |k,v| -v}.each do |k,v|
file.printf "%+5d: %s (%d)\n", v, k.name, curr[k] unless v == 0
end
file.flush
delta.clear
prev.clear
prev.update curr
GC.start
rescue Exception => err
STDERR.puts "** memory_profiler error: #{err}"
end
sleep opt[:delay]
end
end
end
endAs usual, the good bits are Ryan’s, and the bad bits are mine.
