With recent versions of Rails, you can subscribe to certain notifications that allow you to track various internal stats about your Rails app. In this post, I’ll show you how to track ActiveRecord query times.

This code is going to do two things. It is going to track the value of every query’s duration so that you know in general how your system is performing. It will also log the sql of any really slow queries to a log file so you can check to make sure you have the necessary indices. Mysql has had a slow log feature for years, but this is a database-agnostic way to do it in case you’re not using mysql. The code is also going to track the slow query occurrence so that you can get alerted when a lot of them suddenly appear. It will also only subscribe to the notification in production mode. Feel free to change the first line to test it in development mode.

The best time to subscribe to notifications is when your Rails app is initializing. Create a file in config/initializers named notifications.rb and put this code in it:

{% 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 "sql.active_record" do |name, start, finish, id, payload|
    if payload[:name] == "SQL"
        duration = (finish - start) * 1000
        StatHat::API.ez_post_value("rails sql query duration", "info@stathat.com", duration)

        if duration > 500
            slow_log.info("#{Time.now.to_formatted_s(:db)} slow query (#{duration.to_i}ms): #{payload[:sql]}")
            slow_logfile.flush
            StatHat::API.ez_post_count("rails slow sql query", "info@stathat.com", 1)
        end
    end
end

end {% endhighlight %}

Stay tuned for an upcoming post on other information you can track with the Rails notification subscriptions.