PabloBM

ActiveRecord: getting a backtrace of your SQL queries

The other day I had some strange database queries in my Rails log. I didn’t know what was originating them, so I set out to track down their origin.

Thus I found out about ActiveSupport::Notifications. It is used by Rails to notify about events ocurring inside the framework, and is used to generate the standard logs that we see in our applications. We can turn them to our advantage to solve the problem at hand.

We can tap into these notifications to find out what is generating those DB queries. To do this, we print out the backtrace of the program when we get notified of an SQL query happening. Like this:

# lib/query_tracer.rb
module QueryTracer

  # Borrowed some ANSI color sequences from elsewere
  CLEAR = ActiveSupport::LogSubscriber::CLEAR
  BOLD = ActiveSupport::LogSubscriber::BOLD

  def self.start!
    # Tap into notifications framework. Subscribe to sql.active_record messages
    ActiveSupport::Notifications.subscribe('sql.active_record') do |*args|
      QueryTracer.publish(*args)
    end
  end

  # Notice the 5 arguments that we can expect
  def self.publish(name, started, ended, id, payload)
    name = payload[:name]
    sql = payload[:sql]

    # Print out to logs
    ActiveRecord::Base.logger.debug "#{BOLD} TRACE: #{sql}#{CLEAR}"
    clean_trace.each do |line|
      ActiveRecord::Base.logger.debug "  #{line}"
    end
  end

  def self.clean_trace
    Rails.backtrace_cleaner.clean(caller[2..-1])
  end

end

QueryTracer.start!

To make this work, we only need to require the module from anywhere appropriate. An initializer would be a good place, for example:

# config/initializers/query_tracer.rb
require 'query_tracer'

Now, for each SQL query generated within ActiveRecord, we will get the following output in the logs:

 TRACE: INSERT INTO `user_words` (`created_at`, `updated_at`, `user_id`, `word_id`) VALUES ('2011-11-27 18:33:53', '2011-11-27 18:33:53', 2, 2)
  app/models/user.rb:18:in `block in add_word'
  app/models/user.rb:12:in `tap'
  app/models/user.rb:12:in `add_word'
  app/controllers/words_controller.rb:6:in `create'

And that’s it!