How To Track Rails Request Durations

Rails has always shown you some metrics about your requests in the Rails logfile, including the overall time a request took, how much of that was spent generating the view, and how much of that was consumed by the database. Recent versions of Rails allow you to tap into these metrics for your own use.

In our previous post, How To Track ActiveRecord Query Durations in Rails, we covered tracking individual database queries. In this post, I’ll show you how to track the overall request, view, and database durations. The code will track all three of these times for every request. It will also track the occurrence of any slow requests, as well as writing them to a log file.

Put this code in config/initializers/notifications.rb. If you already put the code from our ActiveRecord tracking post in there, you do not need the production environment check or the initialization of the slow log file twice.

{% highlight ruby %} if Rails.env.production? slow_logfile =“log”, “slow.log”), ‘a’) slow_log = slow_log.level = Logger::INFO

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, start, finish, id, payload|
    duration = (finish - start) * 1000
    StatHat::API.ez_post_value("rails request duration", "", duration)
    view_time = 0
    db_time = 0
    unless payload[:view_runtime].nil?
        view_time = payload[:view_runtime]
        StatHat::API.ez_post_value("rails request view duration", "", view_time)
    unless payload[:db_runtime].nil?
        db_time = payload[:db_runtime]
        StatHat::API.ez_post_value("rails request db duration", "", db_time)
    if view_time > 100"#{} slow request (slow view) (#{duration.to_i}ms total, view: #{view_time.to_i}ms): #{payload[:path]} controller: #{payload[:controller]}, action: #{payload[:action]}")
    if db_time > 100"#{} slow request (slow db) (#{duration.to_i}ms total, db: #{db_time.to_i}ms): #{payload[:path]} controller: #{payload[:controller]}, action: #{payload[:action]}")
    if duration > 500
        StatHat::API.ez_post_count("rails slow request", "", 1)"#{} slow request (#{duration.to_i}ms, view: #{view_time.to_i}ms, db: #{db_time.to_i}ms): #{payload[:path]} controller: #{payload[:controller]}, action: #{payload[:action]}")

end {% endhighlight %}

This is a powerful way to stay on top of the performance of your Rails application and detect any bottlenecks.

Comments? Send us a tweet.


How To Track ActiveRecord Query Durations in Rails
Save Money with Temporary EC2 Deploy Server