ActiveSupport::Notificationsで実行されるSQLを確認する
ActiveRecordなどORMを使用していると、うっかり大量のSQLを発行してしまうことがある。Bulletを使えばN+1のクエリは検知出来るが、そうでないクエリでも肥大化するケースはある。 例えば、集計するような処理を複数のモデルからメソッドを寄せ集めて書いていると、いつの間にか実行されるSQLが膨れ上がっていたということがあった。 もちろん実装の問題なので、そのときは実装方法を考え直して解消したが、そもそも開発している段階では、ログに張り付いていないと気付きにくいという問題がある。
ブラウザでロードした際に実行される処理であれば、rack-mini-profilerやChrome拡張のRails PanelからSQLの数と内容を確認できるが、APIやバックグラウンド処理の場合は難しい。 もっとカジュアルに確認できないものかと調べていたら、ActiveSupport::Notificationsで簡単にSQLを拾えることが分かったので、これを利用してテストを書くことにした。
バージョン
- Rails 4.2.2
ActiveSupport::Notificationsについて
以下のスライドとブログがとてもわかりやすい。
- つながりをゆるふわにしよう Active supprt notifications
- Railsの計測を支えるActiveSupport::Notificationsについて | GMOメディア エンジニアブログ
今回はActiveRecordがSQLを発行した際に実行されるイベント(sql.active_record)を利用する。
.subscribe
メソッドのインターフェースは以下の通り。
ActiveSupport::Notifications.subscribe('イベント名') do |name, start, finish, id, payload| name # => String, name of the event (such as 'render' from above) start # => Time, when the instrumented block started execution finish # => Time, when the instrumented block ended execution id # => String, unique ID for this notification payload # => Hash, the payload end
また、sql.active_recordのpayloadの中身は以下のようになっている。(アダプターはMySQL)
{ sql: "SELECT `users`.* FROM `users`", name: "User Load", # キャッシュが有効な場合は`CACHE`となる connection_id: 70255513457520, statement_name: nil binds: [] }
確認方法
payloadを全て持っていれば、様々な条件で使用できるので、適当な場所にpayloadを配列に入れて返すヘルパーを定義する。
def capture_queries(&block) queries = [] ActiveSupport::Notifications.subscribe('sql.active_record') do |_name, _start, _finish, _id, payload| queries << payload end yield block ActiveSupport::Notifications.unsubscribe('sql.active_record') queries end
調べたいときは上で定義したヘルパーに確認したいメソッドや処理を渡せばいい。
let(:queries) do capture_queries do super_heavy_task end end it do # キャッシュされていないSQL一覧を表示 queries.each do |q| next if q[:name] == 'CACHE' puts q[:sql] end # 実行されるSQLが10以下であることをテスト expect(queries.count).to be < 10 end
別にRSpecである必要もないので、コントローラやモデルに書いてもいい。
手軽なのでパフォーマンスチューニングの際にお試しください。