Rails で更新系 SQL クエリをログ

2020年4月20日
- ruby
- rails

DB への書き込みの負荷が大きい Rails アプリケーションで、どこで多くの書き込みが発生しているか調べるためにログを出力するようにした。

arproxy を使って、更新系 (INSERT, UPDATE, DELETE) のクエリが発行される際に Rails.logger を使ってログ出力する。

bundle add arproxy して、下記を config/initializers/arproxy.rb などに保存する。

class UpdateLogger < Arproxy::Base
  # Rail.root 下で vendor 以外にマッチするパターン
  RAILS_ROOT_REGEXP = Regexp.compile("^" + Regexp.escape(Rails.root.to_s) + "/(?!vendor)")

  def execute(sql, name = nil)
    return super unless log?(sql)

    result = nil
    time = Time.now
    ms = Benchmark.ms { result = super(sql, name) }
    backtrace = caller.map {|line| line.gsub!(RAILS_ROOT_REGEXP, "") }.compact
    log_sql(sql, ms, backtrace, time)

    result
  end

  private
  def log_sql(sql, ms, backtrace, time)
    Rails.logger.info(
      {
        type: "update_logger",
        duration: ms.round(1),
        sql: sql,
        backtrace: backtrace,
        time: time.to_i,
      }.to_json,
    )
  end

  def log?(sql)
    sql.strip.match?(/^(INSERT|UPDATE|DELETE)/i)
  end
end

Arproxy.configure do |config|
  config.adapter = "mysql2"
  config.use UpdateLogger
end

Arproxy.enable! if ENV["ARPROXY"] || File.exists?("#{Rails.root}/tmp/arproxy")

クエリの他に、クエリの実行にかかった時間と、どこのコードから呼ばれたかを (gem のパスを除外して) 記録している。

常に記録しておく必要はないので、環境変数 ARPROXY または tmp/arproxy ファイルの有無で起動時に有効・無効を切り替えるようにした。

JSON で記録して CloudWatch Logs に送信しておくと CloudWatch Insight でリアルタイムで分析できて便利。