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 6 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 13 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] 18 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 25 26 def self.clean_trace 27 Rails.backtrace_cleaner.clean(caller[2..-1]) 28 end 29end 30 31QueryTracer.start!
To make this work, we only need to require the module from anywhere appropriate. An initializer would be a good place, for example:
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!