参考: TestProfのリポジトリにある図
test-prof/test-profより
TestProf: Ruby/Railsの遅いテストを診断するツール（翻訳）
はじめに
テストを書くことは、特にRubyやRailsのコミュニティにおいて開発の重要なプロセスですが、テストの完了に長時間を要するようにならないと、テストスイートのパフォーマンスを気にしない傾向があります。身に覚えがありませんか？
専用のテストプロファイラであるTestProfを用いて、Railsテストのパフォーマンスボトルネックを特定して修正する方法を学びましょう。
原文編集者注
本記事は、TestProfの利用方法の変更を反映するため、2024年半ばに大幅に更新されました。最初の公開からほぼ7年が経過していますが、本記事で扱っている問題やソリューションは現在でも有効です。
私はEvil Martiansに入社した最初の年から、さまざまなタイプのRailsアプリケーション（モノリス、モジュリス（モジュラー+モノリス）、APIのみ、Hotwireなど）に取り組んできました。これらのアプリケーションは、どれもテストスイートの速度面に改善の余地がまだまだ残されていました。
私はテスト高速化のヒントやノウハウを集めるようになり、最終的にそのノウハウをすべてTestProfという名のメタgemに盛り込みました。TestProfはRubyのテストをプロファイリングするツールボックスです。
🔗 開発の動機
テストが遅いと生産性が低下し、貴重な時間が無駄になってしまいます。
「テストスイートのパフォーマンスがそこまで重要な理由って何なの？」とお思いの方もいらっしゃるでしょうから、議論を始める前にいくつかの統計情報をお見せしたいと思います。
2017年の初頭に、Ruby開発者にテストのパフォーマンスに関する簡単な聞き取り調査を行いました。
最初によいお知らせです。Ruby開発者のほとんどすべてがテストを書いています（正直、私は当然だと思っています）。私はRubyコミュニティのこういうところが大好きです。
質問: テストを書いていますか？
調査の結果、テスト実行に10分以上かかっているケースは4分の1程度にとどまりました。かつ、半分近くは5分以内に収まっています。
質問: テストの実行時間は？
状況はそれほど悪くなさそうですね。それでは、exampleが1000件を超えるテストスイートに限定して聞いてみましょう。
質問: テストスイート全体の実行時間は？（exampleが1000以上の場合）
今度はだいぶ残念な結果になりました。テストスイートの約半分は実行に10分以上を要し、ほぼ3割近くが20分以上かかっています。
（なお、私がこれまで経験した典型的なRailsアプリでは、およそ6000件〜10000件のexampleがありました）
もちろん、変更のたびにテストスイート全体を隅から隅まで実行する必要などありません。通常、私が中規模の機能を手がけている場合は、1コミットあたり100件のexampleを実行しており、実行には1分程度しかかかりません。しかしその「1分」といえども私の開発リズムが崩されてしまい（Justin Searlsの講演動画↓をご覧ください）、その間私の貴重な時間が無駄になります。
それでも私たちは、デプロイ時にはすべてのテストをCIサービスで実行しなければなりません。あなたは、ちっぽけな修正のデプロイに数十分（キューに多数のビルドが積まれていれば数時間）待たされても平気ですか？私は大いに疑問です。
それなりのコストはかかりますが、ビルドのコンカレント化で待ち時間を軽減することも可能です。以下のグラフをご覧ください。
質問: CIでのパラレル実行ジョブ数は？
たとえば、私がEvil Martiansで初めて手がけたFountainのテスト最適化プロジェクトでは、パラレル化は5xで、ジョブ1件あたりの平均RSpec実行時間は2分を達成しました（テスト2000件あたりに直すと5分）。つまり、TPM（1分あたりのテスト実行数）は約800件になります。
最適化を行う前は、750件のテスト実行に約5分を要していました（TPMにしてわずか150件）。つまり最適化によって、絶対的な実行速度はビルドあたり3〜4分向上しましたが、相対的な実行速度の改善は著しく、テストは5倍高速になりました。
このおかげで、テスト数の急激な増加にも対応可能になり、CIのフィードバックループに長時間かかる悲しい状況を回避できました。
皆さんは、ビルドのたびに30分待たされるのに耐えられますか？数時間待たされるとしたらどうですか？私はそういうプロジェクトをいくつも見たことがあります。
まとめると、遅いテストはあなたの貴重な時間を奪い、生産性が低下します。ありがたいことに、ほとんどの場合、テストの高速化に膨大な時間をかける必要はありません。適切なツールさえあれば大丈夫です。
そういうわけで、TestProfを詳しく見てみましょう。
🔗 ツールボックス
TestProfは、テストスイートのボトルネックを特定して、修正方法を提供するツールです。
TestProfを活用してテストスイートを分析・最適化する方法を解説します。
🔗 一般的なプロファイリング
最も大きな改善は、利用頻度が最も高い機能（メソッドやパターンなど）を最適化することで得られるのが普通です。頻繁に使われる容疑者を見つけるには、テストファイル自体を調べるのではなく、まずはテストスイートに関する高レベルの情報を収集しましょう。
試しに、テストスイートについて以下の質問に答えてみてください。
- テストスイートのどこで時間を食っているか: コントローラか、モデルか、サービスか、ジョブか？
- 最も時間のかかっているモジュールやメソッドはどれか
答えを考えるのも楽ではありませんね。TestProfはこうしたゲームをスキップして、代わりに答えを見つけてくれます。
質問1の答えが知りたい場合は、TestProfのTag Profilerを使います。これはRSpecの特定のタグ値でグループ化された統計情報を収集してくれます。RSpecはexampleにtypeタグを自動で追加するので、以下のように使えます。
$ TAG_PROF=type rspec
[TEST PROF INFO] TagProf report for type
type time total %total %time avg
controller 08:02.721 2822 39.04 34.29 00:00.171
service 05:56.686 1363 18.86 25.34 00:00.261
model 04:26.176 1711 23.67 18.91 00:00.155
job 01:58.766 327 4.52 8.44 00:00.363
request 01:06.716 227 3.14 4.74 00:00.293
form 00:37.212 218 3.02 2.64 00:00.170
query 00:19.186 75 1.04 1.36 00:00.255
facade 00:18.415 95 1.31 1.31 00:00.193
serializer 00:10.201 19 0.26 0.72 00:00.536
policy 00:06.023 65 0.90 0.43 00:00.092
presenter 00:05.593 42 0.58 0.40 00:00.133
mailer 00:04.974 41 0.57 0.35 00:00.121
...
つまり、テストのボトルネックを探すときに、最も時間のかかるテスト種別に集中できるので、それ以外のものを無視できるということです。結局のところ、テストスイート全体の実行時間にさほど影響しないテスト種別を最適化しても、あまり効果がありません。
さて、最もメモリ消費量の大きいメソッドはどうやって知ることができるでしょうか？ここでは、RubyProfやStackProf、あるいは新しいVernierなどの既存のRubyプロファイラを使うことも、汎用のRubyプロファイラを使うことも可能です。
TestProfを使えば、テストスイートに対して無設定のまま検査を実行できます。以下のように、調べたい項目に対応する環境変数を指定して実行し、出力された指示に従って最適化を進めればよいのです。
$ TEST_RUBY_PROF=1 bundle exec rake test
...
[TEST PROF INFO] StackProf report generated: tmp/test_prof/stack-prof-report-wall-raw-boot.dump
[TEST PROF INFO] StackProf JSON report generated: tmp/test_prof/stack-prof-report-wall-raw-boot.json
StackProfを使う場合は、2通りのフォーマットでレポートを出力しています。*.dumpファイルはstackprof CLIで利用可能なフォーマット、*.jsonファイルはSpeedscopeでフレームグラフ形式の分析に利用できます。
TestProfの各種プロファイラが生成するレポートを使って、最も利用頻度の高いスタックパスを特定すれば、質問2.にも答えられるようになります。
残念ながら、この種のプロファイリングはリソース消費が大きく、ただでさえ遅いテストスイートの実行がますます遅くなるので、テストのごく一部に狙いを絞り込んでプロファイルを実行する必要があります。しかしどうやって絞り込めばよいのでしょうか。実は、ランダムに絞り込めるのです。
TestProfには特殊なパッチが同梱されており、RSpecのexampleグループ（またはMinitestのスイート）をランダムに選んで実行できます。
SAMPLE=10 bundle exec rspec
たとえば、Stackprofのプロファイルに以下のようなコンテンツが含まれているとします。
%self calls name
20.85 721 <Class::BCrypt::Engine>#__bc_crypt
2.31 4690 *ActiveSupport::Notifications::Instrumenter#instrument
1.12 47489 Arel::Visitors::Visitor#dispatch
1.04 205208 String#to_s
0.87 531377 Module#===
0.87 117109 *Class#new
私達が認証ライブラリとして使っているSorceryの暗号化設定は、実行環境にかかわらず同じであることがわかりました。つまり、test環境でもproduction環境と同じ暗号強度になっているということです。
しかしtest環境の暗号化をそこまで真剣に考える必要はあるでしょうか。私たちがSorceryに投げた修正プルリク（#81）はたった1行ですが、これだけでパフォーマンスが20%向上しました。
汎用のプロファイラレポートには、Active Recordのさまざまな対話操作（ActiveRecord::PostgreSQLAdapter#exec_no_cacheなど）が多数含まれているのが普通です。
続いて、テストでデータベースがどのように使われているかを深掘りしてみましょう。
🔗 データベースとのやりとり
テストスイートの実行時間にデータベースが占める割合がどのぐらいあるかを把握していますか？繰り返しますが、あてずっぽうはやめてTestProfで測定しましょう。
RailsのInstrumentation（ActiveSupportのNotification/Instrumentation機能）については既に別記事で詳しく説明したので、基本的な概要は省略してEventProfilerを紹介します。
EventProfは、テストスイート実行中にinstrumentationメトリクスを収集し、遅いグループの上位N個のランキングや、特定のメトリクスに関連するexampleについての一般的な情報をレポートします。
現時点では、ActiveSupport::Notificationsのみ無設定で利用できますが、カスタムinstrumentationと手軽に統合できます。
データベース利用量の情報を取得するには、sql.active_recordイベントを使います。この場合のレポートは次のようになります（rspec --profileの出力と非常に似ています）。
$ EVENT_PROF=sql.active_record rspec
[TEST PROF INFO] EventProf results for sql.active_record
Total time: 00:05.045 00:24.512 (21.00%)
Total events: 6322
Top 5 slowest suites (by time):
MessagesController (./spec/controllers/messages_controller_spec.rb:3) – 00:03.253 (4058 / 100)
UsersController (./spec/controllers/users_controller_spec.rb:3) – 00:01.508 (1574 / 58)
Confirm (./spec/services/confirm_spec.rb:3) – 00:01.255 (1530 / 8)
RequestJob (./spec/jobs/request_job_spec.rb:3) – 00:00.311 (437 / 3)
ApplyForm (./spec/forms/apply_form_spec.rb:3) – 00:00.118 (153 / 5)
検討中のプロジェクトでは、データベースクエリが総時間に占める割合はおよそ20%です。この数字をどのように読み取ればよいでしょうか。
この測定値には、あらゆるプロジェクトで使えるような単一の最適な値というものはありません。この値はテストのスタイルによって大きく変わるものであり、単体テストと統合テストのどちらを多く書いたかによって異なります。ただし、私たちの経験ではsql.active_recordは10〜15%あたりになるのが普通なので、20%という値は疑わしく思えます。
データベースがテスト時間に占める割合が高い典型的な理由とは何でしょうか。すべての理由を列挙するのはさすがに無理ですが、一部をリストアップしてみました。
- 1: データの永続化に意味がない
- 2: テストのセットアップが重すぎる
- 3: ファクトリーのカスケード
項目1は、有名な「User.new vs User.create問題」（またはFactoryBotの「build_stubbed vs create問題」）です。おそらくモデルの単体テストでデータベースにアクセスする必要はないはずなので、データベースにはアクセスしない方がよいでしょう。
しかし既にテストコードでデータベースにアクセスしているとしたらどうでしょう。テストで永続化が不要かどうかをどうやって突き止めればよいでしょうか。そこでFactory Doctorの登場です。
Factory Doctorは、不要なデータ作成がいつ行われたかを通知してくれます。
$ FDOC=1 rspec
[TEST PROF INFO] FactoryDoctor report
Total (potentially) bad examples: 2
Total wasted time: 00:13.165
User (./spec/models/user_spec.rb:3)
validates name (./spec/user_spec.rb:8)–1 record created, 00:00.114
validates email (./spec/user_spec.rb:8)–2 records created, 00:00.514
Factory Doctorは残念ながら万能の魔法使いではありません（まだ学習中です）ので、偽陽性や偽陰性が生じることもあります。いずれにしろ、実際に動かしながら試し、データ生成戦略を軽量なものに差し替えるとテスト時間が短くなるかどうかを確認することをおすすめします。
第2の「テストのセットアップが重すぎる」問題は、少し複雑です。次の例を考えてみましょう。
describe BeatleSearchQuery do
# この検索機能をテストしたいので
# exampleごとに何らかのデータが必要
let!(:paul) { create(:beatle, name: 'Paul') }
let!(:ringo) { create(:beatle, name: 'Ringo') }
let!(:george) { create(:beatle, name: 'George') }
let!(:john) { create(:beatle, name: 'John') }
# この後15件ほどexampleが続く
end
「そんなのfixtureにすればいいじゃない」とお思いかもしれません。数十個ものモデルが毎日変更されるようなかなり大きなプロジェクトでもない限り、fixtureにするのがよいでしょう。
もうひとつの方法は、before(:all)フックでデータを1度だけ生成することです。しかしこの方法には1つ注意点があります。before(:all)はトランザクションの外で実行されるので、データベースを手動でクリーンアップしなければならなくなります。
あるいは、グループ全体を1つのトランザクションに手動で閉じ込める方法も考えられます。TestProfのbefore_allヘルパーはまさにこれを行っているのです。
describe BeatleSearchQuery do
before_all do
@paul = create(:beatle, name: 'Paul')
@ringo = create(:beatle, name: 'Ringo')
@george = create(:beatle, name: 'George')
@john = create(:beatle, name: 'John')
end
# この後15件ほどexampleが続く
end
コンテキストを別のグループ（ファイル）間でも共有したい場合は、Any Fixtureを検討してください。これを使うことで、（ファクトリーを使って）コードからフィクスチャを生成できるようになります。
🔗 ファクトリーのカスケード問題
ファクトリーのカスケード問題は実にありがちなのですが、めったに対処されていないので、テストスイート全体が遅くなる可能性があります。要するに、ファクトリー呼び出しのネストによって大量のデータが生成されるという、制御不能なプロセスなのです、TestProfはこれに対処する方法を理解しており、それ専用の記事もありますので、ぜひお読みください↓。
🔗 バックグラウンドジョブ
TestProfを使うと、テストを手動で操作しなくても、テストをリファクタリングして速度を向上させるときに役立ちます。これを説明するために、Railsアプリケーションのテストによくある別のボトルネックを見ていくことにしましょう。
テストでよく行われるのが、バックグラウンドジョブをインライン化する（Sidekiq::Testing.inline!など）という手法です。
通常、重たい処理はバックグランドに回すので、すべてのジョブを無条件に実行すると実行時間が長くなります。
TestProfは、バックグラウンドに要した時間のプロファイリングもサポートしています。Sidekiqでは、以下のように特殊なsidekiq.inlineを指定できます。
$ EVENT_PROF=sidekiq.inline bundle exec rspec spec/requests
[TEST PROF INFO] EventProf results for sidekiq.inline
Total time: 00:03.515 00:14.512 (24.00%)
Total events: 851
...
これで無駄になっている時間を正確に把握したら、次はどうすればよいでしょうか。単にインラインモードをオフにすると、多くのテストが動かなくなるかもしれません（多すぎてすぐには修正しきれないほどです）。
解決方法は、インラインをグローバルにオフにし、必要な場合のみオンにすることです。RSpecを使っている場合は以下の操作を実行できます。
RSpec.configure do |config
config.before(:each) do |ex|
if ex.metadata[:sidekiq] == :inline
Sidekiq::Testing.inline!
else
Sidekiq::Testing.fake!
end
end
end
# タグを用いてインラインモードを有効にする
it "do some bg", sidekiq: :inline do
# ...
end
失敗したexampleのひとつひとつにタグを付けて回らなければならないのでしょうか？TestProfを使っていればその必要はありません。
ツールボックスにはRSpec Stampという特殊なツールが含まれており、特定のタグを自動で追加してくれます。
$ RSTAMP=sidekiq:inline bundle exec rspec
...
Total patches: 62
Total files: 30
RSpec Stampの内部では、ソースファイルをパースしてタグを正しく挿入するためにRipperというパーサーを用いています。inline!をfake!に移行する方法について詳しくはRSpec Stampのガイドをご覧ください。
TestProfはGitHubとrubygems.orgで公開されており、いつでもアプリに導入してテストスイートのパフォーマンス向上に役立てられます。詳しくは以下のドキュメントをどうぞ。
参考: TestProf: Ruby tests profiling and optimization toolbox
なお、本記事はTestProfの紹介記事であり、すべての機能を網羅しているわけではありません。本シリーズのパート2である以下の記事を続けてお読みいただくことで、テストを高速化してTDDのフィードバックループを短縮し、今よりも幸せなRuby開発者になれるTestProfについてさらに詳しく学べます。
概要
元サイトの許諾を得て翻訳・公開いたします。