public

Measuring Performance

  • Download Gist
performance.markdown
Markdown

Measuring Performance

Performance is often ignored in Rails development until it becomes a problem. If ignored too long, though, it can get very tricky to improve. It's valuable to regularly audit performance and look for hotspots or design choices that are slowing things down.

Inspecting the Logs

Inspecting the log will help identify the source of several performance issues the application may have.

The Rails application log outputs the time spent processing each request. It breakdowns the time spent at the database level as well processing the view code. In development mode, the logs are displayed on STDOUT where the server is being run. In a production setting the logs will be in log/production.log within the application's root directory.

An Example

Take note of lines 4-9 in the following request:

1 Started GET "/articles/1" for 127.0.0.1 at 2011-09-12 13:07:21 -0400
2   Processing by ArticlesController#show as HTML
3   Parameters: {"id"=>"1"}
4   Article Load (0.3ms)  SELECT "articles".* FROM "articles" WHERE "articles"."id" = 1 LIMIT 1
5   Tag Load (0.3ms)  SELECT "tags".* FROM "tags" INNER JOIN "taggings" ON "tags".id = "taggings".tag_id WHERE (("taggings".article_id = 1))
6   SQL (0.2ms)  SELECT COUNT(*) FROM "comments" WHERE ("comments".article_id = 1)
7   Comment Load (0.2ms)  SELECT "comments".* FROM "comments" WHERE ("comments".article_id = 1)
8 Rendered articles/show.html.erb within layouts/application (102.8ms)
9 Completed 200 OK in 124ms (Views: 106.7ms | ActiveRecord: 1.0ms)
  • Lines 4-7 include a breakdown of the time spent executing the database queries to fulfill the request.
  • Line 8 indicates how long was spent building the view
  • Line 9 reports the total time spent along with a breakdown of time in the view vs in the database

The total time will likely be greater than the sum of the view and database processing time. The remaining time is spent in other parts of the system, such as the router, controller, and logger I/O.

NOTE: Be aware of the environment of the log being inspected. By default, in production the log output will not include the details of time spent processing each database query, although it will still provide the total time as indicated on line 9 of the above request. Lines 4-7 of the above request would not be present in production.

Response Time

Response time for an effective application should never go above half a second. If you cross that line, it's time to investigate ways to move some of the processing to asynchronous workers, cut down the number of queries, or cache data.

Query Count

If the log for a single request is filled with a lot of database queries that can often be a red flag in identifying a performance bug. A normal request should have somewhere between 1-4 queries. If more than that are being spawned, they should be condensed using techniques in the next section.

Scenarios that trigger many queries include:

Accessing Child Objects

When you have nested child object it is easy to trigger a large number of queries. Consider a blogging application where an Article has many comments, and each of those comments belongs to a User.

 # articles_controller.rb
 ...
 def show
   @article = Article.find(params[:id])
 end
 ...

 # app/views/articles/show.html.erb
 ...
 <% @article.comments.each do |comment| %>
   <div class='comment'>
     <p>
       <em><%= comment.user.name %></em> said at <%= distance_of_time_in_words(@article.created_at, comment.created_at) %> later:</p>
       <p><%= comment.body %></p>
     </p>
   </div>
 <% end %>
 ...

We fetch the @article in the controller which executes a single query. When we call @article.comments in the controller it runs a second query to fetch all the comments matching the foreign key of this article.

That's not a problem, yet. Then when we access comment.user.name we'll kick off another query to fetch the User with the matching user_id. This will cause an additional query for each comment on the page. So a popular article, with 30 comments, would run 32 total queries.

Side-Effect Queries

Side-Effect Queries are queries that may be executed for every or many requests in the application. These types of queries often come from before_filter calls doing things like looking up the current user or the contents of a shopping cart.

If these queries are crucial to every request in the application then they may be a good candidate for a high-performance cache like Redis.

New Relic

New Relic (http://newrelic.com/sliderocket) is an essential tool for any Rails application. It tracks the performance of every request and can be used in both development and production.

Setup

Add the newrelic_rpm gem to your Gemfile and bundle.

Register for an account at http://newrelic.com/ and get the newrelic.yml from the welcome email. Drop this file into the /config directory of your project.

Usage in Development

New Relic will track the most recent 100 requests in development. To view the data visit /newrelic in your browser.

So, assuming your app is running on localhost:3000, find New Relic at http://localhost:3000/newrelic

Usage in Production

There's no additional configuration for production, just run your app as normal then view the results here: http://rpm.newrelic.com/

Perftools.rb

PerfTools.rb is a port of Google's Perftools: https://github.com/tmm1/perftools.rb

It's an amazing library to profile which methods are making up the bulk of your processing time.

Basic Ruby Usage

  • gem install perftools.rb
  • Collect data by:

    • Using a block:

      require 'perftools'
      PerfTools::CpuProfiler.start("/tmp/add_numbers_profile") do
        5_000_000.times{ 1+2+3+4+5 }
      end
      
    • Using Start/Stop

      require 'perftools'
      PerfTools::CpuProfiler.start("/tmp/add_numbers_profile")
      5_000_000.times{ 1+2+3+4+5 }
      PerfTools::CpuProfiler.stop
      
    • Running Externally

      CPUPROFILE=/tmp/my_app_profile RUBYOPT="-r`gem which perftools | tail -1`" ruby my_app.rb
      

Where my_app.rb is the external file

Reports

With the data file generated you can create a variety of reports.

Plain Text Table

The simplest is the plain text table. Run this from the command line:

pprof.rb --text /tmp/add_numbers_profile

To generate output like this:

Total: 1735 samples
    1487  85.7%  85.7%     1735 100.0% Integer#times
     248  14.3% 100.0%      248  14.3% Fixnum#+

Where the columns indicate:

  1. Number of profiling samples in this function
  2. Percentage of profiling samples in this function
  3. Percentage of profiling samples in the functions printed so far
  4. Number of profiling samples in this function and its callees
  5. Percentage of profiling samples in this function and its callees
  6. Function name

GIF Graph

To generate a GIT graph, which is highly recommended, you'll need the graphviz library installed on your OS.

On OS X this can be done with brew install graphviz

On Ubuntu Linux, install it with apt-get install graphviz

With the library installed, generate and open the GIF report with these instructions:

pprof.rb --gif /tmp/add_numbers_profile > /tmp/add_numbers_profile.gif
open /tmp/add_numbers_profile.gif

PDF Ouput

Lastly, to generate PDFs which are better for zooming in to read details of the text, you'll need the ps2pdf utility.

On OS X, install it with brew install ghostscript.

On Linux, install it with apt-get install ps2pdf

Then generate and open the pdf with:

pprof.rb --pdf /tmp/add_numbers_profile > /tmp/add_numbers_profile.pdf
open /tmp/add_numbers_profile.pdf

Usage with Rails

There's a Rack middleware which can easily inject PerfTools into your application.

First, add the following to your Gemfile then run bundle:

gem 'rack-perftools_profiler', :require => 'rack/perftools_profiler'

Next, open /config/application.rb and initialize the middleware:

config.middleware.use ::Rack::PerftoolsProfiler, :default_printer => 'gif', :bundler => true

Finally, it's time to make your request. Using curl or a browser, enter the URL you want to examine and add the parameter ?profile=true. For instance, to see the graph for the articles#index you could visit: http://localhost:3000/articles?profile=true

For better statistical accuracy, you might want to run the same request several times by adding the times parameter: http://localhost:3000/articles?profile=true&times=5

References

Please sign in to comment on this gist.

Something went wrong with that request. Please try again.