Rails 3.2 ActiveRecord の自動 EXPLAIN に関するメモ

• http://weblog.rubyonrails.org/2011/12/6/what-s-new-in-edge-rails-explain/
• http://guides.rubyonrails.org/active_record_querying.html#running-explain
• config.active_record.auto_explain_threshold_in_seconds

logging_query_plan に与えたブロックの実行時間が閾値を超えていた場合、EXPLAINの結果がログに WARN レベルで記録される。

activerecord-3.2.13/lib/active_record/explain.rb

    def logging_query_plan # :nodoc:
      return yield unless logger

      threshold = auto_explain_threshold_in_seconds
      current   = Thread.current
      if connection.supports_explain? && threshold && current[:available_queries_for_explain].nil?
        begin
          queries = current[:available_queries_for_explain] = []
          start = Time.now
          result = yield
          logger.warn(exec_explain(queries)) if Time.now - start > threshold
          result
        ensure
          current[:available_queries_for_explain] = nil
        end
      else
        yield
      end
    end

logging_query_plan にブロックを渡しているのは、find_by_sqlとto_aである模様。

• activerecord-3.2.13/lib/active_record/querying.rb
• activerecord-3.2.13/lib/active_record/relation.rb

find_by_sqlではブロック内でselect_allして得られたデータを使ってインスタンス化していて、to_aではブロック内でexec_queriesを実行している。

閾値が比較されるのは、純粋なSQL実行時間がだけではなく、ActiveRecord が必要とするモデルインスタンスを生成するまでにかかった時間も含んでいる模様。

余談：Rails4 の自動 EXPLAIN

リリースノートにあるとおり、Rails4では自動 EXPLAIN が削除された。経緯は知らない。

Remove automatic execution of EXPLAIN queries. The option active_record.auto_explain_threshold_in_seconds is no longer used and should be removed.
Ruby on Rails 4.0 Release Notes

閾値を元に自動で EXPLAIN してログに記録する機能は消えたが、explain メソッド自体は消えてない。
supports_explain? で EXPLAIN が使えるか判断でき、explain メソッドで EXPLAIN 結果を得られる。