Upgrade to Pro — share decks privately, control downloads, hide ads and more …

[RubyConfBY Minsk 2017] Run Test Run

[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

Vladimir Dementyev

April 02, 2017
Tweet

More Decks by Vladimir Dementyev

Other Decks in Programming

Transcript

  1. THE SURVEY Q: Do you write tests? Yes No 94%

    6% * Conducted on Feb, 2017, about 200 respondents
  2. 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%
  3. 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%
  4. 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
  5. THE STORY OnboardIQ (Oct, 2016) — ~3700 tests — 20-22

    minutes* on TravisCI (no parallelism) — Sometimes build spent hours in a queue * only RSpec
  6. 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
  7. THE STORY OnboardIQ (Mar, 2017) — ~6100 tests — 2.5

    minutes on CircleCI (5x parallelism)
  8. THE STORY OnboardIQ (Mar, 2017) — ~6100 tests — 2.5

    minutes on CircleCI (5x parallelism) 1.6x more tests – 1.6x faster
  9. 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
  10. 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
  11. 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
  12. RSPEC VS. MINITEST Real-life benchmark: — ~4k examples* — RSpec:

    9 minutes 30 seconds — MiniTest: 8 minutes 40 seconds * Rails request tests
  13. RSPEC VS. MINITEST Real-life benchmark: — ~4k examples* — RSpec:

    9 minutes 30 seconds — MiniTest: 8 minutes 40 seconds only 10% slower * Rails request tests
  14. 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
  15. 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
  16. 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"
  17. ENCRYPTION STORY # Sorcery config config.user_config do |config| # default

    is 10 for bcrypt! config.stretches = 1 if Rails.env.test? end
  18. 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!
  19. 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
  20. 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)
  21. 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
  22. 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!
  23. STEP #0 The worst case — Sub-suite (500 examples) —

    Run-time – 7 minutes — DB* time – 3 minutes * raw DB time, without ActiveRecord overhead
  24. 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
  25. PROFILING — Take a look at your code — General

    profilers (ruby prof, stackprof) — ActiveSupport instrumentation
  26. STEP #1 Transactional tests (baseline) — Sub-suite (500 examples) —

    Run-time – 4 minutes 40 seconds — DB time – 1 minute 10 seconds 1.5x faster
  27. EXCESS DATA context "test pagination" do # page size is

    40 before { create_list(:post, 41) } it "shows second page" do end end
  28. 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
  29. 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
  30. 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
  31. 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
  32. 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
  33. factory :comment do answer author end factory :answer do question

    author end factory :question do author end
  34. factory :comment do answer author end factory :answer do question

    author end factory :question do author end create(:comment) # creates 5 records
  35. FACTORY STACK create(:comment) # stack = [ # :comment, #

    :answer, # :question, # :user, # :user, # :user # ]
  36. 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
  37. 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
  38. CASCADE FIX #1 factory :stage do funnel end create(:stage, funnel:

    funnel) # raise ActiveRecord Invalid # account can't be blank
  39. CASCADE FIX #2 factory :stage do funnel account do funnel&.account

    build(:account) end end create(:stage, funnel: funnel) # OK
  40. CASCADE FIX #3 user = create_default(:user) question = create_default(:question) answer

    = create(:answer) answer.question question answer.user question.user user
  41. 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
  42. PROFILING — Take a look at your code — General

    profilers (ruby prof, stackprof) — ActiveSupport instrumentation — Factory profilers (FactoryProf, FactoryDoctor)
  43. 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
  44. 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
  45. 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
  46. 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) }
  47. 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
  48. 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?
  49. 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
  50. 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
  51. 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
  52. 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
  53. 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
  54. 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
  55. 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
  56. 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
  57. FUTURE — Sub-suite (500 examples) — Run-time – 1 minutes

    25 seconds — DB time – 30 seconds 3x faster than the baseline
  58. 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
  59. 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
  60. 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
  61. 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
  62. BOOT TIME — Split helpers (rails_helper.rb, spec_helper.rb, features_helper.rb, etc) —

    Try bootsnap (released 2 days ago) — Use code preloaders
  63. THE SURVEY Q: Do you use code preloaders such as

    Spring, Zeus? Spring Zeus 57% 3% Nothing 40%
  64. 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! "