このエントリは、SmartHR Advent Calendar 2023 シリーズ1の5日目の記事です。
こんにちは！SmartHRでプロダクトエンジニアをしている大澤(@qwyngg)です。
最近Railsの自動テストの高速化について調べていたので、その内容をまとめてみました。
主にtest_profというgemを用いた解析と、その結果を元にした改善方法について書いています。
test_profとは
https://github.com/test-prof/test-prof
テストのパフォーマンスを分析する様々なツールを提供するgemです。
色々機能があるのですが、今回は以下の機能を使って発見した問題とその解決方法を紹介します。
- factory_botプロファイラ
- テストに対してstackprofを(面倒な設定無しで）実行できる
詳しい使い方はTestProf: Ruby tests profiling and optimization toolboxを参照してください。
factory_botプロファイラの使用例
factory_botの利用状況を出力してくれる機能です。 以下のようにfactory_botの利用状況を出力してくれます。
## 実際に従業員factoryを1回createした時のプロファイリング結果。nameは省いています。
Total: 10
Total top-level: 5
Total time: 00:00.920 (out of 00:05.601)
Total uniq factories: 8
total top-level total time time per call top-level time
3 0 0.0423s 0.0141s 0.0000s
1 1 0.0174s 0.0174s 0.0174s
1 1 0.0148s 0.0148s 0.0148s
1 1 0.1395s 0.1395s 0.1395s
1 0 0.0490s 0.0490s 0.0000s
1 1 0.7231s 0.7231s 0.7231s
1 1 0.0258s 0.0258s 0.0258s
1 0 0.0199s 0.0199s 0.0000s
発見した問題
実際のテストのfactory_botの利用状況を調べてみると、従業員factoryを過剰にcreateしているテストがいくつかあることがわかりました。 該当するテストを見てみると以下のようなコードでした。
let(:家族) { FactoryBot.build(:家族) } # 家族factoryは内部で`association :従業員`を呼び出している let(:従業員) { FactoryBot.create(:従業員, 家族s: [家族]) } it '従業員が作成される' do expect(従業員).to be_persisted end
一見問題なさそうですが、家族factory内部で従業員をcreateしてしまい、従業員が2回作成されていました。
total top-level total time time per call top-level time name
3 0 0.0407s 0.0136s 0.0000s
2 1 0.0584s 0.0292s 0.0091s
2 2 1.0599s 0.5299s 1.0599s 従業員
1 1 0.1309s 0.1309s 0.1309s
1 0 0.0195s 0.0195s 0.0000s
1 1 0.0297s 0.0297s 0.0297s
1 1 0.0196s 0.0196s 0.0196s
1 1 0.0178s 0.0178s 0.0178s
1 1 0.0151s 0.0151s 0.0151s
コード上では1回しかcreateしていないように見えますが、内部では2回createされていることがわかります。
原因を調査したところ、テストコード内でFactoryBot.use_parent_strategy = falseが設定されており、build時もassociation先がcreateされていたのが原因でした。
参考: https://github.com/thoughtbot/factory_bot/blob/master/GETTING_STARTED.md#build-strategies-1
解決方法
今回はassociation先を明示することで問題を解消しました。
let(:家族) { FactoryBot.build(:家族, 従業員: nil) } let(:従業員) { FactoryBot.create(:従業員, 家族s: [家族]) } it '従業員が作成される' do expect(従業員).to be_persisted end
total top-level total time time per call top-level time name
3 0 0.0432s 0.0144s 0.0000s
2 1 0.0737s 0.0369s 0.0236s
1 1 0.0146s 0.0146s 0.0146s
1 1 0.1439s 0.1439s 0.1439s
1 1 0.0214s 0.0214s 0.0214s
1 1 0.7370s 0.7370s 0.7370s 従業員
1 1 0.0286s 0.0286s 0.0286s
1 0 0.0192s 0.0192s 0.0000s
1 1 0.0185s 0.0185s 0.0185s
実際に従業員のcreate回数が減っているのがわかります。冒頭の出力例でも紹介しましたが、従業員factoryを一回createするだけも1秒近くかかるので、削減するとチリツモで効果があります。
今回はassociationを明示することで解決しましたが、Gemを使ったりFixtureを使ったり解決方法は色々あります。
factory内部でfactoryをcreateしてしまう問題はTestProf（2） Rubyテストの遅いfactoryを診断治療する（翻訳）｜TechRacho by BPS株式会社という素晴らしい記事で色々な解決方法が紹介されていますので、参考にしてみてください。
テストに対してstackprofを実行
テストに対して面倒な設定なしにstackprofをいい感じに実行できるようになる機能です。
発見した問題
早速実行時間の長いsystem specに対してstackprofを実行してみました。
has_content?でした。
def signin_by(user) signin(user.email, user.password) # ログイン完了を待つ page.has_content?(:all, 'ログインしました') end
画面遷移を確実にするための処理ですが、これが原因でテストが遅くなっていました。
SmartHRではログイン完了時点でのフラッシュメッセージはいくつか存在しており、「ログインしました」だけでは網羅できていませんでした。has_content?はタイムアウトするまで要素が存在するかどうかを確認するため「ログインしました」が存在しない場合はタイムアウトまで待つことになります。
signin_byヘルパーはsystem spec各所で使用されているため、タイムアウトまで待つ処理が大量にありました。
解決方法
cssのセレクタを使ってフラッシュメッセージの存在を確認するように変更しました。
def signin_by(user) signin(user.email, user.password) # ログイン完了を待つ page.has_css?('.alert-success') end
これにより今までタイムアウトまで待機していた処理がなくなり、テストの実行時間が大幅に短縮されました。(6分→2分になったテストもありました） ただ、この方法もフラッシュメッセージに依存した実装ですので、より良い方法があるかもしれません。
まとめ
test_profを使うことで、テストの実行時間が長い原因を特定し、改善することができます。
今回挙げた２つの問題はどちらもコード上では問題なさそうなコードでしたが、実際にプロファイリングを行うことで問題を発見することができました。
もし妙に遅いテストがある場合は、test_profを使って色々調べてみると良いかもしれません。遅い原因は意外なところに隠されているかも...。
最後に、この素晴らしいGemをメンテナンスしてくださっている方々ありがとうございます！本当に助かっています！
We Are Hiring!
SmartHR では一緒に SmartHR を作りあげていく仲間を募集中です！ 計測してプロダクトを改善していきたい方、カジュアル面談でざっくばらんにお話ししましょう！
