Rails helpfully logs queries to ActiveRecord::Base.logger in development mode. This logging is an easy way to keep an eye on unexpected costs hidden by Rails’ abstractions - like N + 1 queries - which might otherwise slip by unnoticed. One thing I’ve found that makes this query logging even more useful is to log the line of code that caused the query.

I’ll walk through the genesis of this mixin in detail, so if you’re just interested in the mixin itself, jump to the end of this post to see the final code.

Finding something to modify

First, we’ll need to determine what to modify. We know what the logged lines look like, which gives us a reasonable starting point: User Load (0.3ms) SELECT `users`.* FROM `users` WHERE `users`.`id` = 18 LIMIT 1` . Most of the line is based on the query - but the “Load” text is likely to show up in a string literal. Sure enough, “Load” only appears three times in string literals in ActiveRecord code, and only one of those looks relevant. In querying.rb:

connection.select_all(sanitize_sql(sql), "#{name} Load", binds).collect! { |record| instantiate(record) }

Following #select_all to #select in database_statements.rb, we find that it is just an empty placeholder method for database adapters to implement:

def select(sql, name = nil, binds = [])
end
undef_method :select

Looking at a database adapter - mysql_adapter.rb in this case - we find an implementation of #select that passes the name argument to #exec_query, which in turn passes it to #exec_without_stmt. Now we’re getting somewhere:

def exec_without_stmt(sql, name = 'SQL')
  # ...
  log(sql, name) do
  # ...

The #log method is defined in abstract_adapter.rb, and uses ActiveSupport::Notifications::Instrumenter to broadcast an event named “sql.active_record”. Instrumentation allows for decoupling of the subscriber and broadcaster, so while we could look for a string literal in a call like ActiveSupport::Notifications.subscribe('sql.active_record', ...) - that doesn’t lead us anywhere promising in this case. Fortunately, “sql.active_record” shows up in a comment block in ActiveSupport::LogSubscriber:

# After configured, whenever a "sql.active_record" notification is published,
# it will properly dispatch the event (ActiveSupport::Notifications::Event) to
# the sql method.

Additional comments in ActiveSupport::LogSubscriber direct us to ActiveRecord::LogSubscriber, where we find the code responsible for logging those queries.

Determining how to modify

Looking at ActiveRecord::LogSubscriber, we see that the #sql method calls #debug to print the query. The #identity method - used to log identity map access - also calls #debug. We’ll add our behavior to debug so it will affect both methods.

The #debug method isn’t actually defined in ActiveRecord::LogsSubscriber. It’s defined in the base class - ActiveSupport::LogSubscriber - along with a handful of similar helper methods:

%w(info debug warn error fatal unknown).each do |level|
  class_eval <<-METHOD, __FILE__, __LINE__ + 1
    def #{level}(*args, &block)
      return unless logger
      logger.#{level}(*args, &block)
    end
  METHOD
end

Since #debug isn’t defined in ActiveRecord::LogSubscriber itself, we have some options for modifying the behavior. We could re-open the class to add our own #debug with extra behavior - and would still be able to call super without worrying about hiding an existing method. Instead, we can take a more future-safe route and prepend a module that defines a #debug method. By doing this, we allow for future updates to ActiveRecord::LogSubscriber that add an implementation of #debug, without requiring changes to our mixed-in method:

module LogQuerySource
  def debug(*args, &block)
    super
    # Add some new behavior here...
  end
end
ActiveRecord::LogSubscriber.send :prepend, LogQuerySource

Adding the new behavior

Now we’ll figure out what to do in our modified #debug method. Jumping into the #sql method in a debugger (byebug) just before the call to #debug, we can inspect the result of caller. Sure enough, our code that caused the query shows up in the backtrace, but it’s buried under dozens of calls to ActiveRecord and ActiveSupport helper methods.

We can clean up our caller pretty easily, the same way Rails clean up backtraces for error output:

backtrace = Rails.backtrace_cleaner.clean caller

Now we have a much cleaner backtrace, only containing lines with code in our project. In this particular case, we might have a mixin that shows up in the cleaned backtrace, but we don’t want to include that here, so we’ll clean a bit more:

backtrace = Rails.backtrace_cleaner.clean caller

relevant_caller_line = backtrace.detect do |caller_line|
  !caller_line.include?('/initializers/')
end

relevant_caller_line will contain the last line of our code that caused the query - or nil if there is no relevant line of code in the backtrace.

We want to call super, so the original method can log the query. Since the #debug method defined in ActiveSupport::LogSubscriber has the line return unless logger - and the subsequent call to the logger returns a truthy value - we can use that as a proxy for the logger being enabled in our method:

def debug(*args, &block)
   return unless super
   # ...
 end

Finally, if we’ve found a relevant caller line, and logging is enabled, we’ll go ahead and log something:

if relevant_caller_line
  logger.debug("  ↳ #{ relevant_caller_line.sub("#{ Rails.root }/", '') }")
end

The mixin

In a config/initializers/active_record_log_subscriber.rb file, add:

module LogQuerySource
  def debug(*args, &block)
    return unless super

    backtrace = Rails.backtrace_cleaner.clean caller

    relevant_caller_line = backtrace.detect do |caller_line|
      !caller_line.include?('/initializers/')
    end

    if relevant_caller_line
      logger.debug("  ↳ #{ relevant_caller_line.sub("#{ Rails.root }/", '') }")
    end
  end
end
ActiveRecord::LogSubscriber.send :prepend, LogQuerySource

Now we’ll see which lines caused ActiveRecord queries, making inefficiencies much easier to track down.