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. RUN TEST RUN
    Vladimir Dementyev, Evil Martians
    RubyConfBy, 2017

    View Slide

  2. View Slide

  3. View Slide

  4. EVIL OPEN SOURCE

    View Slide

  5. View Slide

  6. THIS TALK

    View Slide

  7. TESTING
    * slap shit together and deploy

    View Slide

  8. PROFILING
    * Gorbypuff

    View Slide

  9. AUTOMATION

    View Slide

  10. LEGACY
    * But it's not by foot

    View Slide

  11. THE QUESTION

    View Slide

  12. THE SURVEY
    Q: Do you write tests?
    Yes
    No
    94%
    6%
    * Conducted on Feb, 2017, about 200 respondents

    View Slide

  13. THE SURVEY
    Q: How long does your whole suite run?

    View Slide

  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%

    View Slide

  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%

    View Slide

  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

    View Slide

  17. View Slide

  18. THE STORY
    OnboardIQ (Oct, 2016)
    — ~3700 tests
    — 20-22 minutes* on TravisCI (no
    parallelism)
    — Sometimes build spent hours in a queue
    * only RSpec

    View Slide

  19. View Slide

  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

    View Slide

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

    View Slide

  22. THE STORY
    OnboardIQ (Mar, 2017)
    — ~6100 tests
    — 2.5 minutes on CircleCI (5x parallelism)
    1.6x more tests – 1.6x faster

    View Slide

  23. THE SETUP

    View Slide

  24. THE SETUP
    — RSpec http://rspec.info

    View Slide

  25. View Slide

  26. THE SURVEY
    Q: Which testing framework do you use?
    RSpec
    Other
    80%
    2%
    MiniT
    est
    18%

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

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

    View Slide

  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

    View Slide

  32. View Slide

  33. THE SETUP
    — RSpec http://rspec.info
    — FactoryGirl

    View Slide

  34. THE SETUP
    — RSpec http://rspec.info
    — FactoryGirl (for both factories and
    fixtures )

    View Slide

  35. STEP #0
    The worst case
    — Sub-suite (500 examples)
    — Run-time – 7 minutes

    View Slide

  36. PROFILING

    View Slide

  37. PROFILING
    — General profilers (ruby prof, stackprof)

    View Slide

  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 #current
    0.96 16038 *ActiveRecord AttributeMethods #primary_key

    View Slide

  39. ENCRYPTION STORY
    %self calls name
    20.85 721 # 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

    View Slide

  40. ENCRYPTION STORY
    %self calls name
    20.85 721 # 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"

    View Slide

  41. ENCRYPTION STORY
    # Sorcery config
    config.user_config do |config|
    # default is 10 for bcrypt!
    config.stretches = 1 if Rails.env.test?
    end

    View Slide

  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!

    View Slide

  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

    View Slide

  44. * script example can be found here

    View Slide

  45. * script example can be found here

    View Slide

  46. * script example can be found here

    View Slide

  47. STACKPROF
    * http://www.brendangregg.com/flamegraphs.html

    View Slide

  48. STACKPROF
    * http://www.brendangregg.com/flamegraphs.html

    View Slide

  49. STACKPROF
    * http://www.brendangregg.com/flamegraphs.html

    View Slide

  50. PROFILING
    — General profilers (ruby prof, stackprof)
    — ActiveSupport instrumentation

    View Slide

  51. EVENT PROFILER
    PROF_EVENT='sql.active_record' rspec

    View Slide

  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)

    View Slide

  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

    View Slide

  54. EVENT PROFILER
    PROF_EVENT='factory_girl.run_factory' rspec

    View Slide

  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!

    View Slide

  56. STEP #0
    The worst case
    — Sub-suite (500 examples)
    — Run-time – 7 minutes
    — DB* time – 3 minutes
    * raw DB time, without ActiveRecord overhead

    View Slide

  57. DB CLEANER STORY

    View Slide

  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

    View Slide

  59. View Slide

  60. View Slide

  61. gem "test_after_commit" # or Rails 5

    View Slide

  62. PROFILING
    — Take a look at your code
    — General profilers (ruby prof, stackprof)
    — ActiveSupport instrumentation

    View Slide

  63. View Slide

  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

    View Slide

  65. DATA GENERATION

    View Slide

  66. DATA GENERATION
    Slow Parts
    — Excess Data

    View Slide

  67. EXCESS DATA
    context "test pagination" do
    # page size is 40
    before { create_list(:post, 41) }
    it "shows second page" do
    end
    end

    View Slide

  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

    View Slide

  69. EXCESS DATA
    it "validates name presence" do
    user = create(:user)
    expect(user).not_to be_valid
    end

    View Slide

  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

    View Slide

  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

    View Slide

  72. FACTORY DOCTOR

    View Slide

  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

    View Slide

  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

    View Slide

  75. DATA GENERATION
    Slow Parts
    — Excess Data
    — Factory Cascade

    View Slide

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

    View Slide

  77. factory :comment do
    answer
    author
    end
    factory :answer do
    question
    author
    end
    factory :question do
    author
    end
    create(:comment) # creates 5 records

    View Slide

  78. FACTORY PROF

    View Slide

  79. FACTORY PROF
    Factory flame graphs

    View Slide

  80. FACTORY STACK
    create(:comment)
    # stack = [
    # :comment,
    # :answer,
    # :question,
    # :user,
    # :user,
    # :user
    # ]

    View Slide

  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

    View Slide

  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

    View Slide

  83. CASCADE FIX #1
    factory :stage do
    funnel
    end
    create(:stage, funnel: funnel)
    # raise ActiveRecord Invalid
    # account can't be blank

    View Slide

  84. CASCADE FIX #2
    factory :stage do
    funnel
    account do
    funnel&.account build(:account)
    end
    end
    create(:stage, funnel: funnel)
    # OK

    View Slide

  85. CASCADE FIX #3
    user = create_default(:user)
    question = create_default(:question)
    answer = create(:answer)
    answer.question question
    answer.user question.user user

    View Slide

  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

    View Slide

  87. W/O FACTORY
    DEFAULT

    View Slide

  88. WITH FACTORY
    DEFAULT

    View Slide

  89. View Slide

  90. PROFILING
    — Take a look at your code
    — General profilers (ruby prof, stackprof)
    — ActiveSupport instrumentation
    — Factory profilers (FactoryProf,
    FactoryDoctor)

    View Slide

  91. DATA GENERATION
    Slow Parts
    — Excess Data
    — Factory Cascade
    — Repeatable Data / Actions

    View Slide

  92. REPEATABLE DATA
    before(:each) do
    # some heavy setup
    end
    it "one" { }
    it "ten" { }

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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) }

    View Slide

  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

    View Slide

  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?

    View Slide

  99. View Slide

  100. View Slide

  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

    View Slide

  102. RUBOCOP
    rubocop only RSpec/AggregateFailures auto correct
    1 offense detected, 1 offense corrected
    * cop can be found here

    View Slide

  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

    View Slide

  104. FIXTURES

    View Slide

  105. View Slide

  106. Almost every test needs account (tenant) and funnel
    (top-level model within a tenant)

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  113. FUTURE
    — Sub-suite (500 examples)
    — Run-time – 1 minutes 25 seconds
    — DB time – 30 seconds
    3x faster than the baseline

    View Slide

  114. THE SETUP
    — MRI
    — RSpec http://rspec.info
    — FactoryGirl

    View Slide

  115. View Slide

  116. MINITEST HELL
    require "minitest/hell"
    class UserControllerTest < MT U Test
    # or
    # parallelize_me!
    end

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  121. BOOT TIME
    — Split helpers (rails_helper.rb,
    spec_helper.rb, features_helper.rb,
    etc)
    — Try bootsnap (released 2 days ago)
    — Use code preloaders

    View Slide

  122. THE SURVEY
    Q: Do you use code preloaders such as
    Spring, Zeus?
    Spring
    Zeus
    57%
    3%
    Nothing
    40%

    View Slide

  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! "

    View Slide

  124. THANKS? QUESTIONS?
    Vladimir Dementyev, Evil Martians
    GitHub: @palkan
    Twitter: @evilmartians, @palkan_tula

    View Slide