When running an app in production it’s of paramount importance to keep an eye on performance metrics. After all, you don’t want slow load times to drive you users away while you are blissfully unaware sipping on your b̶e̶e̶r̶ scotch. Everyone knows about the best available solutions for performance monitoring, and you should really use one of those if you have the money since they provide a lot of insight into not only the existence of performance issues, but also the possible culprits. However, these commercial solutions can get very expensive very fast.

Of course when you’re a small bootstrapped startup or just deploying a personal app to test out an idea, it can be hard to justify the cost of using some of the commercial solutions available. That doesn’t mean you can disregard the need for monitoring, so to that end we’ve devised a simple solution we use for small internal projects and experiments to allow us to keep track of performance stats.

Let’s get on with it then!

ActiveSupport instrumentation

A Rails feature that is sometimes overlooked by many is the existence of an instrumentation system that allows you to plug into certain events to get detailed runtime data from Rails. It’s called ActiveSupport::Notifications and essentially it allows you to get data on stuff like controller response times, SQL query runtimes, and views and partial rendering times among other interesting stuff.

If you want to know more, you can read about all the nifty things it can do here and here.

Putting things to work

For today we’re just interested in getting response times from our controller actions. This is a very simplistic metric, but it’s also the easiest to look at to detect performance issues in your app.

To get those response times we need to listen to the process_action.action_controller event, get the data, and log it to a separate log file. This can be done by creating an initializer that will hook us up to ActiveSupport::Notifications and run some custom code:

# config/initializers/log_response_time.rb # create a custom logger that logs to a separate file

event_logger = ::Logger.new("#{Rails.root}/log/response_times.log")

event_logger.formatter = proc { |_severity, _datetime, _progname, msg|

"#{msg}

"

} # Subscribe to the 'process_action.action_controller' event

ActiveSupport::Notifications.subscribe(

'process_action.action_controller'

) do |_, started, finished, _, stats|

request_time = (finished - started) * 1000

controller = stats[:controller][0..-11].underscore

action = "#{stats[:method]} #{controller}##{stats[:action]}.#{stats[:format]}" # log the event data

event_logger.info "#{action} | Status: #{stats[:status]} | "\

"Total: #{request_time} | "\

"ActiveRecord: #{stats[:db_runtime]} | "\

"Views: #{stats[:view_runtime]}"

end

This will log messages similar to the following (times are in milliseconds):

GET whiskies#index.html | Status: 200 | Total: 1896.098532 | ActiveRecord: 651.0056979999991 | Views: 1239.6528750001107

The log is actually pretty similar to what Rails already logs, but has the advantage of being a single line that’s easily splittable for us to analyze.

For example, we can open the log file and get the worst 3 response times for each controller action like this:

# read the file

File.readlines('log/response_times.log'). # split fields into an array

map { |l| l.split(' | ') }. # group lines by controller action

group_by { |l| l[0] }. # get the 3 worst times for each controller action, sorted from worst to best

map { |k, lines| [k, lines.sort_by { |l| 1 / l[2].split[1].to_f }[0..2]] }. # sort controller actions from worst response time to best

sort_by { |_, lines| 1 / lines[0][2].split[1].to_f }

While this isn’t the most glamorous way to look at the data, it gets the job done for a quick look at the worst case response times for your app. Instead of logging to a file we can of course export the data in a more interesting format for analyzing.

In the next installment of “El cheapo Rails performance metrics” we’ll look at better ways to store and view this data, as well as extracting more performance metrics besides reponse time.

Stay tuned!