- 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 結果を得られる。