Findyでエンジニアをしている松村（@shakemurasan）です。
以前、弊社の栁沢が「RailsのCIのテスト実行時間を10分から5分に高速化した話」という記事を投稿しました。
本記事ではその少し前のお話、そもそもRSpecの実行時間自体にまだまだあった伸びしろ、特にFactory周りの問題をTestProfというgemを活用して解消していった話となります。
- 当時のRSpecの実行時間状況
- TestProfとは
- TestProfでの分析結果
- 改善1. 関連したレコードを複数件作成しているFactoryを１レコードに減らす
- 改善2. テストで必要最小限なレコードのみを作成する
- RSpecの実行時間の改善結果
- 考察
当時のRSpecの実行時間状況
これまでにもテスト実行時間の短縮のための取り組み(CI側でのマシンの並列起動および並列実行)はしており、そこまでストレスのある環境ではありませんでした。異様に実行時間を要しているテストが存在することはメンバー間で認識しており、何となく原因のアタリはついていたものの、並列実行導入で快適な環境が得られていたので、テスト軽量化の優先度が落ちている状況でした。
しかし、じわじわとテスト実行時間は伸びていき、並列実行の導入当初は10分程度だったものが、15分を超えるケースが目立つようになってきました。いよいよテスト軽量化に着手しようかという話になり、実際に対応していくことになったのでした。
更に並列化を推進しようという案もその時点であったのですが、そもそも前述の「異様に実行時間を要しているテスト」が原因でマシンごとのテスト実行完了時間に度し難いバラツキが生じており、まずはここを解決しなければならないよねとなりました。
TestProfとは
テスト軽量化にあたって、まずは何となくアタリをつけていたところに本当に原因があるのか測定することにしました。解析/測定に際し、TestProfが使えそうということは様々な記事、他企業様のテックブログ事例から知っていたので、これを採用することにしました。
TestProfには様々な機能があるのですが、アタリをつけていたのはテストデータ生成周りだったため、FactoryProfというFactory周りの解析機能を使っています。FactoryProfを用いることで、Factory別の 総呼び出し回数 / 総実行時間 / 1回あたりの実行時間 あたりをレポーティングでき、この機能を用いて改善に着手しました。
※ この後の章で登場するファイル名、Model、Factoryは仮名に置き換えていますが、数値は実際のものを掲載しています
TestProfでの分析結果
まず大前提、時間がかかっているテストケースの状況を見てみます。
| spec | Before | After | Reduce |
|---|---|---|---|
| Worst1 | 78.37s | ??? | ??? |
| Worst2 | 75.71s | ??? | ??? |
| Worst3 | 48.76s | ??? | ??? |
| Worst4 | 48.16s | ??? | ??? |
| Worst5 | 88.01s | ??? | ??? |
| Total of worst | 339.01s | ??? | ??? |
実にテストケース5本で5分39秒を越えている状況で、これはちょっと辛いな.... というのがわかります。ここから、一番重たいテストケースのみを指定してFactoryProfの解析をかけてみます。
FPROF=1 bin/rspec spec/models/worst_spec.rb:2244
すると次のようなレポートが得られます。
[TEST PROF INFO] Factories usage
Total: 1586
Total top-level: 8
Total time: 01:32.432 (out of 01:59.446)
Total uniq factories: 12
total top-level total time time per call top-level time name
309 0 80.7570s 0.2613s 0.0000s full_item
103 0 0.8972s 0.0087s 0.0000s shop_user
103 0 90.3245s 0.8769s 0.0000s item_like
103 0 88.4511s 0.8587s 0.0000s shop
...
...
...
この結果を見ると、item_like shop が呼び出し回数と1回あたりの実行時間あたりが1s弱と長いことがわかります。ここから段階的に改善の手を打っていきます。
改善1. 関連したレコードを複数件作成しているFactoryを１レコードに減らす
そこで実際のコードを読んでFactory間の依存関係を見てみると次のような状況でした。
item_like -- create --> shop ┬-- create --> full_item
├-- create --> full_item
└-- create --> full_item
テストの要件は割愛させていただくのですが、テストを実行するうえで full_item は3件も必要なく、最低1件はshopにぶら下がっていれば十分という状況でした。 item_like というのはここ以外でも結構色々なところで使われているFactoryで、ほとんどのテストは最低1件のshopがぶら下がっていれば問題ない状況でした。
そこで、item_like のFactoryを修正して full_item を1件だけに限定して再解析したところ、次のような結果が得られました。
[TEST PROF INFO] Factories usage
Total: 659
Total top-level: 8
Total time: 00:36.813 (out of 01:14.075)
Total uniq factories: 11
total top-level total time time per call top-level time name
103 0 32.7865s 0.3183s 0.0000s shop
103 0 27.1212s 0.2633s 0.0000s full_item
103 0 0.8971s 0.0087s 0.0000s shop_user
103 0 34.5748s 0.3357s 0.0000s item_like
...
...
...
単純に full_item の生成回数が1/3に減り、それに比例して実行時間も約1/3に圧縮できました。
改善2. テストで必要最小限なレコードのみを作成する
別の重たいテストも解析していくと、共通して同じ問題が見えてきます。
[TEST PROF INFO] Factories usage
Total: 3157
Total top-level: 582
Total time: 02:05.161 (out of 04:30.214)
Total uniq factories: 48
total top-level total time time per call top-level time name
322 6 6.2221s 0.0193s 0.1149s user_profile
276 70 74.0465s 0.2683s 5.2776s shop
230 0 63.5779s 0.2764s 0.0000s full_item
...
...
...
次に着目したのは、full_item の実行時間の長さです。1回あたり 0.2764s ということでそんなに長く感じないかもしれませんが、呼び出し回数が非常に多く、塵も積もればこのテストでは230回呼ばれて 63.5779s は無視できない実行時間になっています。
またまたコードを読んでみると、full_item は関連するデータを全部盛りで作る.... というFactoryになっていました。item というモデル自体、システムの中でコアなドメインのモデルとなっており、非常に多くの関連を持ちうるものなのでした。しかし、大部分のテストにおいてはそこまで完全な状態の item は要らないという状況でした。
そこで、shop 生成時のデフォルトは full_item ではなく item というスリムなFactoryを使うように切り替え、再度解析をしてみることにしました。
[TEST PROF INFO] Factories usage
Total: 2697
Total top-level: 582
Total time: 01:06.857 (out of 02:53.458)
Total uniq factories: 47
total top-level total time time per call top-level time name
322 6 4.7178s 0.0147s 0.0844s user_profile
276 70 29.5793s 0.1072s 4.0465s shop
230 0 10.8307s 0.0471s 0.0000s item
結果、1回あたり 0.2764s かかっていた full_item から、0.0471s で済む item に取り変わったことで、このテストの実行時間は半分にまで圧縮できるようになりました。
RSpecの実行時間の改善結果
他にもTestProfを用いて細かな改善は入れていき、最終的にワースト5のテスト実行時間は次のように変化しました。
| spec | Before | After | Reduce | Reduce Rate |
|---|---|---|---|---|
| Worst1 | 78.37s | 17.55s | -60.82s | -77.6% |
| Worst2 | 75.71s | 15.73s | -59.97s | -79.22% |
| Worst3 | 48.76s | 8.28s | -40.48s | -83.01% |
| Worst4 | 48.16s | 7.84s | -40.31s | -83.72% |
| Worst5 | 88.01s | 18.1s | -69.9s | -79.43% |
| Total of worst | 339.01s | 67.5s | -271.51s | -80.08% |
339.01s から 67.5s に圧縮され、この最悪値だったテスト5本に限定して言うと、実行時間を8割以上削減できました。さらに上記のテスト以外でも今回改善したFactoryは使われているわけですから、テストの総実行時間にも効いてくるわけです。
考察
今回、TestProfを用いて、何となく重たいんだろうと思っていたところが想定以上に無駄なことをしていたことがわかりました。
「とりあえずデフォルトで全部入りのテストデータ作っておくか！」というのは、ともすればやりがちですし、歴史の長いコードベースだと気づきにくいように感じました。
「推測するな、計測せよ」という言葉がありますが、実際に計測して打ち手をピンポイントに打っていくことで、着実に改善している感覚を得られて周囲にも説明しやすかったのも学びです。
また、今回Factoryの挙動を大胆に変更することで実行時間削減を実現していますが、これは常日頃みんながテストコードをかなり手厚く書いていてくれたおかげというのが大きいです。システムが壊れないことを担保するため、不安と戦うために我々はテストを書くわけですが、テスト自体のリファクタリングにもテストコードが有効であるということは学びになりました。
ファインディは積極的にエンジニアを採用しています。CI/CDを始め、Four Keys、開発生産性、技術トレンド、転職市場など興味のある方は、お気軽にカジュアル面談を受けてみてください :)
ファインディの採用情報はこちら↓
