Help us understand the problem. What is going on with this article?

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などを検知しないとダメだなと思いました。

Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
No comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
ユーザーは見つかりませんでした