Pro Yearly is on sale from $80 to $50! »

[RubyConfBY Minsk 2017] Run Test Run

52cc8a838bf44a589d2572833b2dd1b9?s=47 Vlad Dem
April 02, 2017

[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

52cc8a838bf44a589d2572833b2dd1b9?s=128

Vlad Dem

April 02, 2017
Tweet

Transcript

  1. RUN TEST RUN Vladimir Dementyev, Evil Martians RubyConfBy, 2017

  2. None
  3. None
  4. EVIL OPEN SOURCE

  5. None
  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
  17. None
  18. THE STORY OnboardIQ (Oct, 2016) — ~3700 tests — 20-22

    minutes* on TravisCI (no parallelism) — Sometimes build spent hours in a queue * only RSpec
  19. None
  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

  25. None
  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
  32. None
  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
  59. None
  60. None
  61. gem "test_after_commit" # or Rails 5

  62. PROFILING — Take a look at your code — General

    profilers (ruby prof, stackprof) — ActiveSupport instrumentation
  63. None
  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

  89. None
  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?
  99. None
  100. None
  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

  105. None
  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

  115. None
  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