1 Performance Test Cases
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.
In a freshly generated Rails application, test/performance/browsing_test.rb contains an example of a performance test:
require 'test_helper' require 'rails/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 example is a simple performance test case for profiling a GET request to the application’s homepage.
1.1 Generating Performance Tests
Rails provides a generator called test_unit:performance for creating new performance tests:
rails generate test_unit:performance homepage
This generates homepage_test.rb in the test/performance directory:
require 'test_helper' require 'rails/performance_test_help' class HomepageTest < ActionController::PerformanceTest # Replace this with your real tests. def test_homepage get '/' end end
1.2 Examples
Let’s assume your application has the following controller and model:
# 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
1.2.1 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:
require 'test_helper' require 'rails/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
You can find more details about the get and post methods in the Testing Rails Applications guide.
1.2.2 Model Example
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.
Performance test for Post model:
require 'test_helper' require 'rails/performance_test_help' 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
1.3 Modes
Performance tests can be run in two modes: Benchmarking and Profiling.
1.3.1 Benchmarking
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:
$ rake test:benchmark
1.3.2 Profiling
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:
$ rake test:profile
1.4 Metrics
Benchmarking and profiling run performance tests in various modes described below.
1.4.1 Wall Time
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
1.4.2 Process Time
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
1.4.3 Memory
Memory measures the amount of memory used for the performance test case.
Mode: Benchmarking, Profiling Requires GC Patched Ruby
1.4.4 Objects
Objects measures the number of objects allocated for the performance test case.
Mode: Benchmarking, Profiling Requires GC Patched Ruby
1.4.5 GC Runs
GC Runs measures the number of times GC was invoked for the performance test case.
Mode: Benchmarking Requires GC Patched Ruby
1.4.6 GC Time
GC Time measures the amount of time spent in GC for the performance test case.
Mode: Benchmarking Requires GC Patched Ruby
1.5 Understanding the Output
Performance tests generate different outputs inside tmp/performance directory depending on their mode and metric.
1.5.1 Benchmarking
In benchmarking mode, performance tests generate two types of outputs:
1.5.1.1 Command Line
This is the primary form of output in benchmarking mode. Example:
BrowsingTest#test_homepage (31 ms warmup) wall_time: 6 ms memory: 437.27 KB objects: 5514 gc_runs: 0 gc_time: 19 ms
1.5.1.2 CSV 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
- BrowsingTest#test_homepage_memory.csv
- 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, 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:
measurement,created_at,app,rails,ruby,platform 0.00738224999999992,2009-01-08T03:40:29Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00755874999999984,2009-01-08T03:46:18Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00762099999999993,2009-01-08T03:49:25Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00603075000000008,2009-01-08T04:03:29Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00619899999999995,2009-01-08T04:03:53Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00755449999999991,2009-01-08T04:04:55Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00595999999999997,2009-01-08T04:05:06Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00740450000000004,2009-01-09T03:54:47Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00603150000000008,2009-01-09T03:54:57Z,,3.0.0,ruby-1.8.7.249,x86_64-linux 0.00771250000000012,2009-01-09T15:46:03Z,,3.0.0,ruby-1.8.7.249,x86_64-linux
1.5.2 Profiling
In profiling mode, you can choose from four types of output.
1.5.2.1 Command Line
This is a very basic form of output in profiling mode:
BrowsingTest#test_homepage (58 ms warmup) process_time: 63 ms memory: 832.13 KB objects: 7882
1.5.2.2 Flat
Flat output shows the total amount of time spent in each method. Check ruby prof documentation for a better explanation.
1.5.2.3 Graph
Graph output shows how long each method takes to run, which methods call it and which methods it calls. Check ruby prof documentation for a better explanation.
1.5.2.4 Tree
Tree output is profiling information in calltree format for use by kcachegrind and similar tools.
1.6 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.
Performance test configurability is not yet enabled in Rails. But it will be soon.
1.7 Performance Test Environment
Performance tests are run in the test environment. But running performance tests will set the following configuration parameters:
ActionController::Base.perform_caching = true ActiveSupport::Dependencies.mechanism = :require Rails.logger.level = ActiveSupport::BufferedLogger::INFO
As ActionController::Base.perform_caching is set to true, performance tests will behave much as they do in the production environment.
1.8 Installing GC-Patched Ruby
To get the best from Rails performance tests, you need to build a special Ruby binary with some super powers – GC patch for measuring GC Runs/Time and memory/object allocation.
The process is fairly straightforward. If you’ve never compiled a Ruby binary before, follow these steps to build a ruby binary inside your home directory:
1.8.1 Installation
Compile Ruby and apply this GC Patch.
1.8.2 Download and Extract
[lifo@null ~]$ mkdir rubygc [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>
1.8.3 Apply the Patch
[lifo@null ruby-version]$ curl http://rubyforge.org/tracker/download.php/1814/7062/17676/3291/ruby186gc.patch | patch -p0
1.8.4 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.
[lifo@null ruby-version]$ ./configure --prefix=/<homedir>/rubygc [lifo@null ruby-version]$ make && make install
1.8.5 Prepare Aliases
For convenience, add the following lines in your ~/.profile:
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'
1.8.6 Install Rubygems and Dependency Gems
Download 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:
[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.
2 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:
2.1 benchmarker
benchmarker is a wrapper around Ruby’s Benchmark standard library.
Usage:
$ rails benchmarker [times] 'Person.expensive_way' 'Person.another_expensive_way' ...
Examples:
$ rails benchmarker 10 'Item.all' 'CouchItem.all'
If the [times] argument is omitted, supplied methods are run just once:
$ rails benchmarker 'Item.first' 'Item.last'
2.2 profiler
profiler is a wrapper around the ruby-prof gem.
Usage:
$ rails profiler 'Person.expensive_method(10)' [times] [flat|graph|graph_html]
Examples:
$ rails profiler 'Item.all'
This will profile Item.all in RubyProf::WALL_TIME measure mode. By default, it prints flat output to the shell.
$ rails 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:
$ rails profiler 'Item.all' 10 graph 2> graph.txt
3 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.
3.1 Model
Project.benchmark("Creating project") do project = Project.create("name" => "stuff") project.create_manager("name" => "David") project.milestones << Milestone.find(:all) end
This benchmarks the code enclosed in the Project.benchmark("Creating project") do...end block and prints the result to the log file:
Creating project (185.3ms)
Please refer to the API docs for additional options to benchmark()
3.2 Controller
Similarly, you could use this helper method inside controllers
def process_projects self.class.benchmark("Processing projects") do Project.process(params[:project_ids]) Project.update_cached_projects end end
benchmark is a class method inside controllers
3.3 View
And in views:
<% benchmark("Showing projects partial") do %> <%= render :partial => @projects %> <% end %>
4 Request Logging
Rails log files contain very useful information about the time taken to serve each request. Here’s a typical log file entry:
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:
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 measure 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 interesting blog post explaining the importance of using milliseconds as the metric.
5 Useful Links
5.1 Rails Plugins and Gems
5.2 Generic Tools
5.3 Tutorials and Documentation
- ruby-prof API Documentation
- Request Profiling Railscast – Outdated, but useful for understanding call graphs
6 Commercial Products
Rails has been lucky to have two startups dedicated to Rails specific performance tools:
7 Changelog
- January 9, 2009: Complete rewrite by Pratik
- September 6, 2008: Initial version by Matthew Bergman
Feedback
You're encouraged to help in keeping the quality of this guide.
If you see any typos or factual errors you are confident to patch please clone docrails and push the change yourself. That branch of Rails has public write access. Commits are still reviewed, but that happens after you've submitted your contribution. docrails is cross-merged with master periodically.
You may also find incomplete content, or stuff that is not up to date. Please do add any missing documentation for master. Check the Ruby on Rails Guides Guidelines guide for style and conventions.
Issues may also be reported in Github.
And last but not least, any kind of discussion regarding Ruby on Rails documentation is very welcome in the rubyonrails-docs mailing list.