ActiveSupport::Notificationsで実行されるSQLを確認する

ActiveRecordなどORMを使用していると、うっかり大量のSQLを発行してしまうことがある。Bulletを使えばN+1のクエリは検知出来るが、そうでないクエリでも肥大化するケースはある。 例えば、集計するような処理を複数のモデルからメソッドを寄せ集めて書いていると、いつの間にか実行されるSQLが膨れ上がっていたということがあった。 もちろん実装の問題なので、そのときは実装方法を考え直して解消したが、そもそも開発している段階では、ログに張り付いていないと気付きにくいという問題がある。

ブラウザでロードした際に実行される処理であれば、rack-mini-profilerChrome拡張のRails PanelからSQLの数と内容を確認できるが、APIやバックグラウンド処理の場合は難しい。 もっとカジュアルに確認できないものかと調べていたら、ActiveSupport::Notificationsで簡単にSQLを拾えることが分かったので、これを利用してテストを書くことにした。

バージョン

ActiveSupport::Notificationsについて

以下のスライドとブログがとてもわかりやすい。

今回はActiveRecordSQLを発行した際に実行されるイベント(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である必要もないので、コントローラやモデルに書いてもいい。

手軽なのでパフォーマンスチューニングの際にお試しください。

参考