TechRacho
2017年10月10日

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

        

概要

原著者の許諾を得て翻訳・公開いたします。


evilmartians.com/chroniclesより



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. テストスイートのどこで時間を食っているか: コントローラか、モデルか、サービスか、ジョブか?
  2. 最も時間のかかっているモジュールやメソッドはどれか

これだけでも面倒な作業ですよね。

質問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を絞り込めるようになりました。

RubyProfStackProfのような一般的な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%という値は決して悪くありません(もちろんさらに改善は可能なはずですが)。

データベースがテスト時間に占める割合が高い典型的な理由とは何でしょうか。そのすべてを列挙するのは無理ですが、一部をリストアップしてみました。

最初の項目は、有名な「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はGitHubrubygems.orgで公開されており、いつでもアプリに導入してテストスイートのパフォーマンス向上に役立てることができます。

本記事はTestProfの紹介のみにとどまっており、すべての機能をカバーしているわけではありません。詳しくは以下の追加リソースをどうぞ。

今年9月にモスクワで開催予定のRailsClubでもテストのパフォーマンスについてスピーチしますので、ぜひご来場ください!


スタートアップをワープ速度で成長させられる地球外エンジニアよ!Evil Martiansのフォームにて待つ。

関連記事

FactoryGirlでtraitを使うとintegration test書くのが捗るという話

[Rails] RSpecをやる前に知っておきたかったこと

RSpecで役に立ちそうないくつかのヒント(翻訳)

テストを不安定にする5つの残念な書き方(翻訳)

[Rails] RSpecのモックとスタブの使い方