概要
原著者の許諾を得て翻訳・公開いたします。
- 英語記事: TestProf: a good doctor for slow Ruby tests
- 公開日: 2017/08/25
- gemリポジトリ: palkan/test-prof
- 著者: Vladimir Dem
- サイト: Evil Martians’ team blog
evilmartians.com/chroniclesより
- 参考: TestProfのリポジトリにある図
palkan/test-profより
TestProf: Ruby/Railsの遅いテストを診断するgem（翻訳）
テストを書くことは、開発における重要なプロセスであり、RubyやRailsのコミュニティには特に当てはまります。私たちはテストでgreenが点灯するまで長時間待たされていることに気づいて、初めてテストスイートのパフォーマンスというものに関心を寄せるようになるものです。
私はテストスイートのパフォーマンスの分析に多くの時間を費やし、テストを高速化するテクニックを編み出すとともにツールを開発しました。そうしたノウハウをすべてTestProfという名のメタgemに盛り込みました。TestProfはRubyのテストをプロファイリングするツールボックスです。
開発の動機
テストが遅いと生産性が低下し、無駄な時間を費やす羽目になる
「テストスイートのパフォーマンスがどうしてそんなに重要なんだろうか？」とお思いの方もいらっしゃるでしょうから、議論を始める前にいくつかの統計情報をお見せしたいと思います。
今年初頭に、Ruby開発者にテストのパフォーマンスに関する簡単な聞き取り調査を行いました。
最初によいお知らせです。Ruby開発者のほとんどすべてがテストを書いています（正直、私は驚きませんが）。私はRubyコミュニティのこういうところが好きです。
調査の結果、テスト実行に10分以上かかっているケースは4分の1程度にとどまりました。かつ、半分近くは5分以内に収まっています。
これなら大きな心配はなさそうです。それでは、exampleが1000を超えるテストスイートに限定して聞いてみましょう。
今度はだいぶ残念な結果になりました。テストスイートの約半分は実行に10分以上を要し、ほぼ3割近くが20分以上かかっています。
ところで、私がこれまで経験した典型的なRailsアプリでは、ざっくり6000件から10000件のexampleがありました。
もちろん、変更のたびにテストスイート全体を実行する必要などありません。通常、私が中規模の機能を手がけている場合はコミットあたり100件のexampleを実行しており、実行には1分程度しかかかりません。しかし1分といえども私のフィードバックループは結構な影響を受けますし（Justin Searlsの動画↓をご覧ください）、その間私の貴重な時間は無駄になります。
それでも私たちは、デプロイサイクル中にCIサービスですべてのテストを実行しなければなりません。テスト完了まで10分ばかり（キューでビルドの負荷が生じれば数時間に達することもあります）待たされても平気ですか？私にはそうは思えません。
ビルドの並列処理化で待ち時間を軽減することもできますが、結局コストに跳ね返ります。次のグラフをご覧ください。
たとえば現在のプロジェクトで5xの並列処理を行っているとすると、ジョブ1つあたりの平均RSpec実行時間はexample 1250件あたり2.5分を要します。つまりEPM（examples per minute）は500になります。
最適化を行う前は、800件のexampleで4分を要しました。EPMにしてわずか200です。つまり最適化によってビルドあたり3、4分を節約できたのです。
明らかに、遅いテストはあなたの貴重な時間を奪い、生産性を低下させているのです。
ツールボックス
あなたがテストスイートの遅さに気づいたとしましょう。ではテストが遅い理由をどうやって明らかにしますか？
能書きは以下の動画に任せて、RubyテストのプロファイリングツールボックスであるTestProf gemをご紹介いたします。
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
...
これで、ボトルネックを調べる際のテストのtypeを絞り込めるようになりました。
RubyProfやStackProfのような一般的なRubyプロファイラを使ったことがある方もいると思いますが、TestProfは面倒な設定や改造を一切行わずにテストスイートに対して手軽に実行できます。
TEST_RUBY_PROF=1 bundle exec rake test
# 以下も同じ
TEST_STACK_PROF=1 rspec
TestProfの各種プロファイラが生成するレポートを使って、最も利用頻度の高いスタックパスを突き止めることができ、質問2.にも答えられるようになります。
このプロファイリングについては残念ながらリソース消費が著しく、既に遅いテストスイートの実行がますます遅くなりますので、テストの一部に絞り込んでプロファイルを実行しなければなりません。しかしどうやって絞り込めばよいのでしょうか。実は、ランダムに絞り込めるのです。
TestProfには特殊なパッチが同梱されており、RSpecのexampleグループ（またはMiniTestのスイート）をランダムに選んで実行できます。
SAMPLE=10 bundle exec rspec
後はコントローラのテストのサンプルに対してStackProfを実行し（TagProfでここが最も遅かったので）、出力結果を元に分析すればよいのです。私があるプロジェクトに対して実行した結果を以下に示します。
%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
ここから、test環境におけるSorceryの暗号化設定がproduction環境と同じ制約の強い設定になっていることがわかります。
典型的なRailsアプリの場合、レポートはほとんどの場合以下のようになるでしょう。
TOTAL (pct) SAMPLES (pct) FRAME
205 (48.6%) 96 (22.7%) ActiveRecord::PostgreSQLAdapter#exec_no_cache
41 (9.7%) 22 (5.2%) ActiveModel::AttributeMethods::#define_proxy_call
20 (4.7%) 14 (3.3%) ActiveRecord::LazyAttributeHash#[]
ActiveRecordが随分と多く、データベースの利用も突出しています。ではこれをどうやって改善すればよいのでしょうか。続きをご覧ください。
データベースとのやりとり
テストスイートの実行時間にデータベースが占める割合がどのぐらいあるかを把握していますか？まずは自分であたりを付けてから、TestProfであぶり出してみましょう。
私たちはRailsのInstrumentation周りを既に拡張した（ActiveSupportのNotification/Instrumentation機能）ので、EventProfilerの基本的な概要やご紹介は省略いたします。
EventProfはテストスイート実行中にinstrumentationメトリックスを収集し、遅いグループのランキングや、特定のメトリックスに関連するexampleについての一般的な情報をレポートします。現時点では、ActiveSupport::Notificationsのみ無設定で利用できますが、自分のソリューションへの統合は簡単なはずです。
データベース利用量の情報を取得するには、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
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)
私の現在のプロジェクトでは、DBが総時間に占める割合はおよそ20%ですが、これは既に十分最適化を行った結果です。最適化前は30%を超えていました。
どのプロジェクトでも共通でチェックに使えるようなメトリックの値というものはありません。これはテストのスタイルによって大きく変わるものであり、単体テストと結合テストのどちらが多いかによって異なります。
なお私たちの場合は結合テストがほとんどだったため、20%という値は決して悪くありません（もちろんさらに改善は可能なはずですが）。
データベースがテスト時間に占める割合が高い典型的な理由とは何でしょうか。そのすべてを列挙するのは無理ですが、一部をリストアップしてみました。
- 無意味なデータ生成
- テストの準備が重すぎる（
beforeやsetupのフック） - ファクトリーがカスケードしている
最初の項目は、有名な「Model.new vs Model.create問題」（またの名を「FactoryGirlにおける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でいいじゃない」とお思いかもしれません。十数個ものモデルが毎日変更されるようなかなり大きなプロジェクトでなければ悪くない方法です。
もうひとつの方法は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をご検討ください。これは、（ファクトリーを使って）コードからフィクスチャを生成するのに使えます。
ファクトリーのカスケード問題
ファクトリーのカスケード問題については、これだけで記事になります。今後にご期待下さい！（真っ先に知りたい方はTwitterのフォローをお願いします）
次の記事が公開されるまでの間、EventProfをfactory.createに対して実行し、テストスイートがファクトリでどれだけ重くなるか時間を計ってみるとよいでしょう（警告: かなりショッキングな結果が出ます）。
バックグラウンドジョブ
データベース以外にもさまざまなボトルネックがあります。その中からひとつを取り上げてみましょう。
テストでよく行われるのが、バックグラウンドジョブをインライン化する（Sidekiq::Testing.inline!など）という手法です。
通常、重たい作業はバックグランドに回しますので、すべてのジョブを実行すると実行時間が無条件に長くなります。
TestProfはバックグラウンドに要した時間のプロファイリングもサポートしています（現時点ではSidekiq限定）。以下のようにプロファイルにsidekiq.inlineを指定するだけでできます。
EVENT_PROF=sidekiq.inline bundle exec rspec
これで、無駄になっている時間を正確に知ることができます。次はどうすればよいでしょうか。単にインラインモードをオフにすると、テストのexampleが大量に動かなくなるかもしれません。あまりに多さにすぐには修正しきれないほどです。
解決方法は、インラインをグローバルにオフにし、必要な場合のみオンにすることです。RSpecをお使いの場合は次のようにします。
# 共有コンテキストを追加
shared_context "sidekiq:inline", sidekiq: :inline do
around(:each) { |ex| Sidekiq::Testing.inline!(&ex) }
end
# 必要な場合にのみ使う
it "do some bg", sidekiq: :inline do
...
end
失敗したexampleのひとつひとつにタグを付けて回らなければならないのでしょうか？TestProfならそんな必要はありません。
ツールボックスにはRSpec Stampという特殊なツールが含まれており、特定のタグを自動で追加してくれます。
RSTAMP=sidekiq:inline rspec
ところで、RSpec Stampの内部ではソースファイルをパースしてタグを正しく挿入するためにRipperを用いています。
inline!をfake!に移行する方法についてはRSpec Stampのマニュアルをご覧ください。
TestProfはGitHubとrubygems.orgで公開されており、いつでもアプリに導入してテストスイートのパフォーマンス向上に役立てることができます。
本記事はTestProfの紹介のみにとどまっており、すべての機能をカバーしているわけではありません。詳しくは以下の追加リソースをどうぞ。
- TestProfガイド
- RubyConfByでのセッション「Run Test Run」（動画、スライド）
- 訳注: セッションタイトルはStar Warsのセリフのもじりです
- テストスイートを高速化する秘訣（Benoit Tigeot）
今年9月にモスクワで開催予定のRailsClubでもテストのパフォーマンスについてスピーチしますので、ぜひご来場ください！
スタートアップをワープ速度で成長させられる地球外エンジニアよ！Evil Martiansのフォームにて待つ。
