vendor/rails/railties/doc/guides/source/benchmarking_and_profiling/index.txt

   1 Benchmarking and Profiling Rails
   2 ================================
   3
   4 This guide covers the benchmarking and profiling tactics/tools of Rails and Ruby in general. By referring to this guide, you will be able to:
   5
   6 * Understand the various types of benchmarking and profiling metrics
   7 * Generate performance/benchmarking tests
   8 * Use GC patched Ruby binary to measure memory usage and object allocation
   9 * Understand the information provided by Rails inside the log files
  10 * Learn about various tools facilitating benchmarking and profiling
  11
  12 == Why Benchmark and Profile ?
  13
  14 Benchmarking and Profiling is an integral part of the development cycle. It is very important that you don't make your end users wait for too long before the page is completely loaded. Ensuring a plesant browsing experience to the end users and cutting cost of unnecessary hardwares is important for any web application.
  15
  16 === What is the difference between benchmarking and profiling ? ===
  17
  18 Benchmarking is the process of finding out if a piece of code is slow or not. Whereas profiling is the process of finding out what exactly is slowing down that piece of code.
  19
  20 == Using and understanding the log files ==
  21
  22 Rails logs files containt basic but very useful information about the time taken to serve every request. A typical log entry looks something like :
  23
  24 [source, ruby]
  25 ----------------------------------------------------------------------------
  26 Processing ItemsController#index (for 127.0.0.1 at 2008-10-17 00:08:18) [GET]
  27   Session ID: BAh7BiIKZmxhc2hJQzonQWN0aHsABjoKQHVzZWR7AA==--83cff4fe0a897074a65335
  28   Parameters: {"action"=>"index", "controller"=>"items"}
  29 Rendering template within layouts/items
  30 Rendering items/index
  31 Completed in 5ms (View: 2, DB: 0) | 200 OK [http://localhost/items]
  32 ----------------------------------------------------------------------------
  33
  34 For this section, we're only interested in the last line from that log entry:
  35
  36 [source, ruby]
  37 ----------------------------------------------------------------------------
  38 Completed in 5ms (View: 2, DB: 0) | 200 OK [http://localhost/items]
  39 ----------------------------------------------------------------------------
  40
  41 This data is fairly straight forward to understand. Rails uses millisecond(ms) as the metric to measures the time taken. The complete request spent 5 ms inside Rails, out of which 2 ms were spent rendering views and none was spent communication with the database. It's safe to assume that the remaining 3 ms were spent inside the controller.
  42
  43 == Helper methods ==
  44
  45 Rails provides various helper methods inside Active Record, Action Controller and Action View to measure the time taken by a specific code. The method is called +benchmark()+ in all three components.
  46
  47 [source, ruby]
  48 ----------------------------------------------------------------------------
  49 Project.benchmark("Creating project") do
  50   project = Project.create("name" => "stuff")
  51   project.create_manager("name" => "David")
  52   project.milestones << Milestone.find(:all)
  53 end
  54 ----------------------------------------------------------------------------
  55
  56 The above code benchmarks the multiple statments enclosed inside +Project.benchmark("Creating project") do..end+ block and prints the results inside log files. The statement inside log files will look like:
  57
  58 [source, ruby]
  59 ----------------------------------------------------------------------------
  60 Creating projectem (185.3ms)
  61 ----------------------------------------------------------------------------
  62
  63 Please refer to http://api.rubyonrails.com/classes/ActiveRecord/Base.html#M001336[API docs] for optional options to +benchmark()+
  64
  65 Similarly, you could use this helper method inside http://api.rubyonrails.com/classes/ActionController/Benchmarking/ClassMethods.html#M000715[controllers] ( Note that it's a class method here ):
  66
  67 [source, ruby]
  68 ----------------------------------------------------------------------------
  69 def process_projects
  70   self.class.benchmark("Processing projects") do
  71     Project.process(params[:project_ids])
  72     Project.update_cached_projects
  73   end
  74 end
  75 ----------------------------------------------------------------------------
  76
  77 and http://api.rubyonrails.com/classes/ActionController/Benchmarking/ClassMethods.html#M000715[views]:
  78
  79 [source, ruby]
  80 ----------------------------------------------------------------------------
  81 <% benchmark("Showing projects partial") do %>
  82   <%= render :partial => @projects %>
  83 <% end %>
  84 ----------------------------------------------------------------------------
  85
  86 == Performance Test Cases ==
  87
  88 Rails provides a very easy to write performance test cases, which look just like the regular integration tests.
  89
  90 If you have a look at +test/performance/browsing_test.rb+ in a newly created Rails application:
  91
  92 [source, ruby]
  93 ----------------------------------------------------------------------------
  94 require 'test_helper'
  95 require 'performance_test_help'
  96
  97 # Profiling results for each test method are written to tmp/performance.
  98 class BrowsingTest < ActionController::PerformanceTest
  99   def test_homepage
 100     get '/'
 101   end
 102 end
 103 ----------------------------------------------------------------------------
 104
 105 This is an automatically generated example performance test file, for testing performance of homepage('/') of the application.
 106
 107 === Modes ===
 108
 109 ==== Benchmarking ====
 110 ==== Profiling ====
 111
 112 === Metrics ===
 113
 114 ==== Process Time ====
 115
 116 CPU Cycles.
 117
 118 ==== Memory ====
 119
 120 Memory taken.
 121
 122 ==== Objects ====
 123
 124 Objects allocated.
 125
 126 ==== GC Runs ====
 127
 128 Number of times the Ruby GC was run.
 129
 130 ==== GC Time ====
 131
 132 Time spent running the Ruby GC.
 133
 134 === Preparing Ruby and Ruby-prof ===
 135
 136 Before we go ahead, Rails performance testing requires you to build a special Ruby binary with some super powers - GC patch for measuring GC Runs/Time. This process is very straight forward. If you've never compiled a Ruby binary before, you can follow the following steps to build a ruby binary inside your home directory:
 137
 138 ==== Compile ====
 139
 140 [source, shell]
 141 ----------------------------------------------------------------------------
 142 [lifo@null ~]$ mkdir rubygc
 143 [lifo@null ~]$ wget ftp://ftp.ruby-lang.org/pub/ruby/1.8/ruby-1.8.6-p111.tar.gz
 144 [lifo@null ~]$ tar -xzvf ruby-1.8.6-p111.tar.gz
 145 [lifo@null ~]$ cd ruby-1.8.6-p111
 146 [lifo@null ruby-1.8.6-p111]$ curl http://rubyforge.org/tracker/download.php/1814/7062/17676/3291/ruby186gc.patch | patch -p0
 147 [lifo@null ruby-1.8.6-p111]$ ./configure --prefix=/Users/lifo/rubygc
 148 [lifo@null ruby-1.8.6-p111]$ make && make install
 149 ----------------------------------------------------------------------------
 150
 151 ==== Prepare aliases ====
 152
 153 Add the following lines in your ~/.profile for convenience:
 154
 155 ----------------------------------------------------------------------------
 156 alias gcruby='/Users/lifo/rubygc/bin/ruby'
 157 alias gcrake='/Users/lifo/rubygc/bin/rake'
 158 alias gcgem='/Users/lifo/rubygc/bin/gem'
 159 alias gcirb='/Users/lifo/rubygc/bin/irb'
 160 alias gcrails='/Users/lifo/rubygc/bin/rails'
 161 ----------------------------------------------------------------------------
 162
 163 ==== Install rubygems and some basic gems ====
 164
 165 ----------------------------------------------------------------------------
 166 [lifo@null ~]$ wget http://rubyforge.org/frs/download.php/38646/rubygems-1.2.0.tgz
 167 [lifo@null ~]$ tar -xzvf rubygems-1.2.0.tgz
 168 [lifo@null ~]$ cd rubygems-1.2.0
 169 [lifo@null rubygems-1.2.0]$ gcruby setup.rb
 170 [lifo@null rubygems-1.2.0]$ cd ~
 171 [lifo@null ~]$ gcgem install rake
 172 [lifo@null ~]$ gcgem install rails
 173 ----------------------------------------------------------------------------
 174
 175 ==== Install MySQL gem ====
 176
 177 ----------------------------------------------------------------------------
 178 [lifo@null ~]$ gcgem install mysql
 179 ----------------------------------------------------------------------------
 180
 181 If this fails, you can try to install it manually:
 182
 183 ----------------------------------------------------------------------------
 184 [lifo@null ~]$ cd /Users/lifo/rubygc/lib/ruby/gems/1.8/gems/mysql-2.7/
 185 [lifo@null mysql-2.7]$ gcruby extconf.rb --with-mysql-config
 186 [lifo@null mysql-2.7]$ make && make install
 187 ----------------------------------------------------------------------------
 188
 189 === Installing Jeremy Kemper's ruby-prof ===
 190
 191 We also need to install Jeremy's ruby-prof gem using our newly built ruby:
 192
 193 [source, shell]
 194 ----------------------------------------------------------------------------
 195 [lifo@null ~]$ git clone git://github.com/jeremy/ruby-prof.git
 196 [lifo@null ~]$ cd ruby-prof/
 197 [lifo@null ruby-prof (master)]$ gcrake gem
 198 [lifo@null ruby-prof (master)]$ gcgem install pkg/ruby-prof-0.6.1.gem
 199 ----------------------------------------------------------------------------
 200
 201 === Generating performance test ===
 202
 203 Rails provides a simple generator for creating new performance tests:
 204
 205 [source, shell]
 206 ----------------------------------------------------------------------------
 207 [lifo@null application (master)]$ script/generate performance_test homepage
 208 ----------------------------------------------------------------------------
 209
 210 This will generate +test/performance/homepage_test.rb+:
 211
 212 [source, ruby]
 213 ----------------------------------------------------------------------------
 214 require 'test_helper'
 215 require 'performance_test_help'
 216
 217 class HomepageTest < ActionController::PerformanceTest
 218   # Replace this with your real tests.
 219   def test_homepage
 220     get '/'
 221   end
 222 end
 223 ----------------------------------------------------------------------------
 224
 225 Which you can modify to suit your needs.
 226
 227 === Running tests ===
 228
 229 include::rubyprof.txt[]
 230
 231 include::digging_deeper.txt[]
 232
 233 include::gameplan.txt[]
 234
 235 include::appendix.txt[]
 236
 237 == Changelog ==
 238
 239 http://rails.lighthouseapp.com/projects/16213-rails-guides/tickets/4[Lighthouse ticket]
 240
 241 * October 17, 2008: First revision by Pratik
 242 * September 6, 2008: Initial version by Matthew Bergman <MzbPhoto@gmail.com>