RailsでN+1を検出するならProsopiteがおすすめ

この記事はコインチェック株式会社（以下、コインチェック）のアドベントカレンダー13日目の記事です。コインチェック株式会社のイネイブリングチームでエンジニアをしているyoanです。

はじめに

コインチェックでは Rails アプリケーションのパフォーマンス改善のため、以前から N+1 クエリ検出ツールとして Bullet を導入していました。Bullet は広く使われている優れたツールですが、実際の運用の中で検出できないパターンに遭遇することがありました。

そこで Prosopite という gem を試したところ、Bullet では発見できなかった N+1 問題を見事に検出してくれました。ただし検出に関してはBulletが悪いのではなく、コインチェックのコードに問題がありました。本記事では、実際に遭遇した問題と、Bullet と Prosopite の違い、そして Prosopite の弱点についてご紹介します。

Bulletへの疑問

弊社では Bullet を導入しているにも関わらず、Datadog で N+1 が発生している API が見つかっており Bullet の信頼性はあまり高くありませんでした。なぜ Bullet では検出できないのか興味を持ったため今回の調査に乗り出しました。

Controller Spec での N+1 問題

コインチェックのコードベースは歴史が古く Controller Spec がまだ残っています。 Bullet で検出できなかった API もその多くは Controller Spec でした。

問題のコードは以下のようなものでした：ここでは注文したアカウントを取得し、そのウォレットからなにかしらするAPIを考えます

RSpec.configure do |config|

  # ...

  if Bullet.enable?
    config.before do
      Bullet.start_request
    end

    config.after do
      Bullet.perform_out_of_channel_notifications if Bullet.notification?
      Bullet.end_request
    end
  end

  # ...

end

def some_api
  orders = Order.all
  orders.each do |order|
    some_method(order.account.wallet)
  end
end

テストは下記のようなイメージです。

require "rails_helper"

RSpec.describe SomeController, type: :controller do
  describe "GET some_api" do
    subject { get :some_api }

    context "when valid case" do
      before do
        account1 = create(:account)
        account2 = create(:account)

        order1 = create(:order, amount: 0.1, currency: "BTC", account: account1)
        order2 = create(:order, amount: 0.1, currency: "ETH", account: account2)
      end

      it { is_expected.to have_http_status(:ok) }
    end
  end
end

このコードは Controller Spec で実際には N+1 クエリになっていますが Bullet で検出できませんでした。

なぜ Bullet で検出できなかったのか

ここでは Bullet の詳細を深堀りしていき、なぜ N+1 を検出できなかったのか説明します。

Bullet の N+1 検出の仕組み

Bullet.start_request は以下のレジストリを初期化します：

def start_request
  Thread.current[:bullet_start] = true
  Thread.current[:bullet_possible_objects] = Bullet::Registry::Object.new       # N+1の可能性があるオブジェクト
  Thread.current[:bullet_impossible_objects] = Bullet::Registry::Object.new     # N+1の可能性がないオブジェクト（新規作成されたレコードなど）
  Thread.current[:bullet_object_associations] = Bullet::Registry::Base.new      # includes/preloadされた関連
  # ...
end

Bullet は以下の条件で N+1 を判定します：オブジェクトが

possible_objects に含まれる（複数件取得されたクエリの結果）
impossible_objects に含まれない（新規作成されたレコードではない）
object_associations に含まれない（事前ロードされていない）

重要なポイント：Bullet は新規作成されたレコードを impossible_objects に登録し、N+1 の対象外とします。これは、新規作成直後のオブジェクトは関連データも一緒にメモリ上にあることが多く、実際には N+1 が発生しないケースが多いためと考えられます。

Controller Spec で検出できない理由

Controller Spec では以下の順序で実行されます：

rails_helper.rb で Bullet.start_request が呼ばれる（レジストリ初期化）
before 句でダミーデータ（account と order）が生成される
- → これらは impossible_objects に登録される（新規作成扱い）
get :some_api が呼ばれる（Rack Middleware は呼ばれない）
API 内で Order.all を実行
- → before 句で作成した order が返される
order.account.wallet にアクセス
- → しかし order は impossible_objects に含まれているため N+1 として検出されない！

問題の本質：Rack Middleware が呼ばれないため、Bullet.start_request がテストの最初に一度だけ実行され、API 実行前に再初期化されません。その結果、before 句で作成したレコードが impossible_objects に残り続け、本来検出されるべき N+1 が見逃されます。

Request Spec では検出される理由

Request Spec では Rack Middleware が実行されるため、以下の順序になります：

rails_helper.rb で Bullet.start_request が呼ばれる
before 句でダミーデータが生成される
- → impossible_objects に登録される
get '/some_api' が呼ばれる
- → Rack Middleware が Bullet.start_request を呼ぶ（レジストリが再初期化される！）
API 内で Order.all を実行
- → possible_objects に登録される（before 句の impossible_objects はクリアされている）
order.account.wallet にアクセス
- → N+1 として正しく検出される

Controller Spec と Request Spec の違い

RSpec には Controller Spec と Request Spec という2種類のテストがあります。 RSpec 3.5の時点でRequest Specの利用を推奨しています。

For new Rails apps: we don't recommend adding the rails-controller-testing gem to your application. The official recommendation of the Rails team and the RSpec core team is to write request specs instead. Request specs allow you to focus on a single controller action, but unlike controller tests involve the router, the middleware stack, and both rack requests and responses. This adds realism to the test that you are writing, and helps avoid many of the issues that are common in controller specs. In Rails 5, request specs are significantly faster than either request or controller specs were in rails 4, thanks to the work by Eileen Uchitelle[^foot_1] of the Rails Committer Team.

RSpec 3.5 has been released!

これによると Request Spec は Controller Spec とは異なり Router や middleware 層を利用するためより現実的なテストになっているようです。弊社では大量の Controller Spec が残っており、そのすべてを Request Spec に変更するには他チームの協力が不可欠で現実的ではありません。そこで別の gem である Prosopite に注目しました。

Prosopiteの導入

Prosopite は Middleware に依存せず、SQL クエリの実行パターンを直接監視します。そのため、Controller Spec でも問題なく動作しました。また Bullet は ActiveRecord のメソッドをオーバーライドすることで監視をしてますが、Prosopite は ActiveSupport::Notification.subscribe を利用しています。そのため ActiveRecord のバージョンを上げるごとに Bullet もバージョンを上げる必要がありましたが、Prosopite ではその依存もなくなります。

Middleware に依存せず、ActiveRecord にも依存しないことから Prosopite を採用することにしました。

Prosopite の弱点

実際に Prosopite を運用してみて、いくつか弱点も見えてきました。

1. allow_stack_paths の指定が緩い

Prosopite では allow_stack_paths にファイル名を含めることで該当ファイルに含まれるクエリが N+1 になっても無視します。この allow_stack_paths は単純で下記のような処理をしています。

N+1 を検出
Kernel.#caller_locations と allow_stack_paths を比較
どれか一つでもマッチするなら無視

個人的にテスト内のクエリに関しては遅くないならどう書いても構わない（見やすさを優先すべき）と考えています。そのため spec 内でのクエリは許可したいのですが、caller_locations には app ファイルも spec ファイルも両方含まれてしまいます。したがって spec ファイルを allow_stack_paths に含めてしまうと、app ファイルの N+1 が検出されません。

spec/models/user_spec.rb:123 と行数を指定することもできますが、ファイルを書き換えると行数も更新する必要がでるため採用できません。

弊社ではエラーとなったクエリを正規化してクエリ ignore_queries に追加しました（ログから正規化されたクエリを生成するコストも高く、結局 1000 クエリほど手動で書き換えました）

2. 集計情報がない

これは Bullet にもありませんが、どのファイルに N+1 が多いか集計して可視化をしたいですが集計機能がありません。そこで N+1 のエラー情報をパースして集計する簡単なスクリプトを作成しました。

class Prosopite::LogParser
  attr_reader :n_plus_one_map

  IGNORED_TRACE_PATHS = ["app/models/hogehoge.rb"].freeze

  def initialize
    @n_plus_one_map = {}
  end

  def parse(data)
    log_contents = data.split("\n")
    size = log_contents.size

    i = 0
    while i < size
      line = log_contents[i]

      if line.match?(/^Call stack:/)
        j = i + 1

        traces = []
        loop do
          trace = log_contents[j]
          break if trace.blank?

          # path_and_line_numは "app/models/hoge.rb:123" のような形式
          path_and_line_num = trace.strip.split(":")[0..1].join(":")
          traces << path_and_line_num
          j += 1
        end

        # backtrace_cleanerによってトレース情報が空のパターン
        # specにN+1が含まれていた場合が挙げられる
        if traces.empty?
          i = j
          next
        end

        filtered_traces = (traces - IGNORED_TRACE_PATHS)
        if filtered_traces.empty?
          i = j
          next
        end

        trace = filtered_traces[0]

        n_plus_one_map[trace] = 0 if n_plus_one_map[trace].nil?
        n_plus_one_map[trace] += 1
        i = j
      end

      i += 1
    end
  end
end

def main
  parser = Prosopite::LogParser.new
  data = File.read("log/Prosopite.log")
  parser.parse(data)

  parser.n_plus_one_map.sort_by { |_path, count| -count }.each do |path_line_num, count|
    puts "#{path_line_num}: #{count}"
  end
end

まとめ

コインチェックでは Bullet で検出できなかった N+1 問題を Prosopite で発見・解決できました。これはコインチェックが Controller Spec が大量に残っており、Rack Middleware で制御する Bullet と相性が悪かったことが原因です。 Prosopite はそのシンプルな構造からコインチェックへの移行もスムーズに行えました。 Bullet の信頼性に疑問を覚えるプロジェクトがあれば Prosopite を試しに使ってみることをおすすめします。（そしておそらく Bullet のせいではありません）

Coincheck Tech Blog