Rails performance scripts: profiler and benchmarker

Filed Under (Performance, Rails, Ruby) by Leonardo Borges on 20-11-2008

Tagged Under : , ,

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! ;)

(1) Comment
Read More