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:

  • 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

  • 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.

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

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 from that log entry:

Completed in 5ms (View: 2, DB: 0) | 200 OK [http://0.0.0.0/items]

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.

2. Helper methods

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.

Project.benchmark("Creating project") do
  project = Project.create("name" => "stuff")
  project.create_manager("name" => "David")
  project.milestones << Milestone.find(:all)
end

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:

Creating projectem (185.3ms)

Please refer to API docs for optional options to benchmark()

Similarly, you could use this helper method inside controllers ( Note that it’s a class method here ):

def process_projects
  self.class.benchmark("Processing projects") do
    Project.process(params[:project_ids])
    Project.update_cached_projects
  end
end

and views:

<% benchmark("Showing projects partial") do %>
  <%= render :partial => @projects %>
<% end %>

3. Performance Test Cases

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.

If you have a look at test/performance/browsing_test.rb in a newly created Rails application:

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 is an automatically generated example performance test file, for testing performance of homepage(/) of the application.

3.1. Modes

Performance test cases can be run in two modes : Benchmarking and Profling.

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

$ rake test:benchmark

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

$ rake test:profile

3.2. Metrics

Benchmarking and profiling run performance test cases in various modes to help precisely figure out the where the problem lies.

3.2.1. 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

3.2.2. 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

3.2.3. Memory

Measures the amount of memory used for the performance test case.

Mode : Benchmarking, Profiling [Requires specially compiled Ruby]

3.2.4. Objects

Measures the number of objects allocated for the performance test case.

Mode : Benchmarking, Profiling [Requires specially compiled Ruby]

3.2.5. GC Runs

Measures the number of times GC was invoked for the performance test case.

Mode : Benchmarking [Requires specially compiled Ruby]

3.2.6. GC Time

Measures the amount of time spent in GC for the performance test case.

Mode : Benchmarking [Requires specially compiled Ruby]

3.3. Understanding the output

Performance tests generate different outputs inside tmp/performance directory based on the mode it is run in and the metric.

3.3.1. Benchmarking

In benchmarking mode, performance tests generate two types of outputs :

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

  • 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, it enables you gather data over a sustainable period of time which can be very helpful with various performance analysis.

Sample output of +BrowsingTest#test_homepage_wall_time.csv + :

measurement,created_at,app,rails,ruby,platform
0.00738224999999992,2009-01-08T03:40:29Z,,2.3.0.master.0744148,ruby-1.8.6.110,i686-darwin9.0.0
0.00755874999999984,2009-01-08T03:46:18Z,,2.3.0.master.0744148,ruby-1.8.6.110,i686-darwin9.0.0
0.00762099999999993,2009-01-08T03:49:25Z,,2.3.0.master.0744148,ruby-1.8.6.110,i686-darwin9.0.0
0.00603075000000008,2009-01-08T04:03:29Z,,2.3.0.master.0744148,ruby-1.8.6.111,i686-darwin9.1.0
0.00619899999999995,2009-01-08T04:03:53Z,,2.3.0.master.0744148,ruby-1.8.6.111,i686-darwin9.1.0
0.00755449999999991,2009-01-08T04:04:55Z,,2.3.0.master.0744148,ruby-1.8.6.110,i686-darwin9.0.0
0.00595999999999997,2009-01-08T04:05:06Z,,2.3.0.master.0744148,ruby-1.8.6.111,i686-darwin9.1.0
0.00740450000000004,2009-01-09T03:54:47Z,,2.3.0.master.859e150,ruby-1.8.6.110,i686-darwin9.0.0
0.00603150000000008,2009-01-09T03:54:57Z,,2.3.0.master.859e150,ruby-1.8.6.111,i686-darwin9.1.0
0.00771250000000012,2009-01-09T15:46:03Z,,2.3.0.master.859e150,ruby-1.8.6.110,i686-darwin9.0.0

3.3.2. Profiling

Command line

This is the very basic form of output in profiling mode. Example :

BrowsingTest#test_homepage (58 ms warmup)
        process_time: 63 ms
              memory: 832.13 KB
             objects: 7882
Flat

Flat output shows the total amount of time spent in each method. Check ruby prof documentation for a better explaination.

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 explaination.

Tree

Tree output is profiling information in calltree format for use by kcachegrind and similar tools.

3.4. Preparing Ruby and Ruby-prof

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:

3.4.1. Compile

[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

3.4.2. Prepare aliases

Add the following lines in your ~/.profile for convenience:

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'

3.4.3. Install rubygems and some basic gems

Download Rubygems and install it from source. Afterwards, install rake. rails, ruby-prof and rack gems:

[lifo@null ~]$ gcgem install rake
[lifo@null ~]$ gcgem install rails
[lifo@null ~]$ gcgem install ruby-prof
[lifo@null ~]$ gcgem install rack

3.4.4. Install MySQL gem

[lifo@null ~]$ gcgem install mysql

If this fails, you can try to install it manually:

[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

3.5. Generating performance test

Rails provides a generator for creating new performance tests:

[lifo@null application (master)]$ script/generate performance_test homepage

This will generate test/performance/homepage_test.rb:

require 'test_helper'
require 'performance_test_help'

class HomepageTest < ActionController::PerformanceTest
  # Replace this with your real tests.
  def test_homepage
    get '/'
  end
end

Which you can modify to suit your needs.

4. Other Profiling Tools

5. Commercial products dedicated to Rails Perfomance

6. Changelog

Lighthouse ticket

  • January 9, 2009: Rewrite by Pratik

  • October 17, 2008: First revision by Pratik

  • September 6, 2008: Initial version by Matthew Bergman