diff options
Diffstat (limited to 'railties/doc/guides/source/performance_testing.txt')
| -rw-r--r-- | railties/doc/guides/source/performance_testing.txt | 433 |
1 files changed, 320 insertions, 113 deletions
diff --git a/railties/doc/guides/source/performance_testing.txt b/railties/doc/guides/source/performance_testing.txt index b741ddfd00..84a42cecde 100644 --- a/railties/doc/guides/source/performance_testing.txt +++ b/railties/doc/guides/source/performance_testing.txt @@ -1,108 +1,164 @@ -Performance testing Rails Applications +Performance Testing Rails Applications ====================================== -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: +This guide covers the various ways of performance testing a Ruby on Rails application. By referring to this guide, you will be able to: * Understand the various types of benchmarking and profiling metrics -* Generate performance/benchmarking tests -* Use GC patched Ruby binary to measure memory usage and object allocation -* Understand the information provided by Rails inside the log files +* Generate performance and benchmarking tests +* Use a GC-patched Ruby binary to measure memory usage and object allocation +* Understand the benchmarking information provided by Rails inside the log files * Learn about various tools facilitating benchmarking and profiling -Performance testing 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. +Performance testing 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 pleasant browsing experience for end users and cutting the cost of unnecessary hardware is important for any non-trivial web application. -== Using and understanding the log files == - -Rails logs files containt basic but very useful information about the time taken to serve every request. A typical log entry looks something like : +== Performance Test Cases == -[source, ruby] ----------------------------------------------------------------------------- -Processing ItemsController#index (for 127.0.0.1 at 2009-01-08 03:06:39) [GET] -Rendering template within layouts/items -Rendering items/index -Completed in 5ms (View: 2, DB: 0) | 200 OK [http://0.0.0.0/items] ----------------------------------------------------------------------------- +Rails performance tests are a special type of integration tests, designed for benchmarking and profiling the test code. With performance tests, you can determine where your application's memory or speed problems are coming from, and get a more in-depth picture of those problems. -For this section, we're only interested in the last line from that log entry: +In a freshly generated Rails application, +test/performance/browsing_test.rb+ contains an example of a performance test: [source, ruby] ---------------------------------------------------------------------------- -Completed in 5ms (View: 2, DB: 0) | 200 OK [http://0.0.0.0/items] +require 'test_helper' +require 'performance_test_help' + +# Profiling results for each test method are written to tmp/performance. +class BrowsingTest < ActionController::PerformanceTest + def test_homepage + get '/' + end +end ---------------------------------------------------------------------------- -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. +This example is a simple performance test case for profiling a GET request to the application's homepage. -== Helper methods == +=== Generating performance tests === -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. +Rails provides a generator called +performance_test+ for creating new performance tests: -[source, ruby] +[source, shell] ---------------------------------------------------------------------------- -Project.benchmark("Creating project") do - project = Project.create("name" => "stuff") - project.create_manager("name" => "David") - project.milestones << Milestone.find(:all) -end +script/generate performance_test homepage ---------------------------------------------------------------------------- -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: +This generates +homepage_test.rb+ in the +test/performance+ directory: [source, ruby] ---------------------------------------------------------------------------- -Creating projectem (185.3ms) +require 'test_helper' +require 'performance_test_help' + +class HomepageTest < ActionController::PerformanceTest + # Replace this with your real tests. + def test_homepage + get '/' + end +end ---------------------------------------------------------------------------- -Please refer to http://api.rubyonrails.com/classes/ActiveRecord/Base.html#M001336[API docs] for optional options to +benchmark()+ +=== Examples === -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 ): +Let's assume your application has the following controller and model: [source, ruby] ---------------------------------------------------------------------------- -def process_projects - self.class.benchmark("Processing projects") do - Project.process(params[:project_ids]) - Project.update_cached_projects +# routes.rb +map.root :controller => 'home' +map.resources :posts + +# home_controller.rb +class HomeController < ApplicationController + def dashboard + @users = User.last_ten(:include => :avatars) + @posts = Post.all_today + end +end + +# posts_controller.rb +class PostsController < ApplicationController + def create + @post = Post.create(params[:post]) + redirect_to(@post) + end +end + +# post.rb +class Post < ActiveRecord::Base + before_save :recalculate_costly_stats + + def slow_method + # I fire gallzilion queries sleeping all around + end + + private + + def recalculate_costly_stats + # CPU heavy calculations end end ---------------------------------------------------------------------------- -and http://api.rubyonrails.com/classes/ActionController/Benchmarking/ClassMethods.html#M000715[views]: +==== Controller Example ==== + +Because performance tests are a special kind of integration test, you can use the +get+ and +post+ methods in them. + +Here's the performance test for +HomeController#dashboard+ and +PostsController#create+: [source, ruby] ---------------------------------------------------------------------------- -<% benchmark("Showing projects partial") do %> - <%= render :partial => @projects %> -<% end %> +require 'test_helper' +require 'performance_test_help' + +class PostPerformanceTest < ActionController::PerformanceTest + def setup + # Application requires logged-in user + login_as(:lifo) + end + + def test_homepage + get '/dashboard' + end + + def test_creating_new_post + post '/posts', :post => { :body => 'lifo is fooling you' } + end +end ---------------------------------------------------------------------------- -== Performance Test Cases == +You can find more details about the +get+ and +post+ methods in the link:../testing_rails_applications.html#mgunderloy[Testing Rails Applications] guide. + +==== Model Example ==== -Rails provides a very easy way to write performance test cases, which look just like the regular integration tests. Performance tests run a code profiler on your test methods. Profiling output for combinations of each test method, measurement, and output format are written to your +tmp/performance+ directory. By default, process_time is measured and both flat and graph_html output formats are written, so you'll have two output files per test method. +Even though the performance tests are integration tests and hence closer to the request/response cycle by nature, you can still performance test pure model code. -If you have a look at +test/performance/browsing_test.rb+ in a newly created Rails application: +Performance test for +Post+ model: [source, ruby] ---------------------------------------------------------------------------- require 'test_helper' require 'performance_test_help' -# Profiling results for each test method are written to tmp/performance. -class BrowsingTest < ActionController::PerformanceTest - def test_homepage - get '/' +class PostModelTest < ActionController::PerformanceTest + def test_creation + Post.create :body => 'still fooling you', :cost => '100' + end + + def test_slow_method + # Using posts(:awesome) fixture + posts(:awesome).slow_method end end ---------------------------------------------------------------------------- -This is an automatically generated example performance test file, for testing performance of homepage('/') of the application. - === Modes === -Performance test cases can be run in two modes : Benchmarking and Profling. +Performance tests can be run in two modes : Benchmarking and Profiling. ==== Benchmarking ==== -Benchmarking helps you find out how fast are your test cases. Each Test case is run +4 times+ in this mode. To run performance tests in benchmarking mode: +Benchmarking helps find out how fast each performance test runs. Each test case is run +4 times+ in benchmarking mode. + +To run performance tests in benchmarking mode: [source, shell] ---------------------------------------------------------------------------- @@ -111,7 +167,9 @@ $ rake test:benchmark ==== Profiling ==== -Profiling helps introspect into your test cases and figure out which are the slow parts. Each Test case is run +1 time+ in this mode. To run performance tests in profiling mode: +Profiling helps you see the details of a performance test and provide an in-depth picture of the slow and memory hungry parts. Each test case is run +1 time+ in profiling mode. + +To run performance tests in profiling mode: [source, shell] ---------------------------------------------------------------------------- @@ -120,47 +178,47 @@ $ rake test:profile === Metrics === -Benchmarking and profiling run performance test cases in various modes to help precisely figure out the where the problem lies. +Benchmarking and profiling run performance tests in various modes described below. ==== Wall Time ==== -Measures the real world time elapsed during the test run. It is affected by any other processes concurrently running on the system. +Wall time measures the real world time elapsed during the test run. It is affected by any other processes concurrently running on the system. Mode : Benchmarking ==== Process Time ==== -Measures the time taken by the process. It is unaffected by any other processes running concurrently on the same system. Hence, process time is likely to be constant for any given performance test, irrespective of the machine load. +Process time measures the time taken by the process. It is unaffected by any other processes running concurrently on the same system. Hence, process time is likely to be constant for any given performance test, irrespective of the machine load. Mode : Profiling ==== Memory ==== -Measures the amount of memory used for the performance test case. +Memory measures the amount of memory used for the performance test case. -Mode : Benchmarking, Profiling [Requires specially compiled Ruby] +Mode : Benchmarking, Profiling [xref:gc[Requires GC-Patched Ruby]] ==== Objects ==== -Measures the number of objects allocated for the performance test case. +Objects measures the number of objects allocated for the performance test case. -Mode : Benchmarking, Profiling [Requires specially compiled Ruby] +Mode : Benchmarking, Profiling [xref:gc[Requires GC-Patched Ruby]] ==== GC Runs ==== -Measures the number of times GC was invoked for the performance test case. +GC Runs measures the number of times GC was invoked for the performance test case. -Mode : Benchmarking [Requires specially compiled Ruby] +Mode : Benchmarking [xref:gc[Requires GC-Patched Ruby]] ==== GC Time ==== -Measures the amount of time spent in GC for the performance test case. +GC Time measures the amount of time spent in GC for the performance test case. -Mode : Benchmarking [Requires specially compiled Ruby] +Mode : Benchmarking [xref:gc[Requires GC-Patched Ruby]] === Understanding the output === -Performance tests generate different outputs inside +tmp/performance+ directory based on the mode it is run in and the metric. +Performance tests generate different outputs inside +tmp/performance+ directory depending on their mode and metric. ==== Benchmarking ==== @@ -182,7 +240,7 @@ BrowsingTest#test_homepage (31 ms warmup) ===== CSV files ===== -Performance tests results are also appended to +.csv+ files inside +tmp/performance/<Class>#<test>_<metric>.csv+ file. For example, running the default +BrowsingTest#test_homepage+ will generate following five files : +Performance test results are also appended to +.csv+ files inside +tmp/performance+. For example, running the default +BrowsingTest#test_homepage+ will generate following five files : - BrowsingTest#test_homepage_gc_runs.csv - BrowsingTest#test_homepage_gc_time.csv @@ -190,9 +248,9 @@ Performance tests results are also appended to +.csv+ files inside +tmp/performa - BrowsingTest#test_homepage_objects.csv - BrowsingTest#test_homepage_wall_time.csv -As the results are appended to these files each time the performance tests are run in benchmarking mode, it enables you gather data over a sustainable period of time which can be very helpful with various performance analysis. +As the results are appended to these files each time the performance tests are run in benchmarking mode, you can collect data over a period of time. This can be very helpful in analyzing the effects of code changes. -Sample output of +BrowsingTest#test_homepage_wall_time.csv + : +Sample output of +BrowsingTest#test_homepage_wall_time.csv+: [source, shell] ---------------------------------------------------------------------------- @@ -211,9 +269,11 @@ measurement,created_at,app,rails,ruby,platform ==== Profiling ==== +In profiling mode, you can choose from four types of output. + ===== Command line ===== -This is the very basic form of output in profiling mode. Example : +This is a very basic form of output in profiling mode: [source, shell] ---------------------------------------------------------------------------- @@ -225,103 +285,250 @@ BrowsingTest#test_homepage (58 ms warmup) ===== Flat ===== -Flat output shows the total amount of time spent in each method. http://ruby-prof.rubyforge.org/files/examples/flat_txt.html[Check ruby prof documentation for a better explaination]. +Flat output shows the total amount of time spent in each method. http://ruby-prof.rubyforge.org/files/examples/flat_txt.html[Check ruby prof documentation for a better explanation]. ===== Graph ===== -Graph output shows how long each method takes to run, which methods call it and which methods it calls. http://ruby-prof.rubyforge.org/files/examples/graph_txt.html[Check ruby prof documentation for a better explaination]. +Graph output shows how long each method takes to run, which methods call it and which methods it calls. http://ruby-prof.rubyforge.org/files/examples/graph_txt.html[Check ruby prof documentation for a better explanation]. ===== Tree ===== -Tree output is profiling information in calltree format for use by kcachegrind and similar tools. +Tree output is profiling information in calltree format for use by http://kcachegrind.sourceforge.net/html/Home.html[kcachegrind] and similar tools. + +=== Tuning Test Runs === + +By default, each performance test is run +4 times+ in benchmarking mode and +1 time+ in profiling. However, test runs can easily be configured. + +CAUTION: Performance test configurability is not yet enabled in Rails. But it will be soon. + +[[gc]] +=== Installing GC-Patched Ruby === + +To get the best from Rails performance tests, you need to build a special Ruby binary with some super powers - http://rubyforge.org/tracker/download.php/1814/7062/17676/3291/ruby186gc.patch[GC patch] for measuring GC Runs/Time and memory/object allocation. + +The process is fairly straight forward. If you've never compiled a Ruby binary before, follow these steps to build a ruby binary inside your home directory: -=== Preparing Ruby and Ruby-prof === +==== Installation ==== -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: +Compile Ruby and apply this http://rubyforge.org/tracker/download.php/1814/7062/17676/3291/ruby186gc.patch[GC Patch]: -==== Compile ==== +==== Download and Extract ==== [source, shell] ---------------------------------------------------------------------------- [lifo@null ~]$ mkdir rubygc -[lifo@null ~]$ wget ftp://ftp.ruby-lang.org/pub/ruby/1.8/ruby-1.8.6-p111.tar.gz -[lifo@null ~]$ tar -xzvf ruby-1.8.6-p111.tar.gz -[lifo@null ~]$ cd ruby-1.8.6-p111 -[lifo@null ruby-1.8.6-p111]$ curl http://rubyforge.org/tracker/download.php/1814/7062/17676/3291/ruby186gc.patch | patch -p0 -[lifo@null ruby-1.8.6-p111]$ ./configure --prefix=/Users/lifo/rubygc -[lifo@null ruby-1.8.6-p111]$ make && make install +[lifo@null ~]$ wget <download the latest stable ruby from ftp://ftp.ruby-lang.org/pub/ruby> +[lifo@null ~]$ tar -xzvf <ruby-version.tar.gz> +[lifo@null ~]$ cd <ruby-version> +---------------------------------------------------------------------------- + +==== Apply the patch ==== + +[source, shell] +---------------------------------------------------------------------------- +[lifo@null ruby-version]$ curl http://rubyforge.org/tracker/download.php/1814/7062/17676/3291/ruby186gc.patch | patch -p0 +---------------------------------------------------------------------------- + +==== Configure and Install ==== + +The following will install ruby in your home directory's +/rubygc+ directory. Make sure to replace +<homedir>+ with a full patch to your actual home directory. + +[source, shell] +---------------------------------------------------------------------------- +[lifo@null ruby-version]$ ./configure --prefix=/<homedir>/rubygc +[lifo@null ruby-version]$ make && make install ---------------------------------------------------------------------------- ==== Prepare aliases ==== -Add the following lines in your ~/.profile for convenience: +For convenience, add the following lines in your +~/.profile+: ---------------------------------------------------------------------------- -alias gcruby='/Users/lifo/rubygc/bin/ruby' -alias gcrake='/Users/lifo/rubygc/bin/rake' -alias gcgem='/Users/lifo/rubygc/bin/gem' -alias gcirb='/Users/lifo/rubygc/bin/irb' -alias gcrails='/Users/lifo/rubygc/bin/rails' +alias gcruby='~/rubygc/bin/ruby' +alias gcrake='~/rubygc/bin/rake' +alias gcgem='~/rubygc/bin/gem' +alias gcirb='~/rubygc/bin/irb' +alias gcrails='~/rubygc/bin/rails' ---------------------------------------------------------------------------- -==== Install rubygems and some basic gems ==== +==== Install rubygems and dependency gems ==== -Download http://rubyforge.org/projects/rubygems[Rubygems] and install it from source. Afterwards, install rake. rails, ruby-prof and rack gems: +Download http://rubyforge.org/projects/rubygems[Rubygems] and install it from source. Rubygem's README file should have necessary installation instructions. +Additionally, install the following gems : + + * +rake+ + * +rails+ + * +ruby-prof+ + * +rack+ + * +mysql+ + +If installing +mysql+ fails, you can try to install it manually: + +[source, shell] +---------------------------------------------------------------------------- +[lifo@null mysql]$ gcruby extconf.rb --with-mysql-config +[lifo@null mysql]$ make && make install +---------------------------------------------------------------------------- + +And you're ready to go. Don't forget to use +gcruby+ and +gcrake+ aliases when running the performance tests. + +== Command Line Tools == + +Writing performance test cases could be an overkill when you are looking for one time tests. Rails ships with two command line tools that enable quick and dirty performance testing: + +=== benchmarker === + ++benchmarker+ is a wrapper around Ruby's http://ruby-doc.org/core/classes/Benchmark.html[Benchmark] module. + +Usage: + +[source, shell] ---------------------------------------------------------------------------- -[lifo@null ~]$ gcgem install rake -[lifo@null ~]$ gcgem install rails -[lifo@null ~]$ gcgem install ruby-prof -[lifo@null ~]$ gcgem install rack +$ script/performance/benchmarker [times] 'Person.expensive_way' 'Person.another_expensive_way' ... ---------------------------------------------------------------------------- -==== Install MySQL gem ==== +Examples: +[source, shell] ---------------------------------------------------------------------------- -[lifo@null ~]$ gcgem install mysql +$ script/performance/benchmarker 10 'Item.all' 'CouchItem.all' ---------------------------------------------------------------------------- -If this fails, you can try to install it manually: +If the +[times]+ argument is omitted, supplied methods are run just once: +[source, shell] ---------------------------------------------------------------------------- -[lifo@null ~]$ cd /Users/lifo/rubygc/lib/ruby/gems/1.8/gems/mysql-2.7/ -[lifo@null mysql-2.7]$ gcruby extconf.rb --with-mysql-config -[lifo@null mysql-2.7]$ make && make install +$ script/performance/benchmarker 'Item.first' 'Item.last' ---------------------------------------------------------------------------- -=== Generating performance test === +=== profiler === + ++profiler+ is a wrapper around http://ruby-prof.rubyforge.org/[ruby-prof] gem. + +Usage: -Rails provides a generator for creating new performance tests: +[source, shell] +---------------------------------------------------------------------------- +$ script/performance/profiler 'Person.expensive_method(10)' [times] [flat|graph|graph_html] +---------------------------------------------------------------------------- + +Examples: [source, shell] ---------------------------------------------------------------------------- -[lifo@null application (master)]$ script/generate performance_test homepage +$ script/performance/profiler 'Item.all' ---------------------------------------------------------------------------- -This will generate +test/performance/homepage_test.rb+: +This will profile +Item.all+ in +RubyProf::WALL_TIME+ measure mode. By default, it prints flat output to the shell. + +[source, shell] +---------------------------------------------------------------------------- +$ script/performance/profiler 'Item.all' 10 graph +---------------------------------------------------------------------------- + +This will profile +10.times { Item.all }+ with +RubyProf::WALL_TIME+ measure mode and print graph output to the shell. + +If you want to store the output in a file: + +[source, shell] +---------------------------------------------------------------------------- +$ script/performance/profiler 'Item.all' 10 graph 2> graph.txt +---------------------------------------------------------------------------- + +== Helper methods == + +Rails provides various helper methods inside Active Record, Action Controller and Action View to measure the time taken by a given piece of code. The method is called +benchmark()+ in all the three components. + +=== Model === [source, ruby] ---------------------------------------------------------------------------- -require 'test_helper' -require 'performance_test_help' +Project.benchmark("Creating project") do + project = Project.create("name" => "stuff") + project.create_manager("name" => "David") + project.milestones << Milestone.find(:all) +end +---------------------------------------------------------------------------- -class HomepageTest < ActionController::PerformanceTest - # Replace this with your real tests. - def test_homepage - get '/' +This benchmarks the code enclosed in the +Project.benchmark("Creating project") do..end+ block and prints the result to the log file: + +[source, ruby] +---------------------------------------------------------------------------- +Creating project (185.3ms) +---------------------------------------------------------------------------- + +Please refer to the http://api.rubyonrails.com/classes/ActiveRecord/Base.html#M001336[API docs] for additional options to +benchmark()+ + +=== Controller === + +Similarly, you could use this helper method inside http://api.rubyonrails.com/classes/ActionController/Benchmarking/ClassMethods.html#M000715[controllers] + +NOTE: +benchmark+ is a class method inside controllers + +[source, ruby] +---------------------------------------------------------------------------- +def process_projects + self.class.benchmark("Processing projects") do + Project.process(params[:project_ids]) + Project.update_cached_projects end end ---------------------------------------------------------------------------- -Which you can modify to suit your needs. +=== View === + +And in http://api.rubyonrails.com/classes/ActionController/Benchmarking/ClassMethods.html#M000715[views]: + +[source, ruby] +---------------------------------------------------------------------------- +<% benchmark("Showing projects partial") do %> + <%= render :partial => @projects %> +<% end %> +---------------------------------------------------------------------------- -== Other Profiling Tools == +== Request Logging == + +Rails log files contain very useful information about the time taken to serve each request. Here's a typical log file entry: + +[source, ruby] +---------------------------------------------------------------------------- +Processing ItemsController#index (for 127.0.0.1 at 2009-01-08 03:06:39) [GET] +Rendering template within layouts/items +Rendering items/index +Completed in 5ms (View: 2, DB: 0) | 200 OK [http://0.0.0.0/items] +---------------------------------------------------------------------------- + +For this section, we're only interested in the last line: + +[source, ruby] +---------------------------------------------------------------------------- +Completed in 5ms (View: 2, DB: 0) | 200 OK [http://0.0.0.0/items] +---------------------------------------------------------------------------- + +This data is fairly straightforward 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. + +Michael Koziarski has an http://www.therailsway.com/2009/1/6/requests-per-second[interesting blog post] explaining the importance of using milliseconds as the metric. + +== Useful Profiling Tools == + +=== Rails Plugins and Gems === -* http://www.hpl.hp.com/research/linux/httperf/[httperf] * http://rails-analyzer.rubyforge.org/[Rails Analyzer] * http://www.flyingmachinestudios.com/projects/[Palmist] +* http://github.com/josevalim/rails-footnotes/tree/master[Rails Footnotes] +* http://github.com/dsboulder/query_reviewer/tree/master[Query Reviewer] + +=== External === + +* http://www.hpl.hp.com/research/linux/httperf[httperf] +* http://httpd.apache.org/docs/2.2/programs/ab.html[ab] +* http://jakarta.apache.org/jmeter[JMeter] + +== Commercial Products == + +Rails has been lucky to have three startups dedicated to Rails specific performance tools: -== Commercial products dedicated to Rails Perfomance == * http://www.newrelic.com[New Relic] * http://www.fiveruns.com[Fiveruns] * http://scoutapp.com[Scout] @@ -330,6 +537,6 @@ Which you can modify to suit your needs. http://rails.lighthouseapp.com/projects/16213-rails-guides/tickets/4[Lighthouse ticket] -* January 9, 2009: Rewrite by Pratik +* January 9, 2009: Complete rewrite by Pratik * October 17, 2008: First revision by Pratik -* September 6, 2008: Initial version by Matthew Bergman
\ No newline at end of file +* September 6, 2008: Initial version by Matthew Bergman |