[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
   

   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