遅いRSpecのコードを改善したときのお話

初めに

Jenkinsサーバがやけに不安定で、高負荷の影響により503エラーが発生していました。これはまずいということで、原因を調べていたところ、めちゃくちゃ重いRSpecのコードを発見。これを改善したときのお話をここに書きます。

環境設定

• OS: Windows10 Pro 64bit
  • Version: 1909
  • OS build: 18363.1256
• WLS
  • Ubuntu 20.04
• Ruby 2.7.2
• Rails 6.0.3.3

問題があるテストコードの特定

ローカルですべてのテストコード実行するのも時間かかるので、Jenkins上で実行しているテストコードの単位を分割して、様子見てみます。

JobScript

# ディレクトリごとに分割して、実行 --profile オプションで遅いテストケースを20個ほど表示
bundle exec rspec --profile 20 spec/controllers/*
bundle exec rspec --profile 20 spec/decorators/*
bundle exec rspec --profile 20 spec/helpers/*
bundle exec rspec --profile 20 spec/models/*
bundle exec rspec --profile 20 spec/mailers/*
bundle exec rspec --profile 20 spec/models/*
bundle exec rspec --profile 20 spec/services/*

ある程度目星がついたら、コメントアウトで特定のコードを除外して実行し、安定して動くかどうかを確認。
どうもcontrollers周りのテストコード2ファイルが怪しいことが判明しました。
(今考えるとTestProfの機能使ってたら、もっと楽でしたね。TestProfに関しては後述します)

遅くなっている原因の究明

早速、問題のControllerの内容を確認... shared_contextやshared_examples が大量にあって見づらい...
1,2行程度のletがshared_context化されてたり、全く利用していないものも定義されてて無駄が多い。ヤバそう。

コードから読み解く前に、別の方法を検討したところ下記の記事を見つけました。

• TestProf: Ruby/Railsの遅いテストを診断するgem（翻訳）｜TechRacho（テックラッチョ）
• TestProf（2） Rubyテストの遅いfactoryを診断治療する（翻訳）｜TechRacho（テックラッチョ）

これと公式ドキュメントを参考にしつつ該当のテストコードを分析していきます。

TestProfのインストール

Gemfile

group :test do
  gem "test-prof", "~> 1.0"
end

console

$ bundle install

各種プロファイルの実行

ここからは参考記事のプロファイラを試しに動かしてみます。
ただ、対象のテストコードはめちゃくちゃ重いので、軽いケースだけ少し残してほとんどコメントアウトしておきます。

console

$ EVENT_PROF="factory.create" bundle exec rspec spec/controllers/xxx_controller_spec.rb
[TEST PROF INFO] EventProf results for factory.create

Total time: 03:09.624 of 03:10.254 (99.67%)
Total events: 300

[以下略]

私が携わっているコードベースの中には、factoryからのレコード生成にテスト時間の80%を費やしているものすらあったのです。ここでいったん気持ちを静めましょう。

TestProf（2） Rubyテストの遅いfactoryを診断治療する（翻訳）｜TechRacho（テックラッチョ）
80%どころか、99%なんて数字出てきましたね。factoryで作成されているDBのレコード数に問題がありそうです。次のコマンドで、factoryの全リストと利用統計情報を見てみます。

console

$ FPROF=1 bundle exec rspec spec/controllers/xxx_controller_spec.rb
Finished in 3 minutes 15.6 seconds (files took 18.98 seconds to load)
42 examples, 0 failures
[TEST PROF INFO] Factories usage

 Total: 22358
 Total top-level: 300
 Total time: 03:13.369 (out of 03:19.027)
 Total uniq factories: 23
[以下略]

「オイオイオイ」「死ぬわコイツ」「ほうfactoryカスケードですか...」
まさかの2万2千件。原因は元記事にも書いてありますが、factoryカスケードと呼ばれるものです。factory1つ作るとき、関連するfactoryも作成する設定になっていると連鎖的に作成されてしまうというものです。

対処

テストコードの内容を把握しないとだめなので、テストコード読みつつリファクタリングを実施。
問題となった2つのテストコードが両方とも2000行程度ですが、テストケースそのままで両方とも500行ほど削減できました

不要なテストデータの削除

見たところfactoryのtraitで定義されているところにassociationを作成する設定がありました。ただ、このassociationは今回のテストコードのテストケースに必要ないので削除します。

テストコード修正イメージ

# before trait :mail_send_settings によってassociationが作成
let(:user) { create(:user, :mail_send_settings) }

# after 不要なtraitの削除
let(:user) { create(:user) }

不要な関連付けの排除

元の記事通りに、factoryから元の関連排除できれば良いんですが他のテストコードでも利用されています。削除した影響で他のテストコードに影響が出たら元も子もないので、設定を上書きする方向でいきます。

テストコード修正イメージ

# before company側の設定でuserが複数作成される
let(:company) { create(:company, company_name: 'hoge') }
let(:user)    { company.users.first }

# after 予めuserを1つ作っておき、companyはそれを利用するよう上書き
let(:user)    { create(:user, user_name: 'test_user') }
let(:company) { create(:company, company_name: 'hoge', users: [user]) }

テストケースを1つにまとめる

テストケースのブロックごとにテストケースの作成、初期化が行われれるので、ブロックが増えるほど作成レコード数は増えます。まとめてテストできるものに関しては、1つのブロック内でテストして、作成されるレコード数を減らします。

テストコード修正イメージ

# before
it { expect(response).to render_template(:new) }
it { expect(response).to have_http_status(:ok) }
it { expect(response.body).to include(user.user_name) }

# after
it 'return http success' do
  expect(response).to render_template(:index) 
  expect(response).to have_http_status(:ok)
  expect(response.body).to include(user.user_name)
end

結果

不要なデータを削除したあとの結果がこれです。このデータ自体は以前と異なり、問題になっていた1ファイルすべてのテストケースを実行してます。

console

$ FPROF=1 bundle exec rspec spec/controllers/xxx_controller_spec.rb
Finished in 1 minute 46.19 seconds (files took 39.82 seconds to load)
130 examples, 0 failures
[TEST PROF INFO] Factories usage

 Total: 12717
 Total top-level: 1637
 Total time: 01:39.500 (out of 01:52.619)
 Total uniq factories: 24
[以下略]

最初(軽いケースのみ抽出して3分15秒/Total: 22358)に比べれば改善されましたね。古いテストコードは全部実行したわけではないのですが、15~20分位は掛かりそうな雰囲気だったので1/10以下位になってるかもしれません。問題になっていたもう一つのテストコードの状況も似たような感じですね。ただ、Totalの数まだ結構あるので、改善の余地はありそうです。

まとめ

まだまだ、改善できそうですが遅いRSpecのコードの改善ができました！
Railsは死んだとかよくディスられているんですが、テストコード周りのエコシステムが便利すぎるんですよね。テストコード以外にも、Githubのstar数が結構ある便利なOSSライブラリがあるのが魅力ですね。