CODEWITHSUNDEEP
ruby-on-railsrubypartial-viewsmvc-mini-profiler
Remus Rusanu
Remus Rusanu

Reputation: 294297

Rails partials rendering has 10x spikes render time

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

Upvotes: 5

Views: 583

Answers (1)

user324242
user324242

Reputation:

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.

Upvotes: 5

Related Questions