[RubyConfBY Minsk 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

Video: https://www.youtube.com/watch?v=q52n4p0wkIs

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

Transcript

1. RUN TEST RUN Vladimir Dementyev, Evil Martians RubyConfBy, 2017
4. EVIL OPEN SOURCE
6. THIS TALK
7. TESTING * slap shit together and deploy
8. PROFILING * Gorbypuff
9. AUTOMATION
10. LEGACY * But it's not by foot
11. THE QUESTION
12. THE SURVEY Q: Do you write tests? Yes No 94% 6% * Conducted on Feb, 2017, about 200 respondents
13. THE SURVEY Q: How long does your whole suite run?
14. 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%
15. 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%
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% ~30% suites runs about 20 minutes
18. THE STORY OnboardIQ (Oct, 2016) — ~3700 tests — 20-22 minutes* on TravisCI (no parallelism) — Sometimes build spent hours in a queue * only RSpec
20. 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
21. THE STORY OnboardIQ (Mar, 2017) — ~6100 tests — 2.5 minutes on CircleCI (5x parallelism)
22. THE STORY OnboardIQ (Mar, 2017) — ~6100 tests — 2.5 minutes on CircleCI (5x parallelism) 1.6x more tests – 1.6x faster
23. THE SETUP
24. THE SETUP — RSpec http://rspec.info
26. THE SURVEY Q: Which testing framework do you use? RSpec Other 80% 2% MiniT est 18%
27. 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
28. 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
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 5x slower
30. RSPEC VS. MINITEST Real-life benchmark: — ~4k examples* — RSpec: 9 minutes 30 seconds — MiniTest: 8 minutes 40 seconds * Rails request tests
31. RSPEC VS. MINITEST Real-life benchmark: — ~4k examples* — RSpec: 9 minutes 30 seconds — MiniTest: 8 minutes 40 seconds only 10% slower * Rails request tests
33. THE SETUP — RSpec http://rspec.info — FactoryGirl
34. THE SETUP — RSpec http://rspec.info — FactoryGirl (for both factories and fixtures )
35. STEP #0 The worst case — Sub-suite (500 examples) — Run-time – 7 minutes
36. PROFILING
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 2x faster!
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 2x faster! # 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. * script example can be found here
47. STACKPROF * http://www.brendangregg.com/flamegraphs.html
48. STACKPROF * http://www.brendangregg.com/flamegraphs.html
49. STACKPROF * http://www.brendangregg.com/flamegraphs.html
50. PROFILING — General profilers (ruby prof, stackprof) — ActiveSupport instrumentation
51. EVENT PROFILER PROF_EVENT='sql.active_record' rspec
52. 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)
53. 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
54. EVENT PROFILER PROF_EVENT='factory_girl.run_factory' rspec
55. 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 total time is 03:52!
56. STEP #0 The worst case — Sub-suite (500 examples) — Run-time – 7 minutes — DB* time – 3 minutes * raw DB time, without ActiveRecord overhead
57. DB CLEANER STORY
58. 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
61. gem "test_after_commit" # or Rails 5
62. PROFILING — Take a look at your code — General profilers (ruby prof, stackprof) — ActiveSupport instrumentation
64. STEP #1 Transactional tests (baseline) — Sub-suite (500 examples) — Run-time – 4 minutes 40 seconds — DB time – 1 minute 10 seconds 1.5x faster
65. DATA GENERATION
66. DATA GENERATION Slow Parts — Excess Data
67. EXCESS DATA context "test pagination" do # page size is 40 before { create_list(:post, 41) } it "shows second page" do end end
68. 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
69. EXCESS DATA it "validates name presence" do user = create(:user) expect(user).not_to be_valid end
70. 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
71. 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
72. FACTORY DOCTOR
73. 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
74. 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
75. DATA GENERATION Slow Parts — Excess Data — Factory Cascade
76. factory :comment do answer author end factory :answer do question author end factory :question do author end
77. factory :comment do answer author end factory :answer do question author end factory :question do author end create(:comment) # creates 5 records
78. FACTORY PROF
79. FACTORY PROF Factory flame graphs
80. FACTORY STACK create(:comment) # stack = [ # :comment, # :answer, # :question, # :user, # :user, # :user # ]
81. 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
82. 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
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. PROFILING — Take a look at your code — General profilers (ruby prof, stackprof) — ActiveSupport instrumentation — Factory profilers (FactoryProf, FactoryDoctor)
91. DATA GENERATION Slow Parts — Excess Data — Factory Cascade — Repeatable Data / Actions
92. REPEATABLE DATA before(:each) do # some heavy setup end it "one" { } it "ten" { }
93. 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
94. 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
95. 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
96. 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) }
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
98. 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?
101. 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 * cop can be found here
102. RUBOCOP rubocop only RSpec/AggregateFailures auto correct 1 offense detected, 1 offense corrected * cop can be found here
103. STEP #2 Optimized factories and hooks — Sub-suite (500 examples) — Run-time – 3 minutes 10 seconds — DB time – 55 seconds 1.5x faster than the baseline 2.1x faster than the worst case
104. FIXTURES
106. Almost every test needs account (tenant) and funnel (top-level model within a tenant)
107. 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
108. 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
109. 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
110. 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
111. 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
112. STEP #3 Adding fixtures — Sub-suite (500 examples) — Run-time – 2 minutes 10 seconds — DB time – 45 seconds 2.2x faster than the baseline 3.1x faster than the worst case
113. FUTURE — Sub-suite (500 examples) — Run-time – 1 minutes 25 seconds — DB time – 30 seconds 3x faster than the baseline
114. THE SETUP — MRI — RSpec http://rspec.info — FactoryGirl
116. MINITEST HELL require "minitest/hell" class UserControllerTest < MT U Test # or # parallelize_me! end
117. 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
118. 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
119. 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
120. 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
121. BOOT TIME — Split helpers (rails_helper.rb, spec_helper.rb, features_helper.rb, etc) — Try bootsnap (released 2 days ago) — Use code preloaders
122. THE SURVEY Q: Do you use code preloaders such as Spring, Zeus? Spring Zeus 57% 3% Nothing 40%
123. 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! "
124. THANKS? QUESTIONS? Vladimir Dementyev, Evil Martians GitHub: @palkan Twitter: @evilmartians, @palkan_tula