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 Δ, #{@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
About the Author