Rails であるバッチがあって、そこで発行しているSQLのカウントとか分析をしたくなった。

Claude Code に便利な module を書いてもらった。

module SqlProfiler
  def self.profile(label: "Batch", &block)
    queries = []

    subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |name, start, finish, id, payload|
      next if payload[:name] == "SCHEMA"
      queries << {
        sql: payload[:sql].truncate(100),
        duration_ms: ((finish - start) * 1000).round(2),
        name: payload[:name]
      }
    end

    result = yield

    ActiveSupport::Notifications.unsubscribe(subscriber)

    total = queries.sum { |q| q[:duration_ms] }
    Rails.logger.info <<~LOG
      [#{label}] SQL Stats:
        Total queries: #{queries.size}
        Total time:    #{total.round(2)} ms
        Avg time:      #{(queries.size > 0) ? (total / queries.size).round(2) : 0} ms
        Top 5 slowest:
      #{queries.sort_by { |q| -q[:duration_ms] }.first(5).map { |q| "    #{q[:duration_ms]}ms - #{q[:sql]}" }.join("\n")}
    LOG

    result
  end
end

ActiveSupport::Notifications.subscribeを使っているのがミソっぽい。

Usage

# ブロックで囲んだ処理内のSQLを全部計測
SqlProfiler.profile(label: "ユーザー一括更新") do
  User.where(active: true).find_each do |user|
    user.update!(last_checked_at: Time.current)
  end
end

出力内容:

[ユーザー一括更新] SQL Stats:
  Total queries: 150
  Total time:    320.45 ms
  Avg time:      2.14 ms
  Top 5 slowest:
    12.34ms - UPDATE "users" SET "last_checked_at" = ...
    8.21ms  - SELECT "users".* FROM "users" WHERE ...
    ...