[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. 10.

    / 99 The Survey How long does your whole suite

    run? *having more than 1000 examples 10 |======> | ETA: 38:07:00
  2. 11.

    / 99 The Survey How long does your whole suite

    run? 11 |======> | ETA: 37:55:00 *having more than 2500 examples
  3. 15.

    / 99 The Story OnboardIQ (October, 2016) ~3700 test examples

    20–22 minutes on CI (no parallelism) 12 |======> | ETA: 37:45:00
  4. 16.
  5. 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
  6. 18.
  7. 19.

    / 99 The Story OnboardIQ (October, 2016) ~3700 test examples

    5 minutes on another CI (5x parallelism) 16 |========> | ETA: 36:48:00
  8. 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
  9. 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
  10. 22.

    / 99 The Story OnboardIQ (present time) ~7700 test examples

    2.5 minutes on CI (5x parallelism) 18 |=========> | ETA: 35:21:00
  11. 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
  12. 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
  13. 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
  14. 27.

    / 99 What We Use RSpec https://rspec.info FactoryGirl (for both

    factories and fixtures) 21 |===========> | ETA: 34:26:00
  15. 28.
  16. 29.
  17. 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
  18. 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
  19. 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
  20. 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
  21. 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
  22. 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
  23. 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
  24. 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
  25. 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
  26. 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
  27. 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
  28. 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
  29. 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
  30. 49.

    / 99 EventProf 39 # Minitest – PR welcome! ruby

    test.rb --event_prof=sql.rom + # Maybe, hanami-events? Custom Instrumentation |=======================> | ETA: 24:41:00
  31. 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
  32. 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
  33. 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
  34. 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
  35. 57.

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

    |=============================> | ETA: 21:13:00
  36. 58.

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

    and let the test fail) 45 |=============================> | ETA: 21:13:00
  37. 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
  38. 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
  39. 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
  40. 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
  41. 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
  42. 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
  43. 66.

    / 99 Factory Doctor Sometimes produces false positives/ negatives Integrates

    with RSpec Stamp to tag bad examples automatically 53 |=====================================> | ETA: 17:26:00
  44. 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
  45. 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
  46. 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
  47. 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
  48. 71.

    / 99 Step #0 56 describe StagesController do let(:account) {

    create(:account) } let(:funnel) { create(:funnel) } … end |========================================> | ETA: 15:29:00
  49. 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
  50. 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
  51. 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
  52. 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
  53. 77.

    / 99 Factory Cascade How to detect? How to fix?

    62 |==============================================> | ETA: 11:25:00
  54. 80.

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

    # :comment, # :answer, # :question, # :user, # :user, # :user # ] |================================================> | ETA: 10:38:00
  55. 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
  56. 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
  57. 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
  58. 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
  59. 86.

    / 99 Factory Story 70 From 54 seconds to 2

    seconds! |======================================================> | ETA: 08:07:00
  60. 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
  61. 89.

    / 99 FactoryDefault Fix cascades quickly (w/o touching factories) Use

    when many factories depend on some other factory 73 |=========================================================> | ETA: 06:40:00
  62. 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
  63. 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
  64. 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
  65. 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
  66. 96.

    / 99 RSpec Dissection Useful to detect repeatable data Integrates

    with Rspec Stamp 80 |============================================================> | ETA: 03:54:00
  67. 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
  68. 98.

    / 99 Replace before hooks with before_all where possible 82

    Dissection Flow |==============================================================> | ETA: 03:00:00
  69. 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
  70. 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
  71. 103.

    / 99 Replace let! hooks with let_it_be where possible 86

    Dissection Flow |================================================================> | ETA: 01:57:00
  72. 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
  73. 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
  74. 108.

    / 99 What We Learned Test environment should be different

    91 |===================================================================> | ETA: 00:51:00
  75. 109.

    / 99 What We Learned Test environment should be different

    Make logging less verbose (or turn off completely) 91 |===================================================================> | ETA: 00:51:00
  76. 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
  77. 111.

    / 99 What We Learned Background jobs should be controllable

    Sidekiq ::Testing.inline! is evil! 92 |====================================================================> | ETA: 00:42:00
  78. 112.

    / 99 Prefer build_stubbed over create What We Learned 93

    |=====================================================================> | ETA: 00:36:00
  79. 113.

    / 99 Prefer build_stubbed over create Use both factories &

    fixtures What We Learned 93 |=====================================================================> | ETA: 00:36:00
  80. 114.

    / 99 What We Learned Factory cascades are harmful 94

    |=====================================================================> | ETA: 00:31:00
  81. 115.

    / 99 What We Learned Factory cascades are harmful Avoid

    slow repetitions (i.e. before hooks) 94 |=====================================================================> | ETA: 00:31:00
  82. 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
  83. 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