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 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.
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 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.
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:
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 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 (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.
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.
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
There's no additional configuration for production, just run your app as normal then view the results here: http://rpm.newrelic.com/
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.
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
With the data file generated you can create a variety of reports.
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:
- Number of profiling samples in this function
- Percentage of profiling samples in this function
- Percentage of profiling samples in the functions printed so far
- Number of profiling samples in this function and its callees
- Percentage of profiling samples in this function and its callees
- Function name
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
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
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 => trueFinally, 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×=5
- PerfTools.rb: https://github.com/tmm1/perftools.rb
- Google's PProf: http://google-perftools.googlecode.com/svn/trunk/doc/cpuprofile.html#pprof
- Notes on Profiling Ruby: http://www.igvita.com/2009/06/13/profiling-ruby-with-googles-perftools/
- Rack PerfTools Middleware: https://github.com/bhb/rack-perftools_profiler