大型バイクを押しがけしている — トラブルが起きたとき、昔ながらの方法が役立つこともある

こんにちは。株式会社kickflowプロダクト開発本部の小本です。

Bulletは何の問題点も検出しないが実際に動かすと何故か遅い

Rails業界ではBulletなどのクエリの問題点を検出するツールが普及していますが、それらも万能ではありません。時には生のクエリログが解決の糸口になることがあります。

普通にRailsアプリケーションを作ると、development環境では以下のようなクエリログが出力されるようになっています。

例：

  CACHE User Load (0.0ms)  SELECT "users".* FROM "users" WHERE "users"."tenant_id" = '6fa44ea2-cbbd-4901-980b-abbe3e0f66cc' AND "users"."id" = '4344b765-595e-4ee7-bf91-a627cbfce622' LIMIT 1
  MonthlyActivityLog Load (6.5ms)  SELECT "monthly_activity_logs".* FROM "monthly_activity_logs" WHERE "monthly_activity_logs"."tenant_id" = '6fa44ea2-cbbd-4901-980b-abbe3e0f66cc' AND "monthly_activity_logs"."year" = 2025 AND "monthly_activity_logs"."month" = 3 AND "monthly_activity_logs"."user_id" = '4344b765-595e-4ee7-bf91-a627cbfce622' LIMIT 1 /*action='show',application='Kickflow',controller='tenant'*/
  ↳ app/controllers/api/v1/user_controller.rb:4:in 'Api::V1::UserController#show'
  ↳ app/models/monthly_activity_log.rb:47:in 'MonthlyActivityLog.create_log'

しかし、標準のクエリログは、

人間が読むためにフォーマットされているため機械的に処理しにくい（JSONでくれ！）
log/development.log に他ログと一緒に出力されるので、クエリログを発見しにくい。
全てのアクションのログが１ファイルに出力される（調べたいのは特定の重いアクションだけなのだ。）

という問題があります。そこで、この記事ではクエリログをJSON形式で出力する方法を説明します。

そもそも、どうやってクエリログを得るのか？ ActiveSupport::Notifications

Railsには「SQLを実行する」「テンプレートを描画する」などのイベントをフックできる仕組み - ActiveSupport::Notificationsがあります。

api.rubyonrails.org

詳しくはこちらのブログ記事で解説されています。

Railsの計測を支えるActiveSupport::Notificationsについて | GMOメディアエンジニアブログ

標準のクエリログもActiveSupport::Notificationsを使っており sql.active_record イベントを購読しています（実装はActiveRecord::LogSubscriber#sql）

なのでsql.active_recordを購読して、それをJSONフォーマットで出力すれば一丁上がりです。

全てのクエリをJSON形式でログに出力する例

sql.active_recordを購読すること自体は簡単で、単に.subscribeメソッドを呼ぶだけです。

ActiveSupport::Notifications.subscribe("sql.active_record") do |event|
  # ここでeventをJSONにフォーマットしたりログに出力したりする。
end

sql.active_record の場合 event は以下のような構造になっています。

event.name
event.time # 開始時刻
event.end  # 終了時刻
event.duration # かかった時間
event.cpu_time
event.idle_time
event.allocations

event.payload[:sql]
event.payload[:name]
event.payload[:binds]
event.payload[:type_casted_binds]
event.payload[:async]
event.payload[:connection]
event.payload[:transaction]
event.payload[:row_count]

なので、以下のようなコードを追加すればファイルにJSON形式でクエリログを出力できます。

# ActiveRecordのクエリログをJSON形式でログファイルに出力する例
# config/initializers/query_logging.rb

if Rails.env.development?
  logger = Logger.new(Rails.root.join("log/query.log"))

  ActiveSupport::Notifications.subscribe("sql.active_record") do |event|
    data = {
      name: event.payload[:name],
      cached: event.payload[:cached].present?,
      duration: event.duration,
      sql: event.payload[:sql],
    }
    logger << "#{data.to_json}\n" # JSON形式でログに出力
  end
end

ログをコントローラー/アクション/リクエスト毎に出力したい

ところで、ActiveSupport::Notifications.subscribe では一度をコールバックを登録するとプログラムが終了するまでイベントを購読し続けます。一方ActiveSupport::Notifications.subscribed （名前にdが付いている）というメソッドもあり、こちらは特定のブロックの間だけイベントを購読できます。

api.rubyonrails.org

callback = lambda {|event| ... } # イベント発生時に実行されるブロック
ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
  # このブロックの実行中のみイベントを購読する
end

これをControllerに仕込むと、アクションごとにログファイルを出し分けたり、特定のアクションだけログを出すようにしたり出来ます。

class UsersController < ApplicationController
  # 特定のアクションのみクエリログを出力する例
  around_action :log_activerecord, only: :create

  private def log_activerecord(&block)
    logger = Logger.new(Rails.root.join("log/query.#{controller_name}.#{action_name}.#{Time.current.to_i}log"))

    callback = lambda do |event|
      data = {
        name: event.payload[:name],
        cached: event.payload[:cached].present?,
        duration: event.duration,
        sql: event.payload[:sql],
      }
      logger << "#{data.to_json}\n"
    end

    ActiveSupport::Notifications.subscribed(callback, "sql.active_record", &block)
  end

  # 何かクエリが重いので調査したいアクション  
  def create
     ...
  end
end

クエリの呼び出し元もログに出力する

上記のコードを使って「同じクエリが何度も実行されていて、これが速度低下の原因らしい」と分かったとします。しかし、そのクエリがRubyコードのどこから呼び出されているのか分からなければ、コードを改善することは出来ません。

クエリの呼び出し元は Kernel.#callerで取得できます。

docs.ruby-lang.org

ただしcallerで取得できるバックトレースにはライブラリ内のメソッド呼び出しも含まれてしまっています。そこで、Rails.backtrace_cleanerを使って必要なものだけを残します。

  ActiveSupport::Notifications.subscribe("sql.active_record") do |event|
    # クエリの実行元を特定するために追加
    loc = Rails.backtrace_cleaner.clean(caller).first

    data = {
      name: event.payload[:name],
      cached: event.payload[:cached].present?,
      duration: event.duration,
      sql: event.payload[:sql],
      loc:,
    }
    logger << "#{data.to_json}\n"
  end