Qiita Teams that are logged in
You are not logged in to any team

Log in to Qiita Team
Community
OrganizationAdvent CalendarQiitadon (β)
Service
Qiita JobsQiita ZineQiita Blog
2
Help us understand the problem. What is going on with this article?
@ham0215

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

More than 1 year has passed since last update.

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

2
Help us understand the problem. What is going on with this article?
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
ham0215
Webエンジニアやってます。仕事では主にバックエンド開発をRailsで行っています。仕事で使う機会は少ないですが、フロント開発ではReact、Typescriptを使っています。
vis-its
独自技術ideagramを用いて、人々の「創造性」や「目利き力」の定量化を行い、イノベーター人材の発掘/育成、科学的イノベーション創発支援を行っています。

Comments

No comments
Sign up for free and join this conversation.
Sign Up
If you already have a Qiita account Login
2
Help us understand the problem. What is going on with this article?