ローカル環境でのフルテストを60分短縮した話

Viibarアドベントカレンダーのトップバッターは @yagince が担当致します。

テスト書くのが当たり前になってきた昨今、フルテストはCIサーバに任せるのが当たり前になっている方も多いのではと思います。
しかし、こんな事ありませんか？

• CIのキューがめっちゃ溜まってしまう
• インターネット繋がらない環境にいる時にリモートにpushできない

そんな時、ローカルでフルテスト流したい！ってことになりますよね。
はい、私はなりました。

というわけで、今回はローカル環境でフルテスト流すのを頑張るためにやったことを書きます。

※今回はテスト自体をリファクタリングするのではなくツールや設定を変更する事で改善を試みます

前提

• Ruby: 2.2.2
• Rails: 4.2.3
• MySQL: 5.6.27
• OS: Mac OSX 10.10.5

まずはフルテスト流してみる

$ bin/rspec spec --format progress

この時点で、70分前後かかってました。

アプローチ1 : 分散させてすこしでも速く終わるようにする

RSpecの分散実行としては

• RRRSpec
• parallel_tests
• test-queue

などが有名かと思いますが、今回は一番手軽に出来そうなtest-queueを採用しました。

実行用スクリプトを書く

Gemfile

...
  gem 'test-queue'
...

bin/rspec-testqueue (名前はなんでも良いです)

#!/usr/bin/env ruby

ENV['RAILS_ENV'] ||= 'test'
require File.expand_path('../../config/environment', __FILE__)

require 'test_queue'
require 'test_queue/runner/rspec'

class RSpecTestQueueRunner < TestQueue::Runner::RSpec
  def after_fork(num)
    ENV.update('TEST_ENV_NUMBER' => num.to_s)

    ActiveRecord::Base.configurations['test']['database'] << num.to_s
    ActiveRecord::Base.establish_connection(:test)

    ActiveRecord::Tasks::DatabaseTasks.drop_current
    ActiveRecord::Tasks::DatabaseTasks.create_current
    ActiveRecord::Tasks::DatabaseTasks.load_schema_current
  end

  def summarize
    estatus = @completed.inject(0){ |s, worker| s + worker.status.exitstatus }
    estatus = 255 if estatus > 255
    exit(estatus)
  end

  def run_worker(iterator)
    @run_worker_ret = super
  end

  def cleanup_worker
    Kernel.exit @run_worker_ret if @run_worker_ret
  end
end

RSpecTestQueueRunner.new.execute

• after_forkでやっていること
  • database名にsuffixとして数字を追加
    • 通常のテスト用のスキーマと分ける為
    • 分散した環境毎にスキーマを用意する為
  • テーブルを全てdrop
  • テーブルを作成しなおす

実行してみる

$ time TEST_QUEUE_WORKERS=5 bin/rspec-testqueue spec --format progress
TEST_QUEUE_WORKERS=5 bin/rspec-testqueue spec --format progress --color  1990.74s user 352.09s system 77% cpu 50:31.70 total

• TEST_QUEUE_WORKERSで5worker立ち上げてます
  • デフォルトだとマシンのコア数分のworkerが起動されます
  • 自分の環境だとコア数以上にあげてもこの時点ではあまり変わりませんでした
• 結果
  • 実行時間: 約50分
  • 20分くらい短縮できました

アプローチ2 : ワーニングの出力を減らす

feature specの実行時にCapybaraが外部のURLをブロックした警告が大量に出ていた為
それを抑制する為に、rails_helper.rbに以下を追加しました。

Capybara::Webkit.configure do |config|
  config.block_unknown_urls
end

実行してみる

$ time bin/rspec-testqueue spec --format progress
bin/rspec-testqueue spec --format progress  1601.61s user 215.14s system 80% cpu 37:46.18 total

• 結果
  • 実行時間: 約38分
  • 12〜13分速くなった

アプローチ3 : Databaseのクリーンアップを改善する

これまで弊社ではDatabaseCleanerを使っていましたが、DatabaseRewinderを試してみる事にしました。

しかし、これがなかなか曲者で苦労しました。

rails_helper.rbでDatabaseRewinderを使うように修正する

README通りに直しただけで終了でした。

実行してみる

$ time bin/rspec-testqueue spec --format progress
...
vendor/bundle/ruby/2.2.0/gems/activerecord-4.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:446:in `checkout_new_connection': ActiveRecord::ConnectionNotEstablished (ActiveRecord::ConnectionNotEstablished)
...

エラー発生

※ちなみに、test-queueではなく普通にrspecコマンドで実行すると問題ありませんでした

スタックトレース全文

/******/vendor/bundle/ruby/2.2.0/gems/activerecord-4.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:446:in `checkout_new_connection': ActiveRecord::ConnectionNotEstablished (ActiveRecord::ConnectionNotEstablished)
        from /******/vendor/bundle/ruby/2.2.0/gems/activerecord-4.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:422:in `acquire_connection'
        from /******/vendor/bundle/ruby/2.2.0/gems/activerecord-4.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:349:in `block in checkout'
        from /${HOME}/.rbenv/versions/2.2.2/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
        from /******/vendor/bundle/ruby/2.2.0/gems/activerecord-4.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:348:in `checkout'
        from /******/vendor/bundle/ruby/2.2.0/gems/activerecord-4.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:263:in `block in connection'
        from /${HOME}/.rbenv/versions/2.2.2/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
        from /******/vendor/bundle/ruby/2.2.0/gems/activerecord-4.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:262:in `connection'
        from /******/vendor/bundle/ruby/2.2.0/gems/database_rewinder-0.5.3/lib/database_rewinder/cleaner.rb:29:in `clean_all'
        from /******/vendor/bundle/ruby/2.2.0/gems/database_rewinder-0.5.3/lib/database_rewinder.rb:85:in `each'
        from /******/vendor/bundle/ruby/2.2.0/gems/database_rewinder-0.5.3/lib/database_rewinder.rb:85:in `clean_all'
        from /******/spec/rails_helper.rb:111:in `block (2 levels) in <top (required)>'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/example.rb:424:in `instance_exec'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/example.rb:424:in `instance_exec'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/hooks.rb:357:in `run'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/configuration.rb:1724:in `block in run_hooks_with'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/configuration.rb:1724:in `each'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/configuration.rb:1724:in `run_hooks_with'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/configuration.rb:1679:in `with_suite_hooks'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner/rspec3.rb:30:in `block in run_specs'
        from /******/vendor/bundle/ruby/2.2.0/gems/rspec-core-3.4.0/lib/rspec/core/reporter.rb:77:in `report'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner/rspec3.rb:29:in `run_specs'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner/rspec.rb:22:in `run_worker'
        from bin/rspec-testqueue:35:in `run_worker'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner.rb:228:in `block (2 levels) in spawn_workers'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner.rb:223:in `fork'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner.rb:223:in `block in spawn_workers'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner.rb:220:in `times'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner.rb:220:in `spawn_workers'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner.rb:160:in `execute_parallel'
        from /******/vendor/bundle/ruby/2.2.0/gems/test-queue-0.2.13/lib/test_queue/runner.rb:94:in `execute'
        from bin/rspec-testqueue:43:in `<main>'

一部伏せてますが、関係ないです

事象

スタックトレースを追ってみると...

• DatabaseRewinder.clean_allでエラーになっている
• DatabaseRewinder.clean_allからCleanerの#clean_allに行って
• ActiveRecordのConnectionPool#connectionに行って
• connectionが無い為、なんだかんだで、コネクションを新しく張ろうとして
• 最終的には、checkout_new_connectionでConnectionNotEstablishedがraiseされていた

原因

• test-queueのafter_forkでestablish_connectionした時に
• remove_connectionされて
• @automatic_connectionがfalseに変更されている
• なので、DatabaseRewinderがキャッシュしているconnection_poolが後からリコネクトできない状態になっているように見える

解決策

after_fork内で、database関連の準備をし終わった後に、
DatabaseRewinder.initすることで一旦解決

...
class RSpecTestQueueRunner < TestQueue::Runner::RSpec
  def after_fork(num)
    ENV.update('TEST_ENV_NUMBER' => num.to_s)

    ActiveRecord::Base.configurations['test']['database'] << num.to_s
    ActiveRecord::Base.establish_connection(:test)

    ActiveRecord::Tasks::DatabaseTasks.drop_current
    ActiveRecord::Tasks::DatabaseTasks.create_current
    ActiveRecord::Tasks::DatabaseTasks.load_schema_current

    DatabaseRewinder.init
  end
...
end

実行してみる

bin/rspec-testqueue spec --format progress  1667.93s user 171.16s system 292% cpu 10:28.34 total

• 結果
  • 実行時間: 約10分
  • 約30分速くなった
  • mysqldの負荷が超絶軽くなった
  • Before
    • 
  • After
    • 

まとめ

• test-queueで分散
• ログはI/O発生するので、出力しまくるとやっぱり遅い
• 複数プロセスに分散させるだけで同じDBServerを使うと結局DBの負荷があがって速くならない
• テスト自体をリファクタリングせずともここまではやれる
• Before: 70m After: 10m 約60分短縮