TestProfでボトルネックになっているRSpecのテストケースを改善した
今関わっているプロジェクトがRailsで開発していてRSpecでテストも書かれているのですが、テストの実行時間がネック（ローカルで10分台）になっているのでTestProfを導入しました。
今回はサクッと改善できるところを対応して実行時間を4分短縮（ローカル実行時）できたのでその方法を書き残せればと思います。
（調査すると、共通のクラスでFactoryの生成処理をしている箇所がボトルネックの1つになっていました。そこに手を入れてテストケースごとに最適なテストデータを作成するのは時間がかかるしハードになりそうだったので、実行時間を短くしたいという目先のところを対応するために上記の対応をしました）
進め方は、TestProfのPlaybookを参考にしています。
https://test-prof.evilmartians.io/playbook
TestProf導入
Gemfileのgroup :testの部分にTestProfを追加してbundle install。
group :test do
gem "test-prof", "~> 1.0"
end
spec/rails_helper.rbに以下を追加。
require "test_prof/recipes/rspec/before_all"
require "test_prof/recipes/rspec/let_it_be"
TestProfでボトルネックなどを調査・分析する際に、specのタイプで分類すると進めやすいです。
specディレクトリ配下に独自でディレクトリを追加していたので、以下の記事を参考に独自ディレクトリもグルーピングできるようにしました。
{
lib: 'lib',
services: 'services',
batch: 'batch'
}.each do |key, value|
RSpec::Rails::DIRECTORY_MAPPINGS[key] = %W(spec #{value})
end
これで例えば、spec/lib/配下のテストは、直接記述しなくてもtype: :libと認識されるようになります。
タグのタイプを軸に全体のレポートを出してみる
まずは全体がどうなっているのかを把握するために、レポートを出します。
TAG_PROF=type TAG_PROF_FORMAT=html TAG_PROF_EVENT=sql.active_record,factory.create bundle exec rspec
このコマンドは以下の時間を計測してくれます。
- テスト時間
- factoryの作成にかかった時間
- sqlの実行にかかった時間
コマンドを実行するとtmp/test_prof内にレポートが作成される。
全体感を把握したらタイプごとにボトルネックを抽出して対応を進めます
※ 今回は主にfactory.createの時間短縮をしています。
テスト時間のボトルネック抽出
以下のコマンドでタグタイプ内のテストのなかで、factory.createで時間がかかっているテストを洗いだしてくれます。
EVENT_PROF=factory.create rspec --tag type:hoge
結果は以下です。
[TEST PROF INFO] EventProf results for factory.create
Total time: 04:37.129 of 05:48.934 (79.42%)
Total events: 33966
Top 5 slowest suites (by time):
xxx::xxx (./spec/hoge/xxx_spec.rb:1) – 00:30.708 (918 / 25) of 00:31.795 (96.58%)
xxx::xxx (./spec/hoge/xxx_spec.rb:1) – 00:24.680 (6141 / 42) of 00:27.399 (90.08%)
xxx::xxx (./spec/hoge/xxx_spec.rb:1) – 00:21.377 (217 / 25) of 00:31.819 (67.18%)
xxx::xxx (./spec/hoge/xxx_spec.rb:1) of 00:19.129 (94.79%)
xxx::xxx (./spec/hoge/xxx_spec.rb:1) of 00:17.163 (99.38%)
時間の見方は以下です。
factory crateにかかったいる時間 of テスト実行時間 （実行時間の中でどれだけfactory createの時間が占めているか）
これを見てみると、factory createがめっちゃ時間かかっていることがわかります。
ここから1ファイルずつ対応していきます。
ボトルネックの解消
ボトルネックのファイルがわかったところで、次はそのファイル内でどのfactory作成で時間をかかっているか見ていきます。
以下のコマンドを実行。
FPROF=1 rspec ./spec/hoge/xxx_spec.rb
そうすると、どのFactoryを使っていて、何回作成されて、どれだけ時間がかかっているかがわかります。
[TEST PROF INFO] Factories usage
Total: 266
Total top-level: 229
Total time: 00:12.515 (out of 00:16.256)
Total uniq factories: 3
total top-level total time time per call top-level time name
155 155 2.3684s 0.0153s 2.3684s xxxx
74 37 1.7384s 0.0235s 0.5194s yyyy
37 37 9.6272s 0.2602s 9.6272s zzzz
これを解消していくわけですが、基本的には以下の書き換えをするだけで時間が大幅に短縮することが多いです。
let => let_it_be
before => before_all
https://test-prof.evilmartians.io/recipes/before_all
https://test-prof.evilmartians.io/recipes/let_it_be
letやbeforeはテストケースごとに実行されるのでそれで時間がかかっています。
それをlet_it_beやbefore_allに書き換えると、specファイルを実行するときに1度だけ実行するようになりで無駄な実行を防ぐことができます。
※ もちろん、コード内容にもよるのでこの書き換えをするとテストが落ちるパターンも出てくるので、書き換えないor書き換えてテストコードを調整するなどの判断をする必要があります。
おわりに
この対応だけでも、4分時間を短縮できたのでとてもよい結果になりました。
Github ActionsなどのCI/CDで実行する際には、マシンスペックや並列実行なども考慮にいれれば、テスト実行待ちの時間が少なくなるので開発体験は上がると感じました。
今回は簡単な対応を行ないましたが、Factoryの部分だけでもまだまだ以下のような改善の余地はあったので、これから進めていければと思いました。
- 複数のテストで使っている、共通化されたテストデータをテストごとに最適化
- デフォルトでで全部入りのテストデータをテストごとに最適化
Discussion