Monitoring Rails: Get the Hidden Metrics Out of Your Rails App

Many of our user-facing web applications are built on top of the Ruby on Rails framework. As you can probably imagine, we've put a lot of effort into instrumenting these applications so that we can keep a close watch on all aspects of their performance. In the process, we've learned a lot about getting metrics out of a Rails application.

Let's walk through some of the things to consider when trying to instrument your own application.

What to Measure

Some of the things we might want to measure:

• Request Count - Total number of requests handled by the Rails app. Useful as a general measure of site traffic.
• Total Request Time - The elapsed time between the request reaching the Rails app and a response being returned. This will be a good indication of how the performance of your application may be affecting user experience.
• Database Time - Amount of the total request time spent interacting with the database. It can help you identify problematic queries.
• Service Time - Amount of the total request time spent interacting with external services. Along with the database time, this likely accounts for a large chunk of your total request time.
• Template Rendering Time - Amount of the total request time spent rendering the view. Hopefully, this is a small portion of the request time (you don't have any business logic in your views, right?)
• Queueing Time - Time a request spends between the app server and the Rails process. This is a common cause of hidden latency in your application's overall response time.
• Error Count - Total number of errors raised that aren't being handled by your application. Indicates that there may be problems with your infrastructure or the application itself.
• Status Code Counts - Count of requests that resulted in the different HTTP status codes. Much like the error count, a spike in 4xx or 5xx status codes may signal a problem in your application environment.

Obviously, this doesn't even begin to cover all the things that you could measure, but it's a good start and should give you a sense of the general health of your application. With a list of the things we want to measure in hand, the next question is: how do we measure them?

How to Measure

Rails has great support for filters which allow you to run custom code before, after or "around" any controller action. In fact, if you configure a filter in the ApplicationController it will be run on every action in your application. As a trivial example you might do something like this:

class ApplicationController < ActionController::Base
  around_action :collect_metrics

  def collect_metrics
    start = Time.now
    yield
    duration = Time.now - start
    Rails.logger.info "#{controller_name}##{action_name}: #{duration}s"
  end
end

The example above implements a basic "around" filter that will measure the execution time of all of the actions in your application. You could use a similar approach to collect most of the data that we identified previously. The good news is that there's an easier way.

If you've ever watched the log output from Rails you've probably seen entries like this:

Started GET "/posts" for 192.168.0.102 at 2016-03-29 20:53:32 -0700
Processing by PostsController#index as HTML
  Post Load (0.3ms)  SELECT "posts".* FROM "posts"
  Rendered posts/index.html.erb within layouts/application (3.0ms)
Completed 200 OK in 16ms (Views: 14.0ms | ActiveRecord: 0.3ms)

From this, it's pretty clear that Rails is already tracking and measuring all of the things that we're interested in. What if there were an easy way to tap into that data so that we didn't have to instrument it ourselves?

It turns out that all of the stats you see in the log output above (and lots more) are available by hooking into the ActiveSupport instrumentation API. Rails has defined a number of different events you can subscribe to with a custom listener. These events include things like the execution of controller actions (process_action.action_controller), the rendering of templates (render_template.action_view), and ActiveRecord queries (sql.active_record).

Subscribing to one of these events is as simple as registering a callback block:

ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |*args|
  event = ActiveSupport::Notifications::Event.new(*args)
  Rails.logger.info "Event received: #{event}"
end

With each of these events Rails delivers all sorts of useful data (as part of the args passed to your callback):

• Name of the event
• Start and end time for the event
• Unique event ID
• Name of the exception class and the exception message (if an error occurs during the event)

In addition to the standard event data above, different events can provide a custom, event-specific payload. For example, the process_action.action_controller event provides all of the following data:

• Name of the controller
• Name of the action
• HTTP request parameters
• Request method (get, post, put, etc...)
• Request path
• Response format (HTML, JSON, XML, etc...)
• HTTP status code
• Elapsed time for rendering view
• Elapsed time for executing database queries

As you can see, almost all of the must-collect metrics we identified above are delivered to us as part of this one event.