Logging metrics for Rails web requests using Active Support Instrumentation

Nick Burwell
Mar 7, 2019 · 4 min read
A Kibana dashboard showing requests over time by controller as well as top average latency

We have a lot of metrics that power dashboards and alerts around our production infrastructure. This includes our Rails frontend servers. We believe visibility is critical to being able to anticipate and act on any reliability or performance issue. Something we were lacking though was a complete picture of requests by Rails controllers and actions (in aggregate), that also included the average and upper percentile response latency.

For those familiar with Rails, you know about the stats that show up at the end of each request in the standard Rails logger:

We wanted to hook into that data and send it to our existing metrics & alerting stack without a lot of custom code or around_filters. Turns out Rails makes that simple with their Active Support Instrumentation. The event we subscribed to wasprocess_action.action_controller, which gave us access to the following data points per request:

* controller
* action
* params
* headers
* format
* method
* path
* status
* view_runtime
* db_runtime
* total_runtime

To subscribe to that event, you will want the bold code below to be placed somewhere that is only executed on application startup (versus on every page load). We put ours in an initializer block within application.rb but it could also go in its own config/initializers file.

# config/application.rbrequire File.expand_path('../boot', __FILE__)
require 'rails/all'
module WebService
class Application < Rails::Application
initializer :configure_metrics, after: :initialize_logger do
require_relative './frontend_request_metrics.rb'


And we created a class that took that data in, and sent it off to our metrics stack. Here is a simplified form:

class FrontendRequestMetrics
def call(event_name, started, finished, event_id, payload)
event = ActiveSupport::Notifications::Event.new(event_name, started, finished, event_id, payload)
timing = {
database: event.payload[:db_runtime],
view: event.payload[:view_runtime],
total: event.duration
# send relevant info to metrics server, e.g.
namespace = "frontend.#{event.payload[:controller]}.#{event.payload[:action]}"
metrics.timer("#{namespace}.view_duration", timing[:view])
metrics.timer("#{namespace}.total_duration", timing[:total])

The great thing is we now not only have the overall response latency, but can track DB time and view rendering time per request, as well as in aggregate by controller, action, method and more.

We ended up also sending this info to our ELK stack, so that we could get some succinct log statements for every single web request. In order for these new log entries to be a useful debugging tool in the event of investigations, there were a few things missing from the ActionSupport::Notifications event. We wanted access to the request uuid, as well as the logged in user and organization, if those were known in the session but not present in the url. That way we could tie the response timing data in with the full log output of the Rails log (by filtering on uuid).

Fortunately, Rails has an answer for appending additional data, though this was harder to find and not documented very well. They support adding the following method to your base Application Controller, or any specific controller as well, which passes in the existing payload and gives you an opportunity to augment it before it is sent to the notification hook:

class ApplicationController < ActionController::Base
def append_info_to_payload(payload)
payload[:uuid] = request.uuid
payload[:user_id] = current_user&.id

The nice thing with this append_info_to_payload method is that you have access to the request and response objects as well as the session object, giving you many options for what to include in the event payload.

With the above changes deployed, we were then able to create some alerting thresholds around response latency (and at a finer granularity like Rails controller and action, or customer type, or even specific customer). And with all of this normalized data also flowing to our ELK stack, it was then trivial to create useful dashboards for web requests. We can filter the dashboards down to a specific customer, controller and action, request method, request format and more when troubleshooting a possible issue.

Rails provides many other instrumentation hooks that we are excited to explore and integrate into our monitoring and alerting stack now that we have this pattern established. See this Digging Deep with Notifications talk for some great information and ideas on what is possible. Let us know if you are using any of the available instrumentation hooks in creative ways too!

Invoca Engineering Blog

Welcome to a place where words matter. On Medium, smart voices and original ideas take center stage - with no ads in sight. Watch
Follow all the topics you care about, and we’ll deliver the best stories for you to your homepage and inbox. Explore
Get unlimited access to the best stories on Medium — and support writers while you’re at it. Just $5/month. Upgrade

Get the Medium app

A button that says 'Download on the App Store', and if clicked it will lead you to the iOS App store
A button that says 'Get it on, Google Play', and if clicked it will lead you to the Google Play store