ActiveRecord::LogSubscriber を使って追加でログを出力する - ESM アジャイル事業部開発者ブログ

どうも muryoimpl です。

先日 ActiveRecord::LobSubscriber を使ってログ出力に手を加えたので、その意図と実装例をご紹介したいと思います。

ActiveRecord::LogSubscriber とは

ActiveRecord で発行されたクエリをログに出力する役割を担ったクラスです。ログレベルを debug とした場合に、ActiveRecord のクエリを発行した際に実行時間や SQL 文が出力されますが、それはこのクラスが活躍しているおかげです。

ActiveSupport::Notifications の仕組みを使ってログに記録する ActiveSupport::LogSubscriber を継承したクラスとなっていて、ActiveSupport::LogSubscriber の API ドキュメントをみると、ActiveRecord::LogSubscriber を使った例が記載されています。

ActiveRecord::LogSubscriber を継承した独自のクラスを作り、sql メソッドを上書き実装することで、既存のクエリのログ出力に加え、独自のログ出力を追加することができます。

なぜ ActiveRecord::LogSubscriber を使ったのか

今回私は、特定のテーブルのクエリが発行されているかどうか、発行されたときにどのくらいの時間がかかっているのかを確認したいがために、ActiveRecord::LogSubscriber を継承した独自クラスを作成しました。

Rails アプリケーションのログレベル全体を下げるとログの量が爆発的に増えてしまい、大量のSQLにより欲しい情報が埋もれてしまって探しにくくなってしまう問題があり、条件を指定してログ出力できないか？ということで、ActiveRecord::LogSubscriber の出番となったわけです。

この後記載する実装例でも出てきますが、SQL文やクエリに渡されたパラメータが payload として渡されてくるので、これらを条件にして出力する/しないの切り替えを柔軟に設定ができるのではないかと思います。

ActiveRecord::LogSubscriber 自体には、クエリが実装されているソースがどこかを出力するメソッドも実装されているので、あるテーブルへのクエリがどこから出力されるかを調べることもできるでしょう。

テーブルの特定の属性が更新された場合のみSQL文を出力する実装例

以下の環境で動作確認をしています。

Ruby on Rails: 6.1.3.1
Ruby: 2.7.3

ActiveRecord::LogSubscriber#sql の元の実装や、ActiveRecord::LogSubscriber の API ドキュメントを参考にして実装しています。

今回は Profile モデルの memo 属性が更新された場合に、ログレベル info で SQL を出力するようにしています。ファイルは config/initializers 以下に配置しています。

class ProfileLogSubscriber < ActiveRecord::LogSubscriber
  def sql(event)
    self.class.runtime += event.duration
    payload = event.payload

    # debug レベルでログが二重に出力されないようにしている。
    # また、自分で実装したクエリ以外のSQLが出力対象とならないようにしている。
    return if logger.debug? || IGNORE_PAYLOAD_NAMES.include?(payload[:name])

    sql_str = payload[:sql]
    # profiles と memo が両方含まれているクエリのみを対象とする
    return if !(/profiles/i.match?(sql_str)) || !(/memo/i.match?(sql_str))

    name  = "#{payload[:name]} (#{event.duration.round(1)}ms)"
    name  = "CACHE #{name}" if payload[:cached]

    binds = type_casted_binds(payload[:type_casted_binds])
    # 親クラスの実装は debug で出力されるようになっているが
    # 今回は info で出力する
    info("#{name}  #{color(sql_str, sql_color(sql_str), true)}; #{binds}")
  end
end

# AcitveSupport::Notifications の"active_record" の namespace に
# ProfileLogSubscriber#sql を登録する
ProfileLogSubscriber.attach_to :active_record

event.payload は Hash で、実行されたSQL文(:sql)、SQLの種類を示す名前(:name)、SQL に bind する値(:bind_casted_binds) 等の情報が含まれています。これらを使って、出力するかどうかの判定と、ログに出力する文字列を作成しています。

ちなみに payload{:name] ですが、ActiveRecrod::Relation#explain を呼び出したときは "EXPLAIN"、テーブル情報等スキーマの情報を取得するSQLが発行された場合は "SCHEMA" になります。その他には、transaction を開始/終了した場合は "TRANSACTION"、定義したテーブルのレコードを操作した場合は "<モデル名> <操作名>" (例: Profile Load)になります。

以下は、前述のコードを config/initializers ディレクトリに配置し、development 環境のログレベルを info に設定した上で、bin/rails console を実行してクエリを発行した様子の画像です。profiles テーブルの memo を更新したときのみ SQL が出力されているのがわかると思います。