RSpec の実行を高速におえるためのヒント

こんにちは、アルダグラムの内倉です。

テスト書いていますか？
KANNA では現在、ci で多くの機能のテストをカバーしており、プロダクトの機能・要件が充実してきたこともあって、テスト数自体もかなり増えてきました。
結果、テストの実行時間が長く「ci 通ったらマージしますね」などといった際の待ち時間が負担となっていました。

テストデータの削除方法を見直したり、テストを並列実行にするなどの対策を行い、40〜60 分 → 10分弱まで短縮できていました。

しかし、今回さらに TestProf というテストのパフォーマンスを分析してくれる gem を使って、テスト自体の無駄をなくす方向で試してみたところ、以下のような条件では「ほんとに実行してるかな？」と疑うレベルで効果がありました。

• テストで使用するデータの数が多い
• テストパターンが多い

今日は、今回の改善で行ったことを、ご紹介します👀

TestProf を利用してテストの実行を観察する

まずは、現状を見つめるところからやっていきます💪

0. TestProf 導入

準備はとても簡単で、Gemfile の :test のグループのところに、以下を追加するだけです。

group :test do
  gem "test-prof", "~> 1.0"
end

1. TestProf で観察出来ること

すごくたくさん機能があるのですが、今回使ったものは以下の３つです。

a. 実行時間のうち、データ生成にかかっている時間の割合

主に、テストコード改善の before / after の計測にこちらを使いました。

EVENT_PROF に factory.create を指定して Rspec を実行すると、テストの実行時間のうち、 FactoryBot でデータ生成するのにかかった時間の割合を調べることができます。

↓のように、全テストファイルを実行した場合は、デフォルトで実行時間が長い順に5件表示されます。

% EVENT_PROF="factory.create" bundle exec rspec

[TEST PROF INFO] EventProf enabled (factory.create)

...

[TEST PROF INFO] EventProf results for factory.create

Total time: 00:13.949 of 00:29.909 (46.63%)
Total events: 196

Top 5 slowest suites (by time):

AModel (./spec/models/a_model_spec.rb:5) – 00:05.840 (60 / 6) of 00:11.374 (51.34%)
BJob (./spec/jobs/b_job_spec.rb:6) – 00:06.347 (60 / 6) of 00:10.836 (58.57%)
CModel (./spec/models/c_model_spec.rb:5) – 00:00.967 (15 / 1) of 00:02.143 (45.12%)
DModel (./spec/models/d_model_spec.rb:5) – 00:00.707 (15 / 1) of 00:01.904 (37.13%)
EJob (./spec/jobs/e_job_spec.rb:5) – 00:00.780 (2 / 2) of 00:01.102 (70.78%)

Finished in 2.8 seconds (files took 6.08 seconds to load)

EVENT_PROF には、 factory.create 以外にも色々指定できます。

たとえば、以下を指定して「データベースの利用にかかった時間の割合」や「Job 実行にかかった時間の割合」なども調べることができます。

• sql.active_record
• perform.active_job
• [sidekiq.jobs](http://sidekiq.jobs)

b. 各モデルの生成回数

こちらは、factory cascade を探すのに使いました。

FPROF=1 を指定して Rspec を実行すると、factory の利用状況を一覧で表示してくれます。

% FPROF=1 bundle exec rspec

[TEST PROF INFO] FactoryProf enabled (simple mode)
...
[TEST PROF INFO] Factories usage

 Total: 6079
 Total top-level: 2193
 Total time: 07:30.238 (out of 08:31.410)
 Total uniq factories: 39

   total   top-level     total time      time per call      top-level time               name

    1630         251       64.5391s            0.0396s            11.8767s            a_model
     973           4        7.6210s            0.0078s             0.0266s            b_model
     779           9       18.5388s            0.0238s             0.2215s            c_model
     552           1       26.2110s            0.0475s             0.0285s            d_model

top-level 列は FactoryBot で明示的に create(:xxx) した作成回数、 total 列は、 association などで暗黙的に作成されたものを含む作成回数です。

top と top-level の数値に乖離があるほど「factory cascade が発生してそうだな？」ということになります。

c. 各モデル生成のフレームグラフ

こちらも、factory cascade を探すのに使いました。具体的に、どの model で定義している関連付けがあやしいのか？のヒントになります。

FPROF=flamegraph を指定して、問題ありそうな spec ファイルを実行します。

FPROF=flamegraph bundle exec rspec spec/test_spec.rb

すると tmp/test_prof/factory-flame.html に、factory スタックの HTMLフレームグラフ を出力してくれます。

こちらは、一番下が top-level の呼び出しを表していて、各カラムの幅は呼び出し回数に比例しています。

スタックが深いものを、トップレベルから辿って改善できそうな箇所を探します。

今回は、あからさまにデータ生成周りがあやしかったので、この３つを使用しましたが

「どのタイプのテスト（ model, job ... ）のパフォーマンスに問題がありそうか？」など、ほかにも色々なメトリクスを調べることができます。

一度、ドキュメントを眺めてみると、ご自身のプロジェクトにぴったりのものが見つかるかもしれません。

TestProf の Recipes

複数のテストで、同じ内容のデータを利用している場合など、テストデータを使いまわしたいことが多々あります。

結局、テストの独立性を考えて、各々作りたてのデータを使いがちなのですが、TestProf に同梱されている Recipes を使うと、簡単にデータを使い回せるようになります。

0. 準備

rails_helper.rb に以下を追加します。

require 'test_prof/recipes/rspec/let_it_be'
require 'test_prof/recipes/rspec/any_fixture'

1. let_it_be

こちらは let , let! を置き換えて使います。 let_it_be を使用すると、宣言したブロック内で１度だけデータを生成してくれます。

挙動としては、 before(:all) 内で宣言するのと同じですが、テストデータの削除まで面倒見てくれます。

2. AnyFixture

before(:all) の中で、特別なブロック（ TestProf::AnyFixture.register(:xxx) ※ xxx の部分は、一意になればなんでもOK ）を宣言して使います。

このブロック内で出力されるログを監視して、 データ生成の SQL を発行したテーブルを記録し、親ブロック終了後に該当のテーブルデータを削除してくれます。

あくまで SQL を見ているだけなので、ブロック内で生成するのは factory でも、ふつうの ActiveRecord でも大丈夫です。

テストコードを改善する

今回は、よりわかりやすく爆速になりそうな、プロジェクトで一番実行時間が長いテストファイルを改善してみます。

0. before 計測

まずは、改善前のデータ生成にかかっている時間の割合を見ていきます。

EVENT_PROF="factory.create" bundle exec rspec spec/xxx_spec.rb の結果はこんなかんじ↓↓↓

[TEST PROF INFO] EventProf results for factory.create

Total time: 05:56.373 of 06:29.952 (91.39%)
Total events: 2522

実行時間の 90% 以上を、テストデータの生成に費やしています🥲

つぎに、factory cascade が影響していそうかを確認します。

FPROF=1 bundle exec rspec spec/xxx_spec.rb の結果は、こんなかんじ ↓↓↓

[TEST PROF INFO] Factories usage

 Total: 12346
 Total top-level: 2522
 Total time: 05:42.397 (out of 06:19.865)
 Total uniq factories: 15

やはり、生成しているデータ数がかなり多いです。

が、「そもそもの関連モデルが多い」という前提があるので、 total-level で作成しているデータの割合という点では、割とまともな印象です。

レポートの詳細を見ても、factory cascade としてはそこまで問題のありそうな箇所はありませんでした。

ひとまずテストデータを共通利用する方針で修正を進めます。

1. データの作成回数を減らす

spec ファイルの内容を確認したところ、scope のテストを多く含んでいて、さらに検索値として渡せる項目も多いために、用意するテストデータ・テスト数ともに多くなっていることがわかりました。

たとえば、↓こんな雰囲気のテストです。（実際のコードは、複数の検索項目があったり、ソートの指定もあったりして、もうちょっと複雑です）

describe 'search_name' do
  # search_name は、name のカラムに、search_word が含まれるレコードを返すメソッド。
  # ※ 全角半角、大文字小文字は区別しない。

  subject { described_class.search_name(search_word) }

  let(:model_low_half1) { create(:model, name: 'aiu', ...) } # 完全一致
  let(:model_low_half2) { create(:model, name: 'oaiue', ...) } # 部分一致

  let(:model_low_full1) { create(:model, name: 'ａｉｕ', ...) } # 完全一致
  let(:model_low_full2) { create(:model, name: 'ｏａｉｕｅ', ...) } # 部分一致

  let(:model_up_half1) { create(:model, name: 'AIU', ...) } # 完全一致
  let(:model_up_half2) { create(:model, name: 'OAIUE', ...) } # 部分一致

  let(:model_up_full1) { create(:model, name: 'ＡＩＵ', ...) } # 完全一致
  let(:model_up_full2) { create(:model, name: 'ＯＡＩＵＥ', ...) } # 部分一致

  before do
    # 対象外のレコード
    create(:model, name: 'aaaaa', ...)
  end

  context 'when search_word is aiu ( half-width lowercase )' do
    let(:search_word) { 'aiu' }

    it 'return target records' do
      expect(subject).to contain_exactly(
        model_low_half1,
        model_low_half2
        model_low_full1,
        model_low_full2,
        model_up_half1,
        model_up_half2,
        model_up_full1,
        model_up_full2
      )
    end
  end

  context 'when search_word is ａｉｕ ( full-width lowercase )' do
    let(:search_word) { 'ａｉｕ' }

    ...
  end

  context 'when search_word is AIU ( falf-width uppercase )' do
    let(:search_word) { 'AIU' }

    ...
  end

  context 'when search_word is ＡＩＵ ( full-width uppercase )' do
    let(:search_word) { 'ＡＩＵ' }

    ...
  end
end

ここで利用しているテストデータは、参照のみなので、すべて共通しても問題なさそうです。

後述する注意点もあるのですが、まずは let let! で生成しているデータを、まるまる置き換えていきます。

そして before ブロックで生成している、対象外のデータもまるまる AnyFixture のブロックで囲んでしまいます。

# before
let(:model_low_half1) { create(:model, column_a: 'aiu', ...) }

# after
let_it_be(:model_low_half1) { create(:model, column_a: 'aiu', ...) }

# before
before do
  # 対象外のレコード
  create(:model, column_a: 'aaaaa', ...)
end

# after
before(:all) do
  TestProf::AnyFixture.register(:xxx) do
    # 対象外のレコード
    create(:model, column_a: 'aaaaa', ...)
  end
end

2. after 計測

まずは、実行時間から。

• before

[TEST PROF INFO] EventProf results for factory.create

Total time: 05:56.373 of 06:29.952 (91.39%)
Total events: 2522

• after

[TEST PROF INFO] EventProf results for factory.create

Total time: 00:22.177 of 00:27.751 (79.91%)
Total events: 180

そしてデータの生成数。

• before

[TEST PROF INFO] Factories usage

 Total: 12346
 Total top-level: 2522
 Total time: 05:42.397 (out of 06:19.865)
 Total uniq factories: 15

• after

[TEST PROF INFO] Factories usage

 Total: 459
 Total top-level: 180
 Total time: 00:20.886 (out of 00:28.620)
 Total uniq factories: 15

実行時間全体における、データ生成にかかった時間の割合はまだ高いですが、

• 実行時間：6分半 → 30秒
• 作成しているデータ数：12346 → 459

になったので、大成功じゃないでしょうか🥳

let_it_be AnyFixture 利用時の注意！！

最後に、所感を含みますが、注意点を書き添えておきます👀

置き換えないほうが速い場合もある

使用したテーブルを覚えておいて削除するので、生成するデータの量や、利用回数が少ないと Transaction rollback のほうが低コストです。

今回、「参照のみのテストデータしかないから〜」と、複数の spec ファイルを安易に一括置換したら、全然早くなりませんでした。

ちゃんと、利用状況を考慮しつつ様子を見て置き換えていかないと🙅‍♂️です。

let let! と違って、実行順を厳密に意識する必要がある

当たり前ではあるのですが、今まで let let! のみを使っていたときには、そこまで気を使わなくても済んでしまっていたため、結構引っかかることがありました。

たとえば、 let(:now) { Time.current } など、レコードの作成を行わないものも let_it_be AnyFixture で利用しているなら先に作成しておく必要があります。

テストデータを更新でも利用しているテストでは、意外なところに影響してしまう場合がある

こちらも当たり前なのですが、同一のデータを使い回すので、既存データに対して更新を行う処理のテストが含まれていると、「テストの実行順が変わると失敗する」ようなことが起こりえます。

いくら速くなるとしても、データを宣言する scope を無駄に大きくせず、更新処理のテストの場合は、簡潔に書けなければ無理して使わないなど、節度を持って利用することが大切だな、と思いました。