[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

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