[RailsClub Moscow 2017] Faster Tests

52cc8a838bf44a589d2572833b2dd1b9?s=47 Vlad Dem
September 23, 2017

[RailsClub Moscow 2017] Faster Tests

Video [RU]: https://www.youtube.com/watch?v=8S7oHjEiVzs

The test suite’s run time increases as our application evolves. We don’t care until we found ourselves wasting too much time waiting for the green light.

I want to share some tips & tricks on how to profile your test suite, detect bottlenecks and, of course, how to fix them.

Links:

- TestProf Github https://github.com/palkan/test-prof

- TestProf: a good doctor for slow Ruby tests https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests

- TestProf Map https://goo.gl/S2TV1Q

- Tips to improve speed of your test suite https://medium.com/appaloosa-store-engineering/tips-to-improve-speed-of-your-test-suite-8418b485205c

- Speed Up Your Rails Test Suite By 6% In 1 Line https://jtway.co/speed-up-your-rails-test-suite-by-6-in-1-line-13fedb869ec4

- Improving spec speed in a huge, old Rails app https://goiabada.blog/improving-spec-speed-in-a-huge-old-rails-app-8f3ab05a33f9

- Sidekiq Shame PR https://github.com/mperham/sidekiq/issues/3495

- Cult Of Martians http://cultofmartians.com

52cc8a838bf44a589d2572833b2dd1b9?s=128

Vlad Dem

September 23, 2017
Tweet

Transcript

  1. Faster Tests Vladimir Dementyev, Evil Martians 2017

  2. / 99 |> | ETA: 39:45:00 2

  3. / 99 Evil Martians 3 |=> | ETA: 39:36:00

  4. RailsClub 2016

  5. / 99 AnyCable 5 |==> | ETA: 39:10:00

  6. / 99 This Talk 6 |===> | ETA: 39:01:00

  7. / 99 Testing *slap shit together and deploy 7 |===>

    | ETA: 38:46:00
  8. / 99 8 |====> | ETA: 38:32:00

  9. / 99 The Survey Do you write tests? 9 |====>

    | ETA: 38:21:00
  10. / 99 The Survey How long does your whole suite

    run? *having more than 1000 examples 10 |======> | ETA: 38:07:00
  11. / 99 The Survey How long does your whole suite

    run? 11 |======> | ETA: 37:55:00 *having more than 2500 examples
  12. / 99 The Story 12 |======> | ETA: 37:45:00

  13. / 99 The Story OnboardIQ (October, 2016) 12 |======> |

    ETA: 37:45:00
  14. / 99 The Story OnboardIQ (October, 2016) ~3700 test examples

    12 |======> | ETA: 37:45:00
  15. / 99 The Story OnboardIQ (October, 2016) ~3700 test examples

    20–22 minutes on CI (no parallelism) 12 |======> | ETA: 37:45:00
  16. None
  17. / 99 The Story OnboardIQ (October, 2016) ~3700 test examples

    20–22 minutes on CI (no parallelism) Sometimes builds spent hours in a queue 14 |=======> | ETA: 37:07:00
  18. None
  19. / 99 The Story OnboardIQ (October, 2016) ~3700 test examples

    5 minutes on another CI (5x parallelism) 16 |========> | ETA: 36:48:00
  20. / 99 The Story OnboardIQ (October, 2016) ~3700 test examples

    5 minutes on another CI (5x parallelism) 9 minutes total (setup, tests, linters) 16 |========> | ETA: 36:48:00
  21. / 99 More Tests Number of examples 0 2000 4000

    6000 8000 Oct 16 Dec 16 Feb 17 Apr 17 June 17 Sep 17 17 |=========> | ETA: 35:45:00
  22. / 99 The Story OnboardIQ (present time) ~7700 test examples

    2.5 minutes on CI (5x parallelism) 18 |=========> | ETA: 35:21:00
  23. / 99 The Story OnboardIQ (present time) ~7700 test examples

    2.5 minutes on CI (5x parallelism) 5 minutes total (setup, tests, linters) 18 |=========> | ETA: 35:21:00
  24. / 99 The Story OnboardIQ (present time) ~7700 test examples

    2.5 minutes on CI (5x parallelism) 5 minutes total (setup, tests, linters) 4x faster! 18 |=========> | ETA: 35:21:00
  25. / 99 Making Faster Examples per minute 0 150 300

    450 600 Oct 16 Dec 16 Feb 17 Apr 17 June 17 Sep 17 19 |==========> | ETA: 35:02:00
  26. / 99 How Did We Get Here? 20 |==========> |

    ETA: 34:44:00
  27. / 99 What We Use RSpec https://rspec.info FactoryGirl (for both

    factories and fixtures) 21 |===========> | ETA: 34:26:00
  28. None
  29. None
  30. / 99 Legacy Constraints No application code refactoring Least possible

    amount of tests refactoring 3 years old RoR app, 90k (57k tests) LOC 24 |============> | ETA: 33:31:00
  31. https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests

  32. / 99 TestProf Map 26 https://goo.gl/S2TV1Q |============> | ETA: 33:00:00

  33. / 99 General Profilers RubyProf StackProf 27 |=============> | ETA:

    32:39:00
  34. / 99 StackProf $ TEST_STACK_PROF=1 rspec spec/models/user_spec.rb $ stackprof tmp/test_prof/stackprof-cpu.dump

    TOTAL(pct) SAMPLES (pct) FRAME 2409 (25.5%) 988 (10.4%) AR…#exec_no_cache 2235 (23.6%) 935 (9.9%) AR…#execute 1287 (13.6%) 641 (6.8%) Logger ::LogDevice#write 130 (1.4%) 65 (0.7%) Mongo ::Socket#write https://medium.com/appaloosa-store-engineering/tips-to-improve-speed-of-your-test-suite-8418b485205c 28 |==============> | ETA: 31:41:00
  35. / 99 StackProf $ TEST_STACK_PROF=1 rspec spec/models/user_spec.rb $ stackprof tmp/test_prof/stackprof-cpu.dump

    TOTAL(pct) SAMPLES (pct) FRAME 2409 (25.5%) 988 (10.4%) AR…#exec_no_cache 2235 (23.6%) 935 (9.9%) AR…#execute 1287 (13.6%) 641 (6.8%) Logger ::LogDevice#write 130 (1.4%) 65 (0.7%) Mongo ::Socket#write https://medium.com/appaloosa-store-engineering/tips-to-improve-speed-of-your-test-suite-8418b485205c 28 |==============> | ETA: 31:41:00
  36. / 99 PROTIP #0 https://jtway.co/speed-up-your-rails-test-suite-by-6-in-1-line-13fedb869ec4 config.logger = Logger.new(nil) config.log_level =

    :fatal “Speed Up Your Rails Test Suite By 6% In 1 Line” 29 |==============> | ETA: 31:02:00
  37. / 99 RubyProf $ SAMPLE=10 TEST_RUBY_PROF=1 rspec $ more tmp/test_prof/ruby-prof—report-flat-total.log

    %self calls name 20.85 721 <Class ::BCrypt ::Engine># __bc_crypt 1.12 47489 Arel ::Visitors ::Visitor#dispatch 1.04 205208 String#to_s 30 |===============> | ETA: 30:20:00
  38. / 99 RubyProf $ SAMPLE=10 TEST_RUBY_PROF=1 rspec $ more tmp/test_prof/ruby-prof—report-flat-total.log

    %self calls name 20.85 721 <Class ::BCrypt ::Engine># __bc_crypt 1.12 47489 Arel ::Visitors ::Visitor#dispatch 1.04 205208 String#to_s 30 |===============> | ETA: 30:20:00
  39. / 99 Encryption in Tests # Gemfile gem "sorcery" #

    config/initializers/sorcery.rb config.user_config do |user| # default is 10 for bcrypt! user.stretches = 1 if Rails.env.test? end 31 |===============> | ETA: 29:31:00
  40. / 99 Encryption in Tests # Gemfile gem "sorcery" #

    config/initializers/sorcery.rb config.user_config do |user| # default is 10 for bcrypt! user.stretches = 1 if Rails.env.test? end 2x faster! 31 |===============> | ETA: 29:31:00
  41. / 99 32 https://goiabada.blog/improving-spec-speed-in-a-huge-old-rails-app-8f3ab05a33f9 TEST_RUBY_PROF=call_tree rspec |================> | ETA: 28:45:00

  42. / 99 PROTIP #1 SAMPLE=10 TEST_RUBY_PROF=call_stack rspec “Run general profilers

    against a random sub-suite” 33 |=================> | ETA: 28:02:00
  43. / 99 EventProf 34 rspec --profile + ActiveSupport ::Notifications |==================>

    | ETA: 27:40:00
  44. / 99 EventProf 35 $ EVENT_PROF=sql.active_record rspec [TEST PROF INFO]

    EventProf for sql.active_record Total time: 00:00.256 Total events: 1031 Top 5 slowest suites (by time): AnswersController – 00:00.119 (549 / 20) QuestionsController – 00:00.105 (360 / 18) CommentsController – 00:00.032 (122 / 4) |===================> | ETA: 27:07:00
  45. / 99 EventProf Database sql.active_record sql.rom Factories factory_girl.run_factory factory.create 36

    |====================> | ETA: 26:38:00
  46. / 99 FactoryGirl Caveat 37 $ EVENT_PROF=factory_girl.run_factory rspec [TEST PROF

    INFO] EventProf factory_girl.run_factory Total time: 14:28.175 Total events: 455575 Finished in 10 minutes 26 seconds |=====================> | ETA: 25:51:00
  47. / 99 FactoryGirl Caveat 37 $ EVENT_PROF=factory_girl.run_factory rspec [TEST PROF

    INFO] EventProf factory_girl.run_factory Total time: 14:28.175 Total events: 455575 Finished in 10 minutes 26 seconds |=====================> | ETA: 25:51:00
  48. / 99 PROTIP #2 EVENT_PROF=factory.create rspec “Use ‘factory.create’ when profiling

    time spent in factories to avoid double counting; ’factory_girl.run_factory’ events are not exclusive” 38 |======================> | ETA: 25:13:00
  49. / 99 EventProf 39 # Minitest – PR welcome! ruby

    test.rb --event_prof=sql.rom + # Maybe, hanami-events? Custom Instrumentation |=======================> | ETA: 24:41:00
  50. / 99 EventProf Views render_template.action_view render_partial.action_view Background Jobs perform.active_job sidekiq.inline

    40 |========================> | ETA: 24:04:00
  51. / 99 Sidekiq Shame 41 https://github.com/mperham/sidekiq/issues/3495 |=========================> | ETA: 23:37:00

  52. / 99 Sidekiq Inline 42 $ EVENT_PROF=sidekiq.inline rspec [TEST PROF

    INFO] EventProf for sidekiq.inline Total time: 04:28.175 Total events: 15596 Finished in 20 minutes 26 seconds Using Sidekiq ::Testing.inline! by default |==========================> | ETA: 23:01:00
  53. / 99 Sidekiq Inline 43 $ EVENT_PROF=sidekiq.inline rspec [TEST PROF

    INFO] EventProf for sidekiq.inline Total time: 01:31.605 Total events: 3884 Finished in 17 minutes 19 seconds Using Sidekiq ::Testing.fake! by default |===========================> | ETA: 22:22:00
  54. / 99 Sidekiq Inline 43 $ EVENT_PROF=sidekiq.inline rspec [TEST PROF

    INFO] EventProf for sidekiq.inline Total time: 01:31.605 Total events: 3884 Finished in 17 minutes 19 seconds Using Sidekiq ::Testing.fake! by default ~1.2x faster! |===========================> | ETA: 22:22:00
  55. / 99 PROTIP #3 Sidekiq ::Testing.fake! “If you want faster

    tests you can use fake mode and call WorkerUnderTest.drain.” –Nate 44 |============================> | ETA: 21:50:00
  56. / 99 How to migrate? 45 |=============================> | ETA: 21:13:00

  57. / 99 How to migrate? Turn on Sidekiq ::Testing.fake! 45

    |=============================> | ETA: 21:13:00
  58. / 99 How to migrate? Turn on Sidekiq ::Testing.fake! …

    and let the test fail) 45 |=============================> | ETA: 21:13:00
  59. / 99 How to migrate? Prepare shared context 46 shared_context

    "sq:inline", sidekiq: :inline do around(:each) do |ex| Sidekiq ::Testing.inline!(&ex) end end |==============================> | ETA: 21:13:00
  60. / 99 RSpec Stamp Automatically tags failing examples Automatically tags

    slow examples with EventProf … and more 47 $ EVENT_PROF=factory.create \ $ EVENT_PROF_STAMP=slow:factory rspec |===============================> | ETA: 20:25:00
  61. / 99 How to migrate? Run tests again with RSpec

    Stamp 48 $ RSTAMP=sidekiq:inline rspec --only-failures [TEST PROF INFO] RSpec Stamp results Total patches: 175 Total files: 76 |================================> | ETA: 19:54:00
  62. / 99 The Story 49 Oct 2016 Sep 2017 0s

    10s 20s 30s 40s 50s 60s 70s sql.active_record factory.create * profiles for the fixed tests sample |=================================> | ETA: 19:31:00
  63. / 99 Factory Profilers Factory Doctor FactoryProf 50 |==================================> |

    ETA: 19:07:00
  64. / 99 Useless Data 51 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 VS |===================================> | ETA: 18:43:00
  65. / 99 Factory Doctor 52 $ FDOC=1 rspec [TEST PROF

    INFO] FactoryDoctor report Total (potentially) bad examples: 103 Total wasted time: 00:16.803 User (./spec/models/user_spec.rb:3) ./spec/user_spec.rb:8 – 1 record created, 00:00.114 |====================================> | ETA: 18:14:00
  66. / 99 Factory Doctor Sometimes produces false positives/ negatives Integrates

    with RSpec Stamp to tag bad examples automatically 53 |=====================================> | ETA: 17:26:00
  67. / 99 shared_context "fgirl:stub", fgirl: :stub do # Replace create

    with build_stubbed around { |ex| FactoryGirl.stub_all!(&ex) } end describe User do let(:user) { create(:user) } it "is valid", fgirl: :stub do # no database interactions here expect(user).to be_valid end end Factory Stub All 54 |======================================> | ETA: 17:01:00
  68. / 99 shared_context "fgirl:stub", fgirl: :stub do # Replace create

    with build_stubbed around { |ex| FactoryGirl.stub_all!(&ex) } end describe User do let(:user) { create(:user) } it "is valid", fgirl: :stub do # no database interactions here expect(user).to be_valid end end Factory Stub All 54 Work In Progress |======================================> | ETA: 17:01:00
  69. / 99 FactoryProf 55 $ FPROF=1 rspec [TEST PROF INFO]

    Factories usage total top-level name 372 348 account 366 363 funnel 261 261 interview_stage 167 151 user 156 156 applicant 76 76 available_slot 372 examples, 0 failures |=======================================> | ETA: 16:22:00
  70. / 99 FactoryProf 55 $ FPROF=1 rspec [TEST PROF INFO]

    Factories usage total top-level name 372 348 account 366 363 funnel 261 261 interview_stage 167 151 user 156 156 applicant 76 76 available_slot 372 examples, 0 failures What about fixtures? |=======================================> | ETA: 16:22:00
  71. / 99 Step #0 56 describe StagesController do let(:account) {

    create(:account) } let(:funnel) { create(:funnel) } … end |========================================> | ETA: 15:29:00
  72. / 99 Step #1 57 shared_context "account", account: true do

    let(:account) { create(:account) } let(:funnel) { create(:funnel) } end describe StagesController, :account do … end |=========================================> | ETA: 14:50:00
  73. / 99 AnyFixture Accepts any block of code as data

    generator Cleanups affected tables at the end of the whole suite run 58 |==========================================> | ETA: 14:09:00
  74. / 99 Step #2 59 shared_context "account", account: true do

    before(:all) do @account = TestProf ::AnyFixture.register(:account) do create(:account) end @funnel = TestProf ::AnyFixture.register(:funnel) do create(:funnel, account: @account) end end let(:account) { Account.find(@account.id) } let(:funnel) { account.funnels.first } end |===========================================> | ETA: 13:11:00
  75. / 99 60 Factory Cascade |============================================> | ETA: 12:26:00

  76. / 99 Factory Cascade 61 factory :comment do answer author

    end factory :answer do question author end factory :question do author end create(:comment) # => creates 5 records |=============================================> | ETA: 12:10:00
  77. / 99 Factory Cascade How to detect? How to fix?

    62 |==============================================> | ETA: 11:25:00
  78. / 99 63 Factory Flame |===============================================> | ETA: 11:00:00

  79. / 99 63 Factory Flame |===============================================> | ETA: 11:00:00

  80. / 99 Factory Stack 64 create(:comment) # stack = [

    # :comment, # :answer, # :question, # :user, # :user, # :user # ] |================================================> | ETA: 10:38:00
  81. / 99 Factory Story 65 [TEST PROF INFO] EventProf for

    factory.create Total time: 01:02.279 Total events: 88022 Top 5 slowest suites (by time): EmbeddedSignatureRequestsSet – 00:31.630 (121 / 11) EmbeddedSignatureRequest – 00:22.479 (52 / 13) 24 examples – 54 seconds in factories! |=================================================> | ETA: 10:04:00
  82. / 99 Factory Story 66 |==================================================> | ETA: 09:42:00

  83. / 99 Cascade Fix #1 67 Explicitly provide associated objects

    # before factory :embedded_signature_request do requests_set template … end create(:embedded_signature_request) |===================================================> | ETA: 09:42:00
  84. / 99 Cascade Fix #1 68 Explicitly provide associated objects

    # after factory :embedded_signature_request do … end create(:embedded_signature_request, requests_set: set, template: template) # But create(:embedded_signature_request) # raise ActiveRecord ::Invalid |====================================================> | ETA: 09:10:00
  85. / 99 Cascade Fix #2 69 factory :stage do funnel

    account do funnel&.account || build(:account) end end Inherit associated objects Only works with hierarchical data |=====================================================> | ETA: 08:41:00
  86. / 99 Factory Story 70 From 54 seconds to 2

    seconds! |======================================================> | ETA: 08:07:00
  87. / 99 Factory Story #2 71 |=======================================================> | ETA: 07:37:00

  88. / 99 Cascade Fix #3 72 describe MessageTemplates ::Deliver do

    let(:funnel) do create_default(:funnel) end let(:stage) do create_default(:stage, funnel: funnel) end end |========================================================> | ETA: 07:00:00
  89. / 99 FactoryDefault Fix cascades quickly (w/o touching factories) Use

    when many factories depend on some other factory 73 |=========================================================> | ETA: 06:40:00
  90. / 99 Factory Story #2 74 |=========================================================> | ETA: 06:09:00

  91. / 99 Run EventProf for factory.create and mark top-N slowest

    groups 75 $ EVENT_PROF=factory.create \ $ EVENT_PROF_STAMP=slow:factory rspec Factories Flow |==========================================================> | ETA: 06:00:00
  92. / 99 Run FactoryProf for slow groups 76 $ FPROF=1

    rspec --tag slow:factory Consider extracting popular factories into any-fixtures Factories Flow |===========================================================> | ETA: 05:42:00
  93. / 99 Generate FactoryFlame for slow groups 77 $ FPROF=flamegraph

    rspec --tag slow:factory Fix factory cascades (e.g. using FactoryDefault) Factories Flow |===========================================================> | ETA: 05:05:00
  94. / 99 78 RSpec Dissection |==========================================================> | ETA: 04:44:00

  95. / 99 RSpec Dissection 79 $ RD_PROF=1 rspec [TEST PROF

    INFO] RSpecDissect report Total time: 16:11.661 Total `before(:each)` time: 09:28.678 Total `let` time: 12:26.199 Top 10 slowest suites (by `before(:each)` time): … Top 10 slowest suites (by `let` time): … |===========================================================> | ETA: 04:30:00
  96. / 99 RSpec Dissection Useful to detect repeatable data Integrates

    with Rspec Stamp 80 |============================================================> | ETA: 03:54:00
  97. / 99 Run RSpecDissect and mark top-N slowest groups 81

    $ RD_PROF=1 RD_PROF_STAMP=slow:rd rspec Dissection Flow |=============================================================> | ETA: 03:21:00
  98. / 99 Replace before hooks with before_all where possible 82

    Dissection Flow |==============================================================> | ETA: 03:00:00
  99. / 99 Before All 83 before(:all) + Database Transaction |==============================================================>

    | ETA: 02:49:00
  100. / 99 before(:each) 84 describe BeatleSearchQuery 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 |===============================================================> | ETA: 02:31:00
  101. / 99 before_all 85 describe BeatleSearchQuery do before_all 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 |===============================================================> | ETA: 02:12:00
  102. / 99 86 Dissection Flow |================================================================> | ETA: 01:57:00

  103. / 99 Replace let! hooks with let_it_be where possible 86

    Dissection Flow |================================================================> | ETA: 01:57:00
  104. / 99 Let It Be 87 before_all + let |=================================================================>

    | ETA: 01:40:00
  105. / 99 let! 88 describe BeatleSearchQuery do let!(:paul) { create(:beatle,

    :paul) } let!(:ringo) { create(:beatle, :ringo) } let!(:george) { create(:beatle, :george) } let!(:john) { create(:beatle, :john) } # and more examples here end |==================================================================> | ETA: 01:24:00
  106. / 99 let_it_be 89 describe BeatleSearchQuery do let_it_be(:paul) { create(:beatle,

    :paul) } let_it_be(:ringo) { create(:beatle, :ringo) } let_it_be(:george) { create(:beatle, :george) } let_it_be(:john) { create(:beatle, :john) } # and more examples here end |==================================================================> | ETA: 01:01:00
  107. / 99 90 Closing Notes |===================================================================> | ETA: 00:56:00

  108. / 99 What We Learned Test environment should be different

    91 |===================================================================> | ETA: 00:51:00
  109. / 99 What We Learned Test environment should be different

    Make logging less verbose (or turn off completely) 91 |===================================================================> | ETA: 00:51:00
  110. / 99 What We Learned Test environment should be different

    Make logging less verbose (or turn off completely) Relax encryption settings 91 |===================================================================> | ETA: 00:51:00
  111. / 99 What We Learned Background jobs should be controllable

    Sidekiq ::Testing.inline! is evil! 92 |====================================================================> | ETA: 00:42:00
  112. / 99 Prefer build_stubbed over create What We Learned 93

    |=====================================================================> | ETA: 00:36:00
  113. / 99 Prefer build_stubbed over create Use both factories &

    fixtures What We Learned 93 |=====================================================================> | ETA: 00:36:00
  114. / 99 What We Learned Factory cascades are harmful 94

    |=====================================================================> | ETA: 00:31:00
  115. / 99 What We Learned Factory cascades are harmful Avoid

    slow repetitions (i.e. before hooks) 94 |=====================================================================> | ETA: 00:31:00
  116. / 99 What We Learned Factory cascades are harmful Avoid

    slow repetitions (i.e. before hooks) … and let it be! 94 |=====================================================================> | ETA: 00:31:00
  117. / 99 Where 95 github.com/palkan/test-prof |======================================================================> | ETA: 00:24:00

  118. / 99 What’s Left? 96 |======================================================================> | ETA: 00:20:00

  119. / 99 What’s Left? Custom Rubocop cops Thoughts on multi-threaded

    tests (rspec-hell) Controllers vs. requests specs Faster boot time (bootsnap) CI balancing (knapsack) 97 |=======================================================================> | ETA: 00:12:00
  120. cult of martians.com

  121. Thank you! Questions? Vladimir Dementyev evilmartians.com github.com/palkan @palkan_tula Finished in

    40 minutes 99 examples, 0 failures