Ruby on Rails

Ruby on Rails – your own slow query log, no sql configuration required

Ruby on Rails – your own slow query log, no sql configuration required March 8, 2018Leave a comment

Reading slow query log is a great way to detect weak places in any app where you have to refactor code in order to improve performance.

I used to think about logs generated by the database engine when thinking about slow query log. However, did you know that you can create your own mechanism for logging slow queries in your database? ActiveSupport::Notifications module from Rails allows us to subscribe to given event. sql.active_record is one of the available events and it’s triggered each time we do the database operation.

We can use it like this:

ActiveSupport::Notifications.subscribe('sql.active_record') do |name, start, finish, id, payload|
  # interesting stuff
end

the most interesting variables are:

  • payload – it’s a hash with the query details and you can access payload[:sql] to get the query
  • start – a Time object representing the moment when query started
  • finish – a Time object representing the moment when query finished

We can easily get the duration of the query:

ActiveSupport::Notifications.subscribe('sql.active_record') do |name, start, finish, id, payload|
  duration = finish.to_f - start.to_f
end

If we decide that slow query starts after 3 seconds we can log such query:

ActiveSupport::Notifications.subscribe('sql.active_record') do |name, start, finish, id, payload|
  duration = finish.to_f - start.to_f
  
  if duration >= 3.0
    SomeLogger.log("slow query detected: #{payload[:sql]}, duration: #{duration}")
  end
end

Creating initializer for our Rails app

We created the base functionality of our slow queries logger and now it’s time to put it on our Rails project and run with the server. In order to do this we will create SlowQueryLogger class and put it in config/initializer/slow_query_logger.rb:

class SlowQueryLogger
  MAX_DURATION = 3.0

  def self.initialize!
    ActiveSupport::Notifications.subscribe('sql.active_record') do |name, start, finish, id, payload|
      duration = finish.to_f - start.to_f

      if duration >= MAX_DURATION
        SomeLogger.log("slow query detected: #{payload[:sql]}, duration: #{duration}")
      end
    end
  end
end

SlowQueryLogger.initialize!

and that’s it. You can start logging your slow queries. This class is a nice piece of code which you can use in any project or even create a gem that can help to detect places where we should improve the performance of our queries. You can also send warnings to the monitoring systems like Rollbar instead logging it into the log file.

Download free RSpec & TDD ebook

Do you want to earn more or jump to the next level in your company? Do you know that testing skills are one of the most desired skills? There is only first step: start testing and do it right. My ebook can help you. Subscribe to the newsletter to get a free copy of the book.

Leave a Reply

Your email address will not be published. Required fields are marked *