TestProf: Ruby/Railsの遅いテストを診断するgem(翻訳)

概要 原著者の許諾を得て翻訳・公開いたします。 英語記事: 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 … Continue reading TestProf: Ruby/Railsの遅いテストを診断するgem(翻訳)