Recently we had to investigate a page that had very poor performance. The project used newrelic, but neither that, the application’s logs nor render traces gave clear results. The database wasn’t the bottleneck, but there were well over 100 partials in the render trace. These partials seemed to perform well, except sometimes the same partial would take hundreds to thousands of milliseconds.

As it turns out, the cause of these random delays was actually garbage collection triggered by abusive memory consumption within many of the partials – millions of objects and heap growth in excess of 100mb. We discovered this by using the memory and GC statistics features of Ruby Enterprise Edition. You can get an idea of how much memory is being used and garbage collected during rendering by wrapping parts of your page in a block passed to this helper:

def gc_profile
  raise "Dude, you left GC profiling on!" unless Rails.env.development?
  allocated_objects_before = ObjectSpace.allocated_objects
  GC.enable_stats
  GC.clear_stats

  yield if block_given?

  growth = GC.growth
  collections = GC.collections
  time = GC.time
  mallocs = GC.num_allocations
  allocated_objects = ObjectSpace.allocated_objects - allocated_objects_before
  GC.disable_stats

  concat content_tag :span, "GC growth: #{growth}b, collections: #{collections}, time #{time / 1000000.0}sec, #{mallocs} mallocs, #{allocated_objects} objects created."
end

Because there were so many partials on the page, moving the helper around to identify the most egregious memory abusers got tiring so I wrote a monkeypatch to the venerable Rack::Bug plug-in which shows you memory consumption and garbage collection statistics for each template shown in the Rack::Bug template trace, as well as on the memory panel.

First, install Rack::Bug and make sure it’s working properly, then add the code below in an initializer. Keep in mind this was written to work with Ruby Enterprise Edition 1.8.7 2010.02. Various 1.8 patches and Ruby 1.9 also provide some GC statistics reporting tools which you could probably customize this patch to use instead.

if Rails.env.development?
  require 'rack/bug'

  Rack::Bug::TemplatesPanel::Trace.class_eval do
    alias_method :old_start, :start
    def start(template_name)
      old_start(template_name)
      @initial_allocated_objects = ObjectSpace.allocated_objects
      @initial_allocated_size = GC.allocated_size
      @initial_num_allocations = GC.num_allocations
      @initial_gc_count = GC.collections
      @initial_gc_time = GC.time
    end

    alias_method :old_finished, :finished
    def finished(template_name)
      @current.allocated_objects = ObjectSpace.allocated_objects - @initial_allocated_objects
      @current.allocated_size = GC.allocated_size - @initial_allocated_size
      @current.num_allocations = GC.num_allocations - @initial_num_allocations
      @current.gc_count = GC.collections - @initial_gc_count
      @current.gc_time = (GC.time - @initial_gc_time)/1000.0
      old_finished(template_name)
    end
  end

  Rack::Bug::TemplatesPanel::Rendering.class_eval do
    attr_accessor :allocated_objects
    attr_accessor :allocated_size
    attr_accessor :num_allocations
    attr_accessor :gc_count
    attr_accessor :gc_time

    def memory_summary
      %{<strong>%.2fms</strong><small>in</small><strong>%d</strong><small>GCs</small>
      <strong>%d</strong><small>new objects</small>
      <strong>%d</strong><small>bytes in</small><strong>%d</strong><small>mallocs</small>} % [gc_time, gc_count, allocated_objects, allocated_size, num_allocations]
    end

    def html
      %{<li>
          <p>#{name} (#{time_summary}) [#{memory_summary}]</p>
          #{children_html}
        </li>}
    end
  end

  Rack::Bug::MemoryPanel.class_eval do
    alias_method :old_before, :before
    def before(env)
      old_before(env)
      GC.enable_stats
      GC.clear_stats
      @initial_allocated_objects = ObjectSpace.allocated_objects
      @initial_allocated_size = GC.allocated_size
      @initial_num_allocations = GC.num_allocations
    end

    alias_method :old_after, :after
    def after(env, status, headers, body)
      old_after(env, status, headers, body)
      @gc_count = GC.collections
      @gc_time = GC.time / 1000.0
      @allocated_objects = ObjectSpace.allocated_objects - @initial_allocated_objects
      @allocated_size = GC.allocated_size - @initial_allocated_size
      @num_allocations = GC.num_allocations - @initial_num_allocations
    end

    def heading
      "#{@memory_increase} KB &#916;, #{@total_memory} KB total, %.2fms in #{@gc_count} GCs" % @gc_time
    end

    def has_content?
      true
    end

    def name
      "memory_panel"
    end

    def content
      %{<style>#memory_panel dd { font-size: large; }</style>
        <h3>Garbage Collection Stats</h3>
        <dl>
          <dt>Garbage collection runs</dt>
          <dd>%d</dd>
          <dt>Time spent in GC</dt>
          <dd>%.2fms</dd>
          <dt>Objects created</dt>
          <dd>%d</dd>
          <dt>Bytes allocated</dt>
          <dd>%d</dd>
          <dt>Allocation calls</dt>
          <dd>%d</dd>
      </dl>} % [@gc_count, @gc_time, @allocated_objects, @allocated_size, @num_allocations]
    end
  end
end