FactoryBotでアソシエーションありのモデルを生成する時に気をつけないとN+1が発生する

Railsアプリケーションのテストコードを書くときにRSpec＋FactoryBotを使っているのですが、特に気にせず書いていた記述でN+1が発生することがあったので共有します。

実行環境

Ruby: 2.6.5
Rails: 6.0.0
rspec-rails: 3.9
factory_bot_rails: 5.1.1

N+1が発生するサンプル

reviewsリソースのindexアクションのリクエストスペックを想定しています。

Models

ModelはUserとReviewが一対多で関連しています。

app/models/user.rb

class User < ApplicationRecord
  has_many :reviews
end

app/models/review.rb

class Review < ApplicationRecord
  belongs_to :user

  enum status: {
    draft: 0,
    published: 1,
    deleted: 9,
  }
end

db/migrate/20190914140349_create_users.rb

class CreateUsers < ActiveRecord::Migration[6.0]
  def change
    create_table :users do |t|
      t.string :name

      t.timestamps
    end
  end
end

class CreateReviews < ActiveRecord::Migration[6.0]
  def change
    create_table :reviews do |t|
      t.string :content, default: ''
      t.references :user, null: false, foreign_key: true
      t.integer :status, default: 0

      t.timestamps
    end
  end
end

Contoller

パラメーターで指定されたstatusで絞り込んだReviewを返却しています。
※不正なパラメータの対処など今回の本題ではない処理は省略しています

app/controllers/reviews_controller.rb

class ReviewsController < ApplicationController
  def index
    render json: Review.where(status: Review::statuses[index_params[:status]])
  end

  private

  def index_params
    params.require(:reviews).permit(:user_id, :status)
  end
end

RSpec

下記のようなRSpecがあります。
どこがN+1になっているでしょうか？

spec/requests/reviews_spec.rb

require 'rails_helper'

RSpec.describe ReviewsController, type: :request do
  describe 'GET /reviews' do
    let(:headers) { { 'CONTENT_TYPE': 'application/json', 'Accept': 'application/json'} }
    let(:params) { { reviews: { user_id: user.id, status: status } } }
    let(:user) { FactoryBot.create(:user) }
    let(:body) { JSON.parse(response.body) }

    subject(:req) { get reviews_path, { headers: headers, params: params } }

    before do
      FactoryBot.create(:review, :draft, user_id: user.id, content: 'first draft review.')
      FactoryBot.create(:review, :draft, user_id: user.id, content: 'second draft review.')
      FactoryBot.create(:review, :published, user_id: user.id, content: 'first published review.')
      FactoryBot.create(:review, :published, user_id: user.id, content: 'second published review.')
      FactoryBot.create(:review, :published, user_id: user.id, content: 'third published review.')
    end

    context '下書きを指定した場合' do
      let(:status) { :draft }
      it '下書きの口コミが取得できること' do
        req
        expect(body.all?{ |b| b['status'] == 'draft' }).to be_truthy
      end
    end

    context '公開中を指定した場合' do
      let(:status) { :published }
      it '公開している口コミがが取得できること' do
        req
        expect(body.all?{ |b| b['status'] == 'published' }).to be_truthy
      end
    end
  end
end

N+1が発生する箇所

上記RSpecを実行した場合のログでN+1になっている箇所を抜粋します。
下記の通り、Reviewをcreateする直前に毎回同じUserをreadしています。

log/test.log

  User Load (1.5ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 22 LIMIT 1
  Review Create (0.7ms)  INSERT INTO `reviews` (`content`, `user_id`, `created_at`, `updated_at`) VALUES ('first draft review.', 22, '2019-10-21 17:38:15.420491', '2019-10-21 17:38:15.420491')
  User Load (0.7ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 22 LIMIT 1
  Review Create (0.7ms)  INSERT INTO `reviews` (`content`, `user_id`, `created_at`, `updated_at`) VALUES ('second draft review.', 22, '2019-10-21 17:38:15.427775', '2019-10-21 17:38:15.427775')
  User Load (0.8ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 22 LIMIT 1
  Review Create (0.8ms)  INSERT INTO `reviews` (`content`, `user_id`, `status`, `created_at`, `updated_at`) VALUES ('first published review.', 22, 1, '2019-10-21 17:38:15.435365', '2019-10-21 17:38:15.435365')
  User Load (0.8ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 22 LIMIT 1
  Review Create (0.7ms)  INSERT INTO `reviews` (`content`, `user_id`, `status`, `created_at`, `updated_at`) VALUES ('second published review.', 22, 1, '2019-10-21 17:38:15.443010', '2019-10-21 17:38:15.443010')
  User Load (0.7ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 22 LIMIT 1
  Review Create (0.7ms)  INSERT INTO `reviews` (`content`, `user_id`, `status`, `created_at`, `updated_at`) VALUES ('third published review.', 22, 1, '2019-10-21 17:38:15.450051', '2019-10-21 17:38:15.450051')

なぜN+1になるのか

FactoryBot.createでデータを作る際、reviewのアソシエーションであるuserを指定するときに上記ではuser_idで指定しています。
FactoryBotではアソシエーションをidで指定された場合、作成時に当該データを取得して関連付けてデータを作成するようです。
そのため、xxx_idで指定した場合は必ずselectが発生してしまいます。
ただ、同じselectを何度も実行するのはどう考えても無駄です。
これを回避するのは簡単で、下記のようにモデルを直接指定すれば良いです。

spec/requests/reviews_spec.rb#当該箇所のみ

    before do
      FactoryBot.create(:review, :draft, user: user, content: 'first draft review.')
      FactoryBot.create(:review, :draft, user: user, content: 'second draft review.')
      FactoryBot.create(:review, :published, user: user, content: 'first published review.')
      FactoryBot.create(:review, :published, user: user, content: 'second published review.')
      FactoryBot.create(:review, :published, user: user, content: 'third published review.')
    end

上記に直して再度実行。ログを見てみるとuserがselectされていません！

  Review Create (1.1ms)  INSERT INTO `reviews` (`content`, `user_id`, `created_at`, `updated_at`) VALUES ('first draft review.', 26, '2019-10-21 17:56:11.619272', '2019-10-21 17:56:11.619272')
  Review Create (1.0ms)  INSERT INTO `reviews` (`content`, `user_id`, `created_at`, `updated_at`) VALUES ('second draft review.', 26, '2019-10-21 17:56:11.630369', '2019-10-21 17:56:11.630369')
  Review Create (1.9ms)  INSERT INTO `reviews` (`content`, `user_id`, `status`, `created_at`, `updated_at`) VALUES ('first published review.', 26, 1, '2019-10-21 17:56:11.639061', '2019-10-21 17:56:11.639061')
  Review Create (0.9ms)  INSERT INTO `reviews` (`content`, `user_id`, `status`, `created_at`, `updated_at`) VALUES ('second published review.', 26, 1, '2019-10-21 17:56:11.646400', '2019-10-21 17:56:11.646400')
  Review Create (0.7ms)  INSERT INTO `reviews` (`content`, `user_id`, `status`, `created_at`, `updated_at`) VALUES ('third published review.', 26, 1, '2019-10-21 17:56:11.656874', '2019-10-21 17:56:11.656874')

まとめ

これを気をつけることで1つ1つのテストケースで見ると数msの短縮にしかなりませんが、実際のテストケースは数百数千あると思うので、もしこのことを知らずに書いているとトータルのテスト時間にはかなりの差ができます。
私が直近で対応したRailsアプリもこれを直すだけで数分短縮できました。
機械的に直すことができるので、もし時間が取れれば見直してみてくださいmm

自動テストは結構パフォーマンスが無視されがちだと思いますが、きちんとログをみてN+1などを検知しないとダメだなと思いました。