query_trace: SQLが発行されたファイルと行番号を調べる

ruby

Railsで、ActiveRecordがSQLのログを吐いてくれるんですが、これだとどのクエリがどこから呼ばれたのか分からなくて、デバッグがしにくい。

  Schedule Load (0.023687)   SELECT * FROM schedules WHERE (schedules.id = 3) LIMIT 1
  Resource Load (0.001076)   SELECT * FROM resources WHERE (resources.id = 328) LIMIT 1
  Schedule Load (0.011488)   SELECT * FROM schedules WHERE (schedules.id = 3) LIMIT 1
  Resource Load (0.022471)   SELECT * FROM resources WHERE (resources.id = 328) LIMIT 1

query_trace （ http://rubygems.org/gems/query_trace ）というライブラリを使うと、こんな風にスタックトレースが出るようになるので、このクエリってどこから出てるんだろ？ みたいなときのデバッグがとても楽になります。

  Schedule Load (0.023687)   SELECT * FROM schedules WHERE (schedules.id = 3) LIMIT 1
    app/models/available_work.rb:50:in `study_method'
    app/helpers/plan_helper.rb:4:in `work_description'
    app/views/plan/_resource_schedule.rhtml:27:in `_run_rhtml_plan__resource_schedule'
    app/views/plan/_resource_schedule.rhtml:24:in `_run_rhtml_plan__resource_schedule'
    app/views/plan/_schedule_listing.rhtml:5:in `_run_rhtml_plan__schedule_listing'
    app/views/plan/_schedule_listing.rhtml:3:in `_run_rhtml_plan__schedule_listing'
    app/views/plan/_schedule_listing.rhtml:1:in `_run_rhtml_plan__schedule_listing'
    app/views/plan/index.rhtml:6:in `_run_rhtml_plan_index'
    vendor/plugins/textmate_footnotes/lib/textmate_footnotes.rb:60:in `render'
  Resource Load (0.001076)   SELECT * FROM resources WHERE (resources.id = 328) LIMIT 1
    app/models/available_work.rb:54:in `div_type'
    app/helpers/plan_helper.rb:6:in `work_description'
    app/views/plan/_resource_schedule.rhtml:27:in `_run_rhtml_plan__resource_schedule'
    app/views/plan/_resource_schedule.rhtml:24:in `_run_rhtml_plan__resource_schedule'
    app/views/plan/_schedule_listing.rhtml:5:in `_run_rhtml_plan__schedule_listing'
    app/views/plan/_schedule_listing.rhtml:3:in `_run_rhtml_plan__schedule_listing'
    app/views/plan/_schedule_listing.rhtml:1:in `_run_rhtml_plan__schedule_listing'
    app/views/plan/index.rhtml:6:in `_run_rhtml_plan_index'
    vendor/plugins/textmate_footnotes/lib/textmate_footnotes.rb:60:in `render'
                         :

インストール

2010/10/11現在、 query_trace の最新バージョンは 0.1.1 なんですが、これだとまだRails3に対応していないので、githubから新しいコミットを取ってくることにします。
Gemfileに以下を追記して、 bundle install 。

gem 'query_trace', :git => 'http://github.com/dolzenko/query_trace.git', :ref=>'0e142a25c76816002da7'

もちろん、 0.1.1 以降がリリースされていれば、そちらを使うのがいいでしょう。

使い方

rails server起動時に、環境変数 QUERY_TRACE=true を設定するだけでOKです。

$ QUERY_TRACE=true script/rails server

もしくは、 config/initializers/ 以下あたりに

QueryTrace.enable!

と書いた初期化ファイルを置いておきます。
これだけで、最初に紹介したようなトレースが出るようになります。Rails3はArelの遅延クエリ機能があるおかげで、思わぬところでクエリが発行されたりしまいがちなので、開発時は普段からトレースを出しておくと色々発見があるかもですね。