Rails partials rendering has 10x spikes render time

Question

Looking ruby mini-profiler output I noticed this pattern of 5-6 partials rendering at about 6-7 ms each and then one rendering at an off 60-70 ms. I was wondering what would cause this, it looks like some sort of flushing. All model data is loaded when the view rendering start, so I know is not caused by lazy loading.

 Rendering: application/_row     7.1    +1107.0 
 Rendering: application/_row     68.7   +1115.0 
 Rendering: application/_row     6.7    +1184.0 
 ...     
 Rendering: application/_row     6.5    +1234.0 
 Rendering: application/_row     65.2   +1241.0 
 Rendering: application/_row     6.6    +1306.0 
 ...     
 Rendering: application/_row     6.6    +1321.0 
 Rendering: application/_row     66.6   +1328.0 
 Rendering: application/_row     6.6    +1395.0 
 ...     
 Rendering: application/_row     6.6    +1444.0 
 Rendering: application/_row     65.4   +1451.0 

Ruby 1.9.3p194, Rails 3.2.11

Answer 1

This is most certain MRI's garbage collector swiping the memory. I did some testing with a simple Rails app and a partial:

100.times{Test.new}

I could see the spikes just like you:

Rendered tests/_row.html.erb (3.9ms)
Rendered tests/_row.html.erb (45.3ms)
Rendered tests/_row.html.erb (5.2ms)
...
Rendered tests/_row.html.erb (42.8ms)

Using mini-profiler, it's pretty easy to check how many times the GC was called and, more important, how long it ran. For me, these numbers perfectly matched. If there were 10 spikes, there were also 10 (+/-1) GC calls and also the runtimes of the GC were exactly the difference between the normal renderings and the ones that took longer.

To use the GC timer of mini-profiler append ?pp=profile-gc-time to your URL. There's also a great post about tuning Ruby with mini-profiler.