TaggedLogging で ActiveRecord のログを調査しやすくする方法

Rails4のデフォルトloggerであるTaggedLoggingは、次のようにすると入れ子でタグを出力してくれます。

require "active_support/tagged_logging"
logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT))

logger.tagged("tag1") do
  logger.tagged("tag2") do
    logger.debug "message"
  end
end

# >> [tag1] [tag2] message

これを活用して次のようにモデルの主要メソッドをラップしまくると、何のメソッドがトリガーになってそのSQLが呼ばれたのかがわかりやすくなります。

require "active_record"
ActiveRecord::Base.logger = logger
ActiveSupport::LogSubscriber.colorize_logging = false
ActiveRecord::Migration.verbose = false
ActiveRecord::Base.establish_connection(:adapter => "sqlite3", :database => ":memory:")
ActiveRecord::Schema.define do
  create_table :users do |t|
    t.string :name
  end
end

class User < ActiveRecord::Base
  validates :name, :uniqueness => true

  [:save!, :save, :valid?, :destroy].each do |e|
    define_method(e) do |*args, &block|
      logger.tagged("#{self.class.name}##{e}") { super(*args, &block) }
    end
  end

  [:save, :destroy].each do |e|
    send("around_#{e}", prepend: true) {|_, block| logger.tagged(e, &block) }
  end
end

User.create!(:name => "alice").destroy!

# >>    (1.7ms)  CREATE TABLE "users" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar) 
# >> [User#save!]    (0.1ms)  begin transaction
# >> [User#save!] [User#valid?]   User Exists (0.1ms)  SELECT  1 AS one FROM "users" WHERE "users"."name" = 'alice' LIMIT 1
# >> [User#save!] [save]   SQL (0.1ms)  INSERT INTO "users" ("name") VALUES (?)  [["name", "alice"]]
# >> [User#save!]    (0.0ms)  commit transaction
# >> [User#destroy]    (0.0ms)  begin transaction
# >> [User#destroy] [destroy]   SQL (0.1ms)  DELETE FROM "users" WHERE "users"."id" = ?  [["id", 1]]
# >> [User#destroy]    (0.1ms)  commit transaction

DBの水平分割などをしている場合は、DBの接続先をタグに入れるのも良いと思います。