みなさん、こんにちは！ 2週間ぶりのご無沙汰、MUGENUP の osada です。

ruby 2.1.0、Rails 4.1 で開発した、みなゲー編集部が正式リリースとなりました！よろしくお願いします。

さて、そんなRails 4.1の新機能として、プレローダーspringが標準装備となりました。本日はspringとparalell_testsを併用する方法についてのお話です。

要旨は下記となります。

PARALLEL_TESTS_EXECUTABLEを設定して、paralell_testsにspringを使わせない

bin/rspecを書き換えて、始めのプロセスだけspringを使う

FailuresLogger を使って、失敗したテストを再実行する

RuntimeLoggerを使って、テストのグループを平均化する

では、よろしくお願いします。

`PARALLEL_TESTS_EXECUTABLE`を設定して、`paralell_tests`に`spring`を使わせない

Rails 4.1のテストで、rspecでは成功するのに、paralell_testsでは多くが失敗する、という現象に遭いました。 springが原因と考えられます。

通常、rakeやrspecコマンドを使うとき、コード(code)を読み込んで、メモリ上にRailsのappインスタンスを生成し、使用します。処理が終わると、appは解放されます。

f:id:mgnup:20140223195200p:plain

この処理はかなり重い処理なので、毎回作るのではなく、一度作ったappを使いまわそう、というのがspringの動きです。springで作られたappは処理が終わっても維持され、再度使用されます。

f:id:mgnup:20140223195207p:plain

このspringはbin_stubとして提供され、bin/というディレクトリに rails, rspec, rakeのコマンドが用意されます。例えば、

be bin/rake db:create

のように、通常のコマンドの代わりに、bin/下のコマンドを呼び出すことで、springが使用されます。

一方、paralell_testsというのは、rakeなどの処理を複数のプロセスに分けて同時に処理する方法です。

f:id:mgnup:20140223195212p:plain

例えば、parallel:specを実行すると、下記の4つのコマンドが実行されます。

※be は bundle exec の alias です

$ be rake parallel:spec

TEST_ENV_NUMBER=;export TEST_ENV_NUMBER;PARALLEL_TEST_GROUPS=4;export PARALLEL_TEST_GROUPS;rspec
TEST_ENV_NUMBER=3;export TEST_ENV_NUMBER;PARALLEL_TEST_GROUPS=4;export PARALLEL_TEST_GROUPS;rspec
TEST_ENV_NUMBER=4;export TEST_ENV_NUMBER;PARALLEL_TEST_GROUPS=4;export PARALLEL_TEST_GROUPS;rspec
TEST_ENV_NUMBER=2;export TEST_ENV_NUMBER;PARALLEL_TEST_GROUPS=4;export PARALLEL_TEST_GROUPS;rspec

しかし、これにspringを使用すると、4つのプロセスがあるのに、実際に稼働するappは1つになってしまいます。

f:id:mgnup:20140223195216p:plain

よって、テストが失敗してしまうのです。

原因はparalell_testsがbin/rspecを使用するという点にあります。これをどうにかしましょう。

$ be rake parallel:spec

TEST_ENV_NUMBER=;export TEST_ENV_NUMBER;PARALLEL_TEST_GROUPS=4;export PARALLEL_TEST_GROUPS;bin/rspec
……

結論からいうと、PARALLEL_TESTS_EXECUTABLEを設定することで、bin/rspecの使用を回避できます。

PARALLEL_TESTS_EXECUTABLE="bundle exec rspec" be rake parallel:spec

TEST_ENV_NUMBER=;export TEST_ENV_NUMBER;PARALLEL_TEST_GROUPS=4;export PARALLEL_TEST_GROUPS;bundle exec rspec
……

この理由は、parallel_testsは、実行するファイルを下記のように設定しているからです。

def executable
  ENV['PARALLEL_TESTS_EXECUTABLE'] || determine_executable
end

またrspecのdetermine_executableは下記であり、[bin/rspec, script/spec, bundle exec rspec, spec, rspec] のどれかを起動する事がわかります。

def determine_executable
  cmd = case
  when File.exists?("bin/rspec")
    "bin/rspec"
  when File.file?("script/spec")
    "script/spec"
  when ParallelTests.bundler_enabled?
    cmd = (run("bundle show rspec-core") =~ %r{Could not find gem.*} ? "spec" : "rspec")
    "bundle exec #{cmd}"
  else
    %w[spec rspec].detect{|cmd| system "#{cmd} --version > /dev/null 2>&1" }
  end

  cmd or raise("Can't find executables rspec or spec")
end

bin/rspecを削除しても良いのですが、それではspringが使えなくなるので、 PARALLEL_TESTS_EXECUTABLEを設定する方が適切でしょう。

以上、本項の結論は、

parallel_testsに、springを使わせないためには、PARALLEL_TESTS_EXECUTABLEを設定するとなります。

`bin/rspec`を書き換えて、始めのプロセスだけ`spring`を使う

しかしせっかくのspringです。 4つの内1つだけでspringを使い、残り3つを別のプロセスで動かせば良いのではないでしょうか？

f:id:mgnup:20140223195219p:plain

相手はbin_stubですから、修正はとても簡単です。

bin/rspecのこれを、

if !Process.respond_to?(:fork) || Gem::Specification.find_all_by_name("spring").empty?
  exec "bundle", "exec", "rspec", *ARGV
else
  ARGV.unshift "rspec"
  load Gem.bin_path("spring", "spring")
end

こうしましょう！

if !Process.respond_to?(:fork) || Gem::Specification.find_all_by_name("spring").empty?
  exec "bundle", "exec", "rspec", *ARGV
else
  if ENV["TEST_ENV_NUMBER"].nil? || ENV["TEST_ENV_NUMBER"].empty?
    ARGV.unshift "rspec"
    load Gem.bin_path("spring", "spring")
  else
    exec "bundle", "exec", "rspec", *ARGV
  end
end

ENV["TEST_ENV_NUMBER"].nil? は通常のbin/rspec起動時です。 ENV["TEST_ENV_NUMBER"].empty?は、parallel_testsの一番始めのプロセスの時です。

つまり、

bin/rspecとして起動したとき、または、parallel_testsの一番始めのプロセスの時に、springを使用する。

というbin_stubになりました。

さて、肝心のスピードアップですが、featureテストなどが多いため、私のプロジェクトでは違いが現れませんでした。参考までとはなりますが、環境の影響が少ないspec/modelに適用した結果を載せておきます。

[feature/parallel stash]~/projects/mugenup/workstation: time RAILS_ENV=test PARALLEL_TESTS_EXECUTABLE="bundle exec rspec" bundle exec rake parallel:spec[model]
……
444 examples, 0 failures

Took 216.680576 seconds

real    3m47.661s
user    3m20.585s
sys     0m25.249s

[feature/parallel stash]~/projects/mugenup/workstation: time RAILS_ENV=test bundle exec bin/rake parallel:spec[model]

……
444 examples, 0 failures

Took 212.844729 seconds

real    3m37.395s
user    0m1.378s
sys     0m0.285s

realを見ると10 secほど速くなっているように見えますが、誤差の範囲かもしれません。もし「速くなったよ！」という方がいらっしゃいましたら、ご一報ください！

`FailuresLogger` を使って、失敗したテストを再実行する

featureテストは実際のブラウザの挙動を再現するため、タイムアウトなどの理由により、タイミングによって失敗することもあります。 parallel_testsを使うと、さらに失敗しやすくなります。

たまたま失敗したのか、本当に失敗しているのかを確認するため、失敗したテストのみを再度実行するのですが、その時に役立つのが、FailuresLoggerです。

.rspec_parallel に paralell_testsのみのオプションを設定できます。

# .rspec_parallel

--format progress
--format ParallelTests::RSpec::FailuresLogger --out tmp/failing_specs.log

これには失敗したテストがログに残ります。標準出力と同じものです。

f:id:mgnup:20140223200202p:plain

ここから、再度テストを実行しましょう。

$ grep rspec tmp/failing_specs.log | awk '{print $2}' | xargs bundle exec rspec

/Users/osada/projects/mugenup/workstation/vendor/bundle/gems/rspec-core-2.14.7/lib/rspec/core/configuration.rb:896:in `load': cannot load such file -- /Users/osada/projects/mugenup/workstation/spec/views/projects/edit.html.erb_spec.rb:34 (LoadError)

あら、失敗してしまいました。なぜでしょうか？実際にファイルを開いてみたところ、ascii color codeが含まれていました。

f:id:mgnup:20140223200208p:plain

たしかに、これでは、rspecが通りませんね。といっても--colorを消してしまうのも、嬉しくありません。

そこで、正規表現を使って、抜き出すことにしました。

rspec から始まり、「ドット、スラッシュ、コロン、英数字とアンダースコア」で構成される文字列を抽出する

$ ruby -ne 'puts $1 if /(?<=rspec )([\.\/:\w]+)/' tmp/failing_specs.log | xargs bundle exec rspec

これで、失敗したテストのみ、再実行することができます。

rake taskにするべきか？とも思ったのですが、さらに実行を遅らせてしまいそうなので、 aliasの登録だけにしておきました。

こうゆうとき、どういう技を使えばいいか、わからないの

rubyでワンライナーを書くのは、少し大変ですね。

`RuntimeLogger`を使って、テストのグループを平均化する

さて、paralell_testsはデフォルトでは、ファイルサイズ順に均等化します。ファイルサイズの大きい順に並べて、4つのグループに順番に追加していくわけです。

RuntimeLoggerを使うことで、テストにかかった時間で、均等化することができます。

--format progress
--format ParallelTests::RSpec::RuntimeLogger --out tmp/parallel_runtime_rspec.log

tmp/parallel_runtime_rspec.logには、テストファイル名と、その実行時間が記録されています。

[feature/parallel stash]~/projects/mugenup/workstation: tail tmp/parallel_runtime_rspec.log
……
./spec/views/sub_projects/show.html.erb_spec.rb:2.261982
./spec/views/projects/show.html.erb_spec.rb:2.806851

テストのグループ分けのとき、with_runtime_infoメソッドが呼ばれます。 runtime_logつまりtmp/parallel_runtime_rspecがあるとき、かつ、今回のtestsファイル群が、このログの中に含まれていると考えられるときに、このログを使ってグループ分けします。

puts "Using recorded test runtime"が出力されれば、成功です。

def with_runtime_info(tests)
  lines = File.read(runtime_log).split("\n") rescue []

  # use recorded test runtime if we got enough data
  if lines.size * 1.5 > tests.size
    puts "Using recorded test runtime"
    times = Hash.new(1)
    lines.each do |line|
      test, time = line.split(":")
      next unless test and time
      times[File.expand_path(test)] = time.to_f
    end
    tests.sort.map{|test| [test, times[File.expand_path(test)]] }
  else # use file sizes
    tests.sort.map{|test| [test, File.stat(test).size] }
  end
end

実際に、使用したときと、使用していないときを比較してみます。

[feature/parallel stash]~/projects/mugenup/workstation: RAILS_ENV=test bundle exec bin/rake parallel:spec[model]

Finished in 2 minutes 19.6 seconds
78 examples, 0 failures

Finished in 3 minutes 19.1 seconds
124 examples, 0 failures

Finished in 3 minutes 10.7 seconds
116 examples, 0 failures

Finished in 3 minutes 13.1 seconds
126 examples, 0 failures

使用していないときの処理時間は2:19.6 〜 3:19.1であり、60秒以上のズレがあります。

一方、runtime_logを使用したときは下記です。 Using recorded test runtimeが表示されていることが確認できます。

[feature/parallel stash]~/projects/mugenup/workstation: RAILS_ENV=test bundle exec bin/rake parallel:spec[model]
Using recorded test runtime

Finished in 3 minutes 7.8 seconds
102 examples, 0 failures

Finished in 2 minutes 58.3 seconds
108 examples, 0 failures

Finished in 3 minutes 10.2 seconds
123 examples, 0 failures

Finished in 3 minutes 11.8 seconds
111 examples, 0 failures

2:58.3 〜 3:11.8であり、13秒ほどのズレでした。

残念ながら、こちらも大きなスピードアップは感じられませんでしたが、速くなったよ、という方はご一報いただけると嬉しいです。

まとめ

parallel_testsとspringの使い方、いかがだったでしょうか？

PARALLEL_TESTS_EXECUTABLE="bundle exec rspec" を設定して、paralell_testsにspringを使わせない

bin/rspecを書き換えて、始めのプロセスだけspringを使う

FailuresLogger を使って、失敗したテストを再実行する

RuntimeLoggerを使って、テストのグループを平均化する

弊社でもテストが遅いということが、問題になっており、日々改善に勤しんでおります。

こんなやり方あるよ！という情報をお持ちの方、いらっしゃいましたら、ご教授いただけますと幸いです。

よろしくお願いします！

宣伝

MUGENUP では、rails を使いたいエンジニアを募集中です。無限流開発、ご一緒しませんか？

大きな裁量で自社サービス開発！Rubyエンジニアをウォンテッド！ - 株式会社MUGENUPの求人 - Wantedly

f:id:mgnup:20131118023234p:plain

MUGENUP技術ブログ

Rails 4.1 の spring で paralell_tests を使う方法

`PARALLEL_TESTS_EXECUTABLE`を設定して、`paralell_tests`に`spring`を使わせない

`bin/rspec`を書き換えて、始めのプロセスだけ`spring`を使う

`FailuresLogger` を使って、失敗したテストを再実行する

`RuntimeLogger`を使って、テストのグループを平均化する

まとめ

宣伝

PARALLEL_TESTS_EXECUTABLEを設定して、paralell_testsにspringを使わせない

bin/rspecを書き換えて、始めのプロセスだけspringを使う

FailuresLogger を使って、失敗したテストを再実行する

RuntimeLoggerを使って、テストのグループを平均化する

まとめ

宣伝

`PARALLEL_TESTS_EXECUTABLE`を設定して、`paralell_tests`に`spring`を使わせない

`bin/rspec`を書き換えて、始めのプロセスだけ`spring`を使う

`FailuresLogger` を使って、失敗したテストを再実行する

`RuntimeLogger`を使って、テストのグループを平均化する