How to log Rails queries before they happen?

Question

Rails logger by default will show the SQL after it's been executed. Sometimes - mainly when a query takes a long time - I want to configure the logger to output the SQL before it executes. Then it can add a follow-up log once the database has responded.

Basic idea is something like:

10:01:01 POST Load Executing "SELECT * from posts;'
10:01:03 POST Load 1712ms

How can Rails be configured to break the SQL logging into 2 steps like this?

Answer 1

There is no standard way you can configure logger to output SQL query before execution.

But you can still log queries this way by extending ActiveRecord::LogSubscriber class.

# initializers/extensions/active_record_logger.rb
module Extensions
  module ActiveRecordLogger
    IGNORE_PAYLOAD_NAMES = ActiveRecord::LogSubscriber::IGNORE_PAYLOAD_NAMES

    # ActiveRecord::LogSubscriber doesn't implement this method.
    # This method will be invoked before event starts processing.
    # It's exactly we are looking for!
    def start(name, id, payload)
      super

      return unless logger.debug?
      return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])

      name = payload[:name]
      sql = payload[:sql]

      name = color(name, nil, true)
      sql  = color(sql, nil, true)

      debug "STARTING #{name}  #{sql}"
    end
  end
end

ActiveRecord::LogSubscriber.include Extensions::ActiveRecordLogger

Now you will get query log before execution. For instance, querying

User.find 1

will produce

STARTING  User Load  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1
User Load (0.2ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1  [["id", 1]]
#<User id: 1, username: "dimakura", created_at: "2015-09-08 13:16:42", updated_at: "2015-09-08 13:16:42">