Rails Performance Scripts: Profiler and Benchmarker

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
    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:


$ 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 #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 #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 #find
10.00 10.00 0.00 0.00 1/1 Kernel#sleep
--------------------------------------------------------------------------------
10.00 10.00 0.00 0.00 1/1 #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! ;)

Comments