Memory leak profiling with Rails

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
end

As usual, the good bits are Ryan’s, and the bad bits are mine.

Posted by Scott Laird Fri, 18 Aug 2006 04:57:38 GMT

Read full article 17 comments

Comments

Chris 4 days later:

Hi Scott,

I just used your memory profiler and came to the conclusion that strings present in my irb_history were being leaked on each request when in development[1].

Have you noticed this or do you not use irb_history?

Cheers for the code.

Chris

[1] http://blog.seagul.co.uk/articles/2006/08/22/rails-leaking-some-strings-in-development
Chris Shorrock 4 days later:

Great post, I recently started on a second contract using Rails and something that always troubled me, coming from the Java space, was the lack of profiling tools. This looks to be a great piece of code and something that will make it into all of my future projects in some way or another.
Pat Eyler 5 days later:

Great post Scott!

I’d love to see this packaged as a gem for Ruby in general rather than as a plugin restricting it to Rails users.
Robert J. Berger 7 days later:

For a Rails Noobie with a memory leak, could you clarify where’s the best place to call MemoryProfiler.start in a Rails app so it only gets called once?

Thanks
Chris Roos 7 days later:

Robert. I just started it from the last line of environment.rb.

I think this should be ok, although I may well be wrong.
Scott Laird 7 days later:

Yeah, just start it from environment.rb. I’ll write up some documentation and package it into a .gem when my schedule lets up a bit.
jay 10 days later:

why did you use GC.start the way you did?
Scott Laird 10 days later:

I used GC.start because it gives me a slightly more stable target to work with. I don’t really care about objects that GC can remove–I really only care about objects that can’t be GCed. Triggering GC before each round seems to help.
jay 11 days later:

thanks, that makes perfect sense. Do you need the second call to GC.start ?
Hendrik about 1 month later:

Thanks for publishing this!

One question I have is, how exactly did you diff the string files? My tools (GNU diff 2.8.1 and Apple’s Filemerge) tell me, the files are binary resp. not ASCII Futhermore they state there is a difference, but I was not able to figure out, where exactly. Editing the files in an editor would show up a long list of strings (the way it’s supposed to look), but I could not change the file to work with the diff-tools.
matthew about 1 month later:

Any tips on telling the difference between normal strings and leaked strings? I am seeing thousands of strings created/destroyed but the overall trend is for increase. Sometimes there is a net gain of hundreds of strings per hit. This is in production mode. Do I need to wait a while for things to settle down before I decide what is leaking? What kinds of strings should I be looking for and how would I get them to stop leaking?

So far I see mostly snippets of rhtml files in the string dump. Is that normal?
nicholas about 1 month later:

I would also like to have the same tips that matthew outlined.
Tom 3 months later:

I have the same questions as matthew and nicholas. I think a lot of us would benefit from a little more detail on how to put this information to use, identify the signal from the noise, etc.
Jean-Marc 4 months later:

Scott, I don’t know if your schedule ever got better but I took the liberty of opening a project on tigris.org using your MemoryProfiler as a base. I was having issues on a site I’m building (not officially launched so can’t really say more about it except its at http://search4stock.ca/ *wink*)

I added a few options to the original profiler to get data I could put in a graph.

Anyway… if you’re still interested in turning this could bunch of code into a plugin or a .gem (haven’t done one yet… would be really interesting knowing how to do it) the project is at rails-memoryprofiler-plugin.tigris.org

Cheers!
heri 5 months later:

thanks for the code. i have the same questions as matthew. i wouldnt know how to find in 15 sec a memory leak, as you wrote. i am unable to find the problematic line of code, a page render require in average 4/5 files for me (controller, helpers,partials …)
Mike Draper 8 months later:

/applaud

I have added a link to this post on my blog. This rocks!
Ray 12 months later:

I put the code in lib/memory_profiler.rb and call MemoryProfiler.start at the end of config/environment.rb. I do see output, but I got this error halfway thru loading a site’s homepage:

ActionView::TemplateError (Mysql::Error: Lost connection to MySQL server during query

The homepage loads fine without running MemoryProfiler.start thought. What am I missing?

scottstuff