switch_pointを使いながら、発行SQLと接続先情報を一緒にログに落としてみる

このエントリーは、Money Forward Advent Calendar 2016の記事です。

終わってみたら空きがあったので、埋めてみました。

SwitchPoint

負荷分散などの目的で、read SQLはSlaveへ向ける、などの処理を記述する場合、switch pointなどのgemを使用するかと思います。

その際、SELECT文が正しく readonly DBに向けて発行されているのか？
などを確認したくなりました。

ARPRoxy

arproxyは、ActiveRecordが発行したSQLがDB Adapterによって実行される直前に処理を差し込むことができます。

Arproxy ActiveRecordが発行したSQLを加工できるGem - 酒と泪とRubyとRailsと
こちらの記事が分かりやすい

ログに落としてみよう

switch_pointの情報は、 def execute 内で

$ self.proxy_chain.connection.instance_variable_get(:@config)[:switch_point]
=> {:name=>:hoge_db, :mode=>:writable}

という感じで取得できそうです。

Loggerに

  class SwitchPointConnectionLog < Arproxy::Base
    def execute(sql, name=nil)
      database_config = self.proxy_chain.connection.instance_variable_get(:@config)

      Rails.logger.debug "host: #{database_config[:host]}, database: #{database_config[:database]}, switch_point: #{database_config[:switch_point]}"

      super(sql, name)
    end
  end

  Arproxy.configure do |config|
    config.adapter = "mysql2"
    config.use SwitchPointConnectionLog
  end
  Arproxy.enable!

SQL Commentに

Loggerだと、SQLと同じ行に出力されないので

  class SwitchPointConnectionLogToSqlComment < Arproxy::Base
    def execute(sql, name=nil)
      database_config = self.proxy_chain.connection.instance_variable_get(:@config)

      sql += " /* host: #{database_config[:host]}, database: #{database_config[:database]}, switch_point: #{database_config[:switch_point]} */"

      super(sql, name)
    end
  end

  Arproxy.configure do |config|
    config.adapter = "mysql2"
    config.use SwitchPointConnectionLogToSqlComment
  end
  Arproxy.enable!

December 26, 2016 12:12345 [DEBUG] SQL (1.1ms)  UPDATE `hoge_db`.`users` SET `updated_at` = '2016-12-26 12:34:56' WHERE `hoge_db`.`users`.`id` = 1 /* host: localhost, database: hoge_db, switch_point: {:name=>:hoge_db, :mode=>:writable} */ (pid:12345)

もともと開発時に欲しかっただけなので、実際には、 if Rails.env.development? な条件にしてます。