N+1 ハントの話

こんにちは！アルダグラムでエンジニアをしている森下霞です。

Rails の ActiveRecord を使って素早くDBとのやり取りが書けるのですが、そこに罠があります。N+1 深い罠です。開発時に気づきづらい問題である N+1 の自動探知について話しようと思います。

どうして気づきづらい

開発時にタスク通りの動作やコードの読みやすさに焦点を当てることがおそらく多いが、その中で N+1 を見逃してしまうことがしばしばあると思います。

ログは N+1 問題の手がかりを提供しますが、開発者はログを常に注意深く確認しているわけではありません。特に大規模なシステムでは、ログの量が膨大であり、問題が埋もれてしまう可能性があります。

また、テストカバレッジが十分でない場合、N+1 問題はテスト中に見逃されやすくなります。特に異なる条件やデータ量に対するテストが不足していると、問題の存在に気づくことが難しくなります。

それに、N+1 問題が初期段階では目立たないことがあります。小規模なデータセットでは問題が発生せず、開発者はそれを見逃すことがあります。しかし、システムが拡大するにつれて問題が浮き彫りになることがあります。

どうやって見つける

コードから

コレクションやデータベースの結果に対する反復処理が発生する場合、N+1問題が発生している可能性があります。特に、foreach ループ内でデータベースへの問い合わせが行われていないか確認が重要です。

ログから

ログから問題を見つけるためにはクエリの実行回数に着目します。同じタイプのクエリが複数回実行されていないか確認することで N+1 が見つけます。

自動的に探知する仕組み

N+1問題を見つける方法として、上記のコードやログから検知する手段がありますが、どちらも開発中に忘れやすいものです。そのため、N+1 問題の発生を完全に検知することは難しいです。そこで、N+1 問題を自動的に検知できる方法があれば、よりパフォーマンスがいいコードを簡単に書くことができます。

N+1 を自動的に探知するのに一般的に知られてるのは bullet gem です。

既存のアプリでの活用方法は以下になります。

ログ

Bullet がログで N+1 の起こってる箇所を書き出すのに、developement と test 環境に以下の設定を追加します。

development.rb

config.after_initialize do
  Bullet.enable = true
  Bullet.alert = true
  Bullet.bullet_logger = true
  Bullet.console = true
  Bullet.rails_logger = true # bullet.log を見忘れても、rails ログで見れるのは見逃しにくい
end

test.rb

config.after_initialize do
  Bullet.enable = true
  Bullet.bullet_logger = true
  Bullet.console = true # 特にこの設定で、STDOUT で N＋1 のアラートが見れるので、見逃しにくい
  Bullet.rails_logger = true
end

テストを失敗させる

また、新しいテストを追加する際、以下の設定を付け加えると、N+1 が検知された場合にテストが失敗するようになります。この設定をすべてのテストに適用できれば、N+1 に完全に対処できたとみなすことができます。

config.before(:each, bullet_mode: :error) do
  Bullet.raise = true
end

テストの定義で：

RSpec.describe MyClassToTest, bullet_mode: :error do
  ...

起こってる箇所を洗い出し

開発中にN+1を追加しないようにするには、上記の設定でできるですが、既存のコードにおける N+1 の探知は依然としてややこしい問題が残ります。私はその対策として、全体の RSpec を実行し、bullet.log の内容をパースして結果をCSVに出力するコードを書きました。具体的な実装は以下の通りです。

def extract_file_and_method_name(input_string)
  # ファイル名と行番号を取り出す正規表現
  regex = %r{^(.*\.rb):(\d+):in [`'](.+)(?:'$|$)}

  match = input_string.match(regex)

  if match
    file_location = match[1]
    line_number = match[2].to_i
    method_name = match[3]

    return [file_location, line_number, method_name]
  else
    puts "Invalid input format"
  end
end

# csv を読みやすくするために、エラーになった行のコンテキストを取り出して貼り付ける
def extract_lines_around(file_path, target_line_number, context_lines = 10)
  # 問題が起こったruby ファイルを読み取る
  lines = File.readlines(file_path)

  # context_lines数行前の行番号を見つけ出す
  start_line = [0, target_line_number - context_lines - 1].max
  # context_lines数行後の行番号を見つけ出す
  end_line = [lines.length - 1, target_line_number + context_lines - 1].min

  # start と end の間になる問題コンテキストを取り出す
  extracted_lines = lines[start_line..end_line]

  result = []
  extracted_lines.each_with_index do |line, index|
    line_number = start_line + index + 1
    # 行番号と行自体を書き込む
    result << "#{line_number}: #{line}"
  end
  result.join
end

# テストで同じ箇所何回も出ることが多いので、ユニーク化する
uniq_rows = {}
csv_rows.uniq.each do |error, call_stack|
  first_line = call_stack.lines.first
  # とりあえず、テストのコードで起こってる N+1 を無視する
  next if first_line.include?('_spec.rb:')
  file_location, line_number, method_name = extract_file_and_method_name(first_line)
  # エラーと起こった箇所でユニーク化
  uniq_rows[[error, first_line]] ||= [error, file_location, method_name, call_stack, extract_lines_around(file_location, line_number)]
end; 0

output_file_path = 'log/run_all_rspec_result_1_25.csv'
CSV.open(output_file_path, 'wb') do |csv|
  csv << ['Error', 'File location', 'Method name', 'Call Stack', 'Context']
  uniq_rows.values.each { |row| csv << row }
end; 0

自動的に探知できないところ

N+1を検知できないケースとして3つほど提示します。

1. テストでカバーされてないところ

simplecov gem を使用して、テストカバレッジ率を確認することができます。ループなどでSQLが発行される箇所が十分にカバーされないと、テストにおいては自動的に検知されないことがあります。

ちなみに、弊社ではテストカバレッジ率向上の話は以下になります！

RSpec のテストカバレッジ率向上の取り組み

2. テストデータセット量が不足

テストでなるべくデータを数量を作るといいです。テストデータセット量が少ないと、SELECT文の実行回数が限定的になり、Bullet が通常検知する条件を満たさないことになります。

3. SQL文が微妙に違う

以下のようなクエリが探知されません。ここでは各文の author が異なります。

SELECT count(*) FROM books WHERE author = 'Author 1'
SELECT count(*) FROM books WHERE author = 'Author 2'

Bulletは通常、1つの親レコードを取得する際に、その関連した子レコードを個別に取得することで発生する N+1 問題を探知します。上記のクエリでは、関連ではなく個別の条件に基づいてカウントを行っているため、人目で見ると N+1 に見えますが、Bullet には対象になりません。

また、SQL文が類似しているもの完全に同一ではないときです。Bulletは通常、同一のSQL文が複数回実行される場合にアラートを発生させますが、文の構造が微妙に異なる場合は検知が難しくなります。SQL文が同一でない場合、Bullet が検知するのが難しいケースがあります。

さらに、クエリやモデルに特殊な関連付けが存在する場合、Bulletがこれを正しく検知できないことがあります。例えば、ancestryのようなツリー構造や他の非標準的な関連付けがある場合、Bulletが対応できないことがあります。

まとめ

パーフォマンスに大きな影響を与える N+1 問題を避けるためには、十分なテストカバレジを確保し、複数のデータセットを用意し、さらに bullet gem を活用して、性能向上を図るコードを書きましょう。

もっとアルダグラムエンジニア組織を知りたい人、ぜひ下記の情報をチェックしてみてください！