1. yagince

    Posted

    yagince
Changes in title
+ローカル環境でのフルテストを60分短縮した話
Changes in tags
Changes in body
Source | HTML | Preview
@@ -0,0 +1,259 @@
+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 : 分散させてすこしでも速く終わるようにする
+
+RSspecの分散実行としては
+
+- [RRRSpec](https://github.com/cookpad/rrrspec)
+- [parallel_tests](https://github.com/grosser/parallel_tests)
+- [test-queue](https://github.com/tmm1/test-queue)
+
+などが有名かと思いますが、今回は一番手軽に出来そうな**test-queue**を採用しました。
+
+## 実行用スクリプトを書く
+
+Gemfile
+
+```rb
+...
+ gem 'test-queue'
+...
+```
+
+bin/rspec-testqueue (名前はなんでも良いです)
+
+```rb
+#!/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_WORKER`で5worker立ち上げてます
+ - デフォルトだとマシンのコア数分のworkerが起動されます
+ - 自分の環境だとコア数以上にあげてもこの時点ではあまり変わりませんでした
+- 結果
+ - 実行時間: **約50分**
+ - **20分くらい短縮できました**
+
+# アプローチ2 : ワーニングの出力を減らす
+
+feature specの実行時にCapybaraが外部のURLをブロックした警告が大量に出ていた為
+それを抑制する為に、`rails_helper.rb`に以下を追加しました。
+
+```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](https://github.com/DatabaseCleaner/database_cleaner)を使っていましたが、[DatabaseRewinder](https://github.com/amatsuda/database_rewinder)を試してみる事にしました。
+
+しかし、これがなかなか曲者で苦労しました。
+
+## `rails_helper.rb`でDatabaseRewinderを使うように修正する
+
+[README通り](https://github.com/amatsuda/database_rewinder#basic-configuration)に直しただけで終了でした。
+
+## 実行してみる
+
+```
+$ 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](https://github.com/amatsuda/database_rewinder/blob/76fae52d0c493819da302ba52fd37e96bcd937c8/lib/database_rewinder.rb#L84)から[Cleanerの#clean_all](https://github.com/amatsuda/database_rewinder/blob/76fae52d0c493819da302ba52fd37e96bcd937c8/lib/database_rewinder/cleaner.rb#L29)に行って
+- ActiveRecordの[ConnectionPool#connection](https://github.com/rails/rails/blob/v4.2.3/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L259-L265)に行って
+- connectionが無い為、なんだかんだで、コネクションを新しく張ろうとして
+- 最終的には、[checkout_new_connection](https://github.com/rails/rails/blob/v4.2.3/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L446)で`ConnectionNotEstablished`がraiseされていた
+
+## 原因
+
+- test-queueの`after_fork`で[establish_connectionした時](https://github.com/rails/rails/blob/v4.2.3/activerecord/lib/active_record/connection_handling.rb#L47-L58)に
+- [remove_connectionされ](https://github.com/rails/rails/blob/v4.2.3/activerecord/lib/active_record/connection_handling.rb#L56)て
+- [@automatic_connectionがfalseに変更](https://github.com/rails/rails/blob/v4.2.3/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L590)されている
+- なので、DatabaseRewinderがキャッシュしているconnection_poolが後からリコネクトできない状態になっているように見える
+
+# 解決策
+
+`after_fork`内で、database関連の準備をし終わった後に、
+`DatabaseRewinder.init`することで一旦解決
+
+```rb
+...
+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
+ - <img width="815" alt="test-before-1.png" src="https://qiita-image-store.s3.amazonaws.com/0/9575/bb9e5ee6-a89d-cf49-b8be-e4437c3eba18.png">
+ - After
+ - <img width="806" alt="test-after-1.png" src="https://qiita-image-store.s3.amazonaws.com/0/9575/eeca293b-5bdb-94c4-b7a7-de3dc08d23a6.png">
+
+# まとめ
+
+- test-queueで分散
+- ログはI/O発生するので、出力しまくるとやっぱり遅い
+- 複数プロセスに分散させるだけで同じDBServerを使うと結局DBの負荷があがって速くならない
+- テスト自体をリファクタリングせずともここまではやれる
+- Before: 70m After: 10m **約60分短縮**