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 = File.open(Rails.root.join(“log”, “slow.log”), ‘a’) slow_log = Logger.new(slow_logfile) 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", "info@stathat.com", 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", "info@stathat.com", view_time)
    end
    unless payload[:db_runtime].nil?
        db_time = payload[:db_runtime]
        StatHat::API.ez_post_value("rails request db duration", "info@stathat.com", db_time)
    end
    if view_time > 100
        slow_log.info("#{Time.now.to_formatted_s(:db)} slow request (slow view) (#{duration.to_i}ms total, view: #{view_time.to_i}ms): #{payload[:path]} controller: #{payload[:controller]}, action: #{payload[:action]}")
        slow_logfile.flush
    end
    if db_time > 100
        slow_log.info("#{Time.now.to_formatted_s(:db)} slow request (slow db) (#{duration.to_i}ms total, db: #{db_time.to_i}ms): #{payload[:path]} controller: #{payload[:controller]}, action: #{payload[:action]}")
        slow_logfile.flush
    end
    if duration > 500
        StatHat::API.ez_post_count("rails slow request", "info@stathat.com", 1)
        slow_log.info("#{Time.now.to_formatted_s(:db)} 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]}")
        slow_logfile.flush
    end
end

end {% endhighlight %}

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