[RubyConfLT Vilnius 2017] Run Test Run

Writing tests is a significant part of the development process in Ruby community.

The test suite’s run time increases as our application evolves. We don’t care until we found ourselves wasting time waiting for the green light.

I want to show you how to profile tests and make them run faster

Links:

SpecProfiling (RubyProf, StackProf):  https://gist.github.com/palkan/73395cc201a565ecd3ff61aac44ad5ae

Flame graphs: http://www.brendangregg.com/flamegraphs.html

EventProfiler: https://gist.github.com/palkan/875e90fd085e214ce3b0f76e2b27208f

FactoryDoctor: https://gist.github.com/palkan/4088ab57191f6b537ef3e4d75939a190

FactoryProf: https://gist.github.com/palkan/ee031c4f857e33ca8c7ff28f5c2df117

FactoryDefault: https://gist.github.com/palkan/e0315dee43d3240f5011aeddd51910c8

Rubocop RSpec/AggregateFailures: https://gist.github.com/palkan/ac4eb92f08d0b33f41a9330445e76fbd

AnyFixture: https://gist.github.com/palkan/680250e8ce52460730df78593d22d0af

RSpecHell: https://gist.github.com/palkan/9870bb17899c6849bae20a5413d47c35

ActiveRecord OneLove: https://gist.github.com/palkan/98214019355b6061319769e9efef5eda

Transcript

1. RUN TEST RUN Vladimir Dementyev, Evil Martians RubyConfLT, 2017
2. RUN TEST RUN Vladimir Dementyev, Evil Martians RubyConfLT, 2017, 10th anniversary
5. EVIL OPEN SOURCE
7. THIS TALK
8. TESTING * slap shit together and deploy
9. PROFILING * Gorbypuff
10. AUTOMATION
11. LEGACY * But it's not by foot
12. THE QUESTION
13. THE SURVEY Q: Do you write tests? Yes No 94% 6% * Conducted on Feb, 2017, about 200 respondents
14. THE SURVEY Q: How long does your whole suite run?
15. THE SURVEY Q: How long does your whole suite run? 5–10 min 10–20 min 20–60 min > 60 min < 5 min 12% 10% 5% 26% 47%
16. THE SURVEY Q: How long does your whole suite run? Having more than 1000 examples 5–10 min 10–20 min 20–60 min > 60 min < 5 min 22% 19% 8% 28% 23%
17. THE SURVEY Q: How long does your whole suite run? Having more than 1000 examples 5–10 min 10–20 min 20–60 min > 60 min < 5 min 22% 19% 8% 28% 23% ~30% suites runs about 20 minutes
19. THE STORY OnboardIQ (Oct, 2016) — ~3700 tests — 20-22 minutes* on TravisCI (no parallelism) — Sometimes build spent hours in a queue * only RSpec
21. THE STORY OnboardIQ (Oct, 2016) — ~3700 tests — 20-22 minutes on TravisCI (no parallelism) Migrated to CircleCI: — 10 minutes (2x parallelism*) — 4 minutes (5x parallelism) * the same price as TravisCI
22. THE STORY OnboardIQ (Mar, 2017) — ~6100 tests — 2.5 minutes on CircleCI (5x parallelism)
23. THE STORY OnboardIQ (Mar, 2017) — ~6100 tests — 2.5 minutes on CircleCI (5x parallelism) 2.5k more tests – 40% faster
24. THE SETUP
25. THE SETUP — RSpec http://rspec.info
27. THE SURVEY Q: Which testing framework do you use? RSpec Other 80% 2% MiniT est 18%
28. RSPEC VS. MINITEST Synthetic benchmark: MiniTest class SuperTest < MT Unit TestCase 1.upto(1_000).each do |i| define_method "test_truth_ i}" do assert_equal i, i end end end Finished in 0.040523s
29. RSPEC VS. MINITEST Synthetic benchmark: RSpec describe "Test" do 1.upto(1_000).each do |i| specify { expect(i).to eq i } end end Finished in 0.21693 seconds
30. RSPEC VS. MINITEST Synthetic benchmark: RSpec describe "Test" do 1.upto(1_000).each do |i| specify { expect(i).to eq i } end end Finished in 0.21693 seconds 5x slower
31. RSPEC VS. MINITEST Real-life benchmark: — ~4k examples* — RSpec: 9 minutes 30 seconds — MiniTest: 8 minutes 40 seconds * Rails request tests
32. RSPEC VS. MINITEST Real-life benchmark: — ~4k examples* — RSpec: 9 minutes 30 seconds — MiniTest: 8 minutes 40 seconds only 10% slower * Rails request tests
34. THE SETUP — RSpec http://rspec.info — FactoryGirl
35. THE SETUP — RSpec http://rspec.info — FactoryGirl (for both factories and fixtures )
36. STEP #0 — Sub-suite (500 examples) — Run-time – 7 minutes
37. PROFILING — General profilers (ruby prof, stackprof)
38. RUBYPROF %self calls name 2.51 4690 *ActiveSupport Notifications Instrumenter#instrument 1.31 211554 String#to_s 1.31 47489 Arel Visitors Visitor#dispatch 1.15 117241 *Class#new 1.07 74655 ActiveSupport PerThreadRegistry#instance 1.01 531385 Module# 0.99 45291 ActiveRecord AttributeMethods#column_for_attribute 0.97 117482 <Class Thread>#current 0.96 16038 *ActiveRecord AttributeMethods #primary_key
39. ENCRYPTION STORY %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
40. ENCRYPTION STORY %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 gem "sorcery"
41. ENCRYPTION STORY # Sorcery config config.user_config do |config| # default is 10 for bcrypt! config.stretches = 1 if Rails.env.test? end
42. ENCRYPTION STORY # Sorcery config config.user_config do |config| # default is 10 for bcrypt! config.stretches = 1 if Rails.env.test? end Great impact – about 60-70%!
43. ENCRYPTION STORY # Sorcery config config.user_config do |config| # default is 10 for bcrypt! config.stretches = 1 if Rails.env.test? end Great impact – about 60-70%! # Devise has the same in initializer config.stretches = Rails.env.test? ? 1 : 10
44. * script example can be found here
45. * script example can be found here
46. STACKPROF * http://www.brendangregg.com/flamegraphs.html
47. STACKPROF * http://www.brendangregg.com/flamegraphs.html
48. PROFILING — General profilers (ruby prof, stackprof) — ActiveSupport instrumentation
49. EVENT PROFILER PROF_EVENT='sql.active_record' rspec
50. EVENT PROFILER PROF_EVENT='sql.active_record' rspec Profiling sql.active_record Total time: 03 09.059 Total events: 162454 Top 5 slowest suites: ApplicantsController – 00 34.050 (28637 / 102) Api: V2 ApplicantsController – 00 23.019 (19275 / 30)
51. EVENT PROFILER RSpec.configure do |config| listener = RSpec: EventProfiler.new config.reporter.register_listener(listener, ) config.after(:suite) { listener.print } end class RSpec EventProfiler def initialize ActiveSupport: Notifications.subscribe( ) end end * complete example can be found here
52. EVENT PROFILER PROF_EVENT='factory_girl.run_factory' rspec
53. EVENT PROFILER PROF_EVENT='factory_girl.run_factory' rspec Caveat! Factory events are not exclusive Profiling factory_girl.run_factory Total time: 04 49.064 But real time is 03:52* * How did I find it out? Continue reading
54. STEP #0 — Sub-suite (500 examples) — Run-time – 7 minutes — DB* time – 3 minutes * raw DB time, without ActiveRecord overhead
55. DB CLEANER STORY
56. DB CLEANER STORY config.before(:each) do |example| DatabaseCleaner.strategy = :deletion DatabaseCleaner.start end config.after(:each) do DatabaseCleaner.clean end Yep, this is real
59. gem "test_after_commit" # or Rails 5
60. PROFILING — Take a look at your code — General profilers (ruby prof, stackprof) — ActiveSupport instrumentation
62. STEP #1 — Sub-suite (500 examples) — Run-time – 4 minutes 40 seconds — DB time – 1 minute 10 seconds 30% faster
63. DATA GENERATION
64. DATA GENERATION Slow Parts — Excess Data
65. EXCESS DATA context "test pagination" do # page size is 40 before { create_list(:post, 41) } it "shows second page" do end end
66. EXCESS DATA # rails_helper.rb Kaminari.configure do |conf| conf.default_per_page = 2 end WillPaginate.per_page = 2 context "test pagination" do before { create_list(:post, 3) } it "shows second page" do end end
67. EXCESS DATA it "validates name presence" do user = create(:user) expect(user).not_to be_valid end
68. EXCESS DATA it "validates name presence" do user = create(:user) expect(user).not_to be_valid end it "validates name presence" do user = build_stubbed(:user) expect(user).not_to be_valid end
69. EXCESS DATA it "validates name presence" do user = create(:user) expect(user).not_to be_valid end it "validates name presence" do user = build_stubbed(:user) expect(user).not_to be_valid end Wouldn't it be nice to detect such bad examples automatically
70. FACTORY DOCTOR FDOC=1 rspec FactoryDoctor found useless data generation: User (./spec/models/user_spec.rb:3) ./spec/user_spec.rb:8 – 1 created objects, 00 00.114 Total wasted time: 00 00.165 Finished in 0.83153 seconds * Complete example can be found here
71. FACTORY DOCTOR When 200 examples: FDOC=1 rspec Total wasted time: 00 01.636 Finished in 2.87 seconds * Complete example can be found here
72. DATA GENERATION Slow Parts — Excess Data — Factory Cascade
73. factory :comment do answer author end factory :answer do question author end factory :question do author end
74. factory :comment do answer author end factory :answer do question author end factory :question do author end create(:comment) # creates 5 records
75. FACTORY CASCADE — How to fix?
76. FACTORY CASCADE — How to fix? — How to detect?
77. FACTORY PROF
78. FACTORY PROF Factory flame graphs
79. FACTORY STACK create(:comment) # stack = [ # :comment, # :answer, # :question, # :user, # :user, # :user # ]
80. FACTORY PROF FPROF=flamegraph rspec spec/ Flamegraph written to tmp/factory flame.html Total factories time: 00 31 06.012 * Complete example can be found here
81. FACTORY PROF FPROF=event PROF_EVENT='factory.create' rspec spec/ Profiling factory.create # Exclusive time Total time: 03 21.170 Total events: 3056 Top 5 slowest suites: * Complete example can be found here
82. PROFILING — Take a look at your code — General profilers (ruby prof, stackprof) — ActiveSupport instrumentation — Factory profilers (FactoryProf, FactoryDoctor)
83. CASCADE FIX #1 factory :stage do funnel end create(:stage, funnel: funnel) # raise ActiveRecord Invalid # account can't be blank
84. CASCADE FIX #2 factory :stage do funnel account do funnel&.account build(:account) end end create(:stage, funnel: funnel) # OK
85. CASCADE FIX #3 user = create_default(:user) question = create_default(:question) answer = create(:answer) answer.question question answer.user question.user user
86. FACTORY DEFAULT module FactoryDefault module CreateDefaultMethod def create_default(name, args, &block) res = create(name, args, &block) FactoryDefault.register(name, res) res end end module StrategyExt def association(runner) return super unless FactoryDefault.exists?(runner.name) FactoryDefault.get(runner.name) end end # main stuff here end FactoryGirl: Syntax: Methods.include CreateDefaultMethod FactoryGirl: Strategy: Create.prepend StrategyExt * Complete example can be found here
87. W/O FACTORY DEFAULT
88. WITH FACTORY DEFAULT
90. DATA GENERATION Slow Parts — Excess Data — Factory Cascade — Repeatable Data / Actions
91. REPEATABLE DATA before(:each) do # some heavy setup end it "one" { } it "ten" { }
92. REPEATABLE DATA describe BeatleWeightedSearchQuery do before(:each) do @paul = create(:beatle, name: 'Paul') @ringo = create(:beatle, name: 'Ringo') @george = create(:beatle, name: 'George') @john = create(:beatle, name: 'John') end # and about 15 examples here end
93. REPEATABLE DATA describe BeatleWeightedSearchQuery do before_all do @paul = create(:beatle, name: 'Paul') @ringo = create(:beatle, name: 'Richard') @george = create(:beatle, name: 'George') @john = create(:beatle, name: 'John') end # and about 15 examples here end before_all = before(:all) + transaction
94. module BeforeAll def before_all(&block) raise "Block is required!" unless block_given? before(:all) do ActiveRecord: Base.connection .begin_transaction(joinable: false) instance_eval(&block) end after(:all) do ActiveRecord: Base.connection .rollback_transaction end end end
95. REPEATABLE ACTIONS subject { get "/api/v2/users", params; response } it { is_expected.to be_success } it { is_expected.to have_header('X-TOTAL-PAGES', 10) } it { is_expected.to have_header('X-NEXT-PAGE', 2) }
96. REPEATABLE ACTIONS aggregate_failures it "returns the second page", :aggregate_failures do is_expected.to be_success is_expected.to have_header('X-TOTAL-PAGES', 10) is_expected.to have_header('X-NEXT-PAGE', 2) end
97. REPEATABLE ACTIONS aggregate_failures it "returns the second page", :aggregate_failures do is_expected.to be_success is_expected.to have_header('X-TOTAL-PAGES', 10) is_expected.to have_header('X-NEXT-PAGE', 2) end Detect and auto-correct?
98. RUBOCOP rubocop only RSpec/AggregateFailures Offenses: create_spec.rb:277 7 C RSpec/AggregateFailures: Use :aggregate_failures instead of one liners. context 'not valid secure fields' do ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 18 files inspected, 1 offense detected
99. RUBOCOP rubocop only RSpec/AggregateFailures auto correct 1 offense detected, 1 offense corrected * cop can be found here
100. STEP #2 — Sub-suite (500 examples) — Run-time – 3 minutes 10 seconds — DB time – 55 seconds 30% faster than Step #1
101. FIXTURES
103. Almost every test needs account (tenant) and funnel (top-level model within a tenant)
104. SHARED CONTEXT shared_context "account with funnel", account: true do let(:account) { create(:account, :with_funnel) } let(:funnel) { account.funnels.first } end describe "smth", :account do end Use the context everywhere you need both account and funnel
105. ANY FIXTURE shared_context "account with funnel", account: true do before(:all) do @account = AnyFixture.add(:account) do create(:account) end @funnel = AnyFixture.add(:funnel) do create(:funnel, :with_stages, account: @account) end end # Use `find` to have fresh AR object every time let(:account) { Account.find(@account.id) } let(:funnel) { account.funnels.first } end
106. module AnyFixture class self def add(id) # cache stores the result for the whole run # (or unless cleaned up) cache.fetch(id) do # Track all queries made during the block call ActiveSupport: Notifications.subscribed( method(:subscriber), "sql.active_record") do yield end end end end end * complete example can be found here
107. module AnyFixture INSERT_RXP = /^INSERT INTO ([\S]+)/ class self def subscriber(_event, _start, _finish, _id, data) matches = data.fetch(:sql).match(INSERT_RXP) # Store every affected table tables_cache[matches[1]] = true if matches end end end * complete example can be found here
108. module AnyFixture class self # Called within `after(:suite)` hook def clean # Delete all records from the affected tables tables_cache.keys.each do |table| ActiveRecord: Base.connection.execute %( "DELETE FROM table}" ) end tables_cache.clear cache.clear end end end * complete example can be found here
109. STEP #3 — Sub-suite (500 examples) — Run-time – 2 minutes 10 seconds — DB time – 45 seconds 50% faster than Step #2 110% faster than Step #1
110. FUTURE — Sub-suite (500 examples) — Run-time – 1 minutes 35 seconds — DB time – 30 seconds 3x faster that Step #1
111. THE SETUP — MRI — RSpec http://rspec.info — FactoryGirl
113. MINITEST HELL require "minitest/hell" class UserControllerTest < MT U Test # or # parallelize_me! end
114. MINITEST HELL require "minitest/hell" class UserControllerTest < MT U Test # or # parallelize_me! end bin/rails test test/users_controller_test.rb 20 runs, 23 assertions, 11 failures, 1 errors, 0 skips
115. RSPEC HELL HELL=4 rspec ./spec/users_controller_spec.rb Using RSpecHell 20 examples, 0 failures Sometimes fails too * complete example can be found here
116. MULTITHREADED — Frameworks are not designed for concurrent tests — Libraries are not thread-safe (e.g. Timecop, test adapters for ActiveJob, ActionMailer) — Only 20-25% faster* * maybe, I don't know how to cook JRuby
117. DB CLEANER STORY #2 Alice: Why do we need it?
118. DB CLEANER STORY #2 Alice: Why do we need it? Bob: Multithreaded tests (e.g. Capybara)
119. DB CLEANER STORY #2 Alice: Why do we need it? Bob: Multithreaded tests (e.g. Capybara) Batman: Even with Capybara you don't need it!
120. DB CLEANER STORY #2 Alice: Why do we need it? Bob: Multithreaded tests (e.g. Capybara) Batman: Even with Capybara you don't need it! Alice: ???? Bob: ????
121. CAPYBARA STORY Classic setup with DatabaseCleaner — 230 examples — 14 minutes 20 seconds
122. CAPYBARA STORY Classic setup with DatabaseCleaner — 230 examples — 14 minutes 20 seconds What if could use the same connection in all threads
123. module ActiveRecord OneLove class self def connection=(conn) @connection = conn connection.singleton_class.prepend Connection connection end end module Ext def connection OneLove.connection super end end end * Complete example can be found here
124. module ActiveRecord OneLove # synchonize DB queries module Connection @@mutex = Mutex.new def execute(*) @@mutex.synchronize { super } end end end * Complete example can be found here
125. CAPYBARA STORY With ActiveRecord::OneLove — 230 examples — 9 minutes 30 seconds 40% faster
126. CAPYBARA STORY With ActiveRecord::OneLove — 230 examples — 9 minutes 30 seconds 40% faster NOTE: Experimental
127. SYSTEM TESTS — Selenium vs. PhantomJS, CapybaraWebkit — gem 'rack_session_access' — Proxy for static assets (e.g. NGINX)
128. SYSTEM TESTS module AcceptanceHelper def sign_in(user) visit login_path fill_in 'email', with: user.email fill_In 'passowrd', with: 'beerbeer' click_on 'Log in' end end
129. SYSTEM TESTS module AcceptanceHelper def sign_in(user) page.set_rack_session( 'warden.user.user.key' User.serialize_into_session(user) ) end end 10% faster
130. DATABASE TRICKS — Use in-memory FS for database — Disable durability NOTE: haven't noticed any effect with Docker tmpfs * read more in Nate Berkopec book
131. BOOT TIME — Split helpers (rails_helper.rb, spec_helper.rb, features_helper.rb, etc) — Try bootscale — Use Spring (or similar)
132. THE SURVEY Q: Do you use code preloaders such as Spring, Zeus? Spring Zeus 57% 3% Nothing 40%
133. THE COST OF SPRING — Save you 15-20 seconds every time you run a command — Once in a week you spend a couple of minutes investigating the problem and end with "F**king Spring! "
134. THANKS! QUESTIONS? Vladimir Dementyev, Evil Martians GitHub: @palkan Twitter: @evilmartians, @palkan_tula