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:

 1# lib/query_tracer.rb
 2module QueryTracer
 3  # Borrowed some ANSI color sequences from elsewere
 4  CLEAR = ActiveSupport::LogSubscriber::CLEAR
 5  BOLD = ActiveSupport::LogSubscriber::BOLD
 7  def self.start!
 8    # Tap into notifications framework. Subscribe to sql.active_record messages
 9    ActiveSupport::Notifications.subscribe('sql.active_record') do |*args|
10      QueryTracer.publish(*args)
11    end
12  end
14  # Notice the 5 arguments that we can expect
15  def self.publish(name, started, ended, id, payload)
16    name = payload[:name]
17    sql = payload[:sql]
19    # Print out to logs
20    ActiveRecord::Base.logger.debug "#{BOLD} TRACE: #{sql}#{CLEAR}"
21    clean_trace.each do |line|
22      ActiveRecord::Base.logger.debug "  #{line}"
23    end
24  end
26  def self.clean_trace
27    Rails.backtrace_cleaner.clean(caller[2..-1])
28  end

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

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

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

1 **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)**
2  app/models/user.rb:18:in `block in add_word'
3  app/models/user.rb:12:in `tap'
4  app/models/user.rb:12:in `add_word'
5  app/controllers/words_controller.rb:6:in `create'

And that's it!