Rails performance scripts: profiler and benchmarker
Filed Under (Performance, Rails, Ruby) by Leonardo Borges on 20-11-2008
There are several ways you can measure your rails application’s performance. The techniques range from filling your code with “puts” statements - :p - to fancy ones like NewRelic - which is quite nice, I must say.
But what many people don’t know is that rails ships with a handful of scripts to help you out. One of which is called profiler, located under your application’s scripts/performance directory.
By default it uses the standard ruby profiler but if you want more speed - and additional reporting options - , consider installing the ruby-prof gem.
So if you execute it without params, you’ll get a clue of how it works:
$ script/performance/profiler Usage: ./script/performance/profiler 'Person.expensive_method(10)' [times] [flat|graph|graph_html]
Pretty self explanatory, right?
As a sample code, I have in my rails app a dumb model with a really dumb method I wanna profile:
class Article < ActiveRecord::Base def self.find_all_with_delay sleep 10 self.find(:all) end end
Clearly this method doesn’t perform well and is a bottle neck in our super application! But let’s see what rails’ profiler tells us:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 | $ script/performance/profiler 'Article.find_all_with_delay' 1 graph > text_graph.perf Loading Rails... Using the ruby-prof extension. Thread ID: 109440 Total Time: 10.147995 %total %self total self wait child calls Name -------------------------------------------------------------------------------- 100.00% 0.00% 10.15 0.00 0.00 10.15 1 Global#[No method] (/Users/leo/projects/test/vendor/rails/railties/lib/commands/performance/profiler.rb:24} /Users/leo/projects/test/vendor/rails/railties/lib/commands/performance/profiler.rb:24 10.15 0.00 0.00 10.15 1/1 Object#profile_me -------------------------------------------------------------------------------- 10.15 0.00 0.00 10.15 1/1 Global#[No method] 100.00% 0.00% 10.15 0.00 0.00 10.15 1 Object#profile_me ((eval):1} (eval):1 0.00 0.00 0.00 0.00 1/1 Class#const_missing 10.15 0.00 0.00 10.15 1/1 <Class::Article(id: integer, name: string, content: string, created_at: datetime, updated_at: datetime)>#find_all_with_delay -------------------------------------------------------------------------------- 10.15 0.00 0.00 10.15 1/1 Object#profile_me 99.97% 0.00% 10.15 0.00 0.00 10.15 1 <Class::Article(id: integer, name: string, content: string, created_at: datetime, updated_at: datetime)>#find_all_with_delay (/Users/leo/projects/test/app/models/article.rb:2} /Users/leo/projects/test/app/models/article.rb:2 0.15 0.00 0.00 0.15 1/1 <Class::ActiveRecord::Base>#find 10.00 10.00 0.00 0.00 1/1 Kernel#sleep -------------------------------------------------------------------------------- 10.00 10.00 0.00 0.00 1/1 <Class::Article(id: integer, name: string, content: string, created_at: datetime, updated_at: datetime)>#find_all_with_delay 98.54% 98.54% 10.00 10.00 0.00 0.00 1 Kernel#sleep (ruby_runtime:0} ruby_runtime:0 -------------------------------------------------------------------------------- ... |
As you can see, the group around line 13 is where most of the time is spent, going through our stupid call to Kernel#sleep and detailing every and each call from the very beginning. The report is much larger, so I recommend you give it a try. It’s really useful.
Now, displeased with my method’s performance, I wrote a new one that I think performs much better:
def self.find_all_with_less_delay sleep 5 self.find(:all) end
Nice huh? 
But how can we be sure it performs better? It turns out that under scripts/performance there is another useful script: benchmarker
Again, running it without arguments reveals it’s usage:
$ script/performance/benchmarker Usage: ./script/performance/benchmarker [times] 'Person.expensive_way' 'Person.another_expensive_way' ...
So, ready to see which one of my methods performs better? Let’s check:
$ script/performance/benchmarker 1 'Article.find_all_with_delay' 'Article.find_all_with_less_delay' user system total real #1 0.020000 0.000000 0.020000 ( 10.016033) #2 0.010000 0.000000 0.010000 ( 5.015390)
Pretty neat way to benchmark your methods huh?
Profiler and benchmarker are a powerful combination that have been helping me a lot in the projects I’m working on.
Hope you like it! See u soon! 
