[Paris.rb 2018] 99 problems of slow tests

Video: https://www.youtube.com/watch?v=eDMZS_fkRtk)

https://test-prof.evilmartians.io

Transcript

1. TestProf Vladimir Dementyev I GOT 99 PROBLEMS BUT MY TEST AIN’T ONE 99 problems of slow tests
2. palkan_tula palkan 2 @palkan @palkan_tula Vladimir Dementyev 694 489 259 359
3. palkan_tula palkan 3
4. palkan_tula palkan https://evilmartians.com 4
5. palkan_tula palkan https://evilmartians.com 5
6. palkan_tula palkan https://evilmartians.com 6
7. This Talk
8. palkan_tula palkan 99 problems of slow tests 8
9. RAISE YOUR HAND IF YOUR TESTS ARE SLOW
11. palkan_tula palkan fountain.com 11 3700 tests / 22 minutes = 170 TPM 9800 tests / 14 minutes = 700 TPM
12. TestProf
14. Problem #1 Misconfigured Environment TODO: картинко
15. palkan_tula palkan Use general profilers to diagnose environment problems 15
16. palkan_tula palkan General Profilers 16 RubyProf StackProf rbspy
17. palkan_tula palkan $ 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 17 TEST_STACK_PROF
18. palkan_tula palkan #PROTIP 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” 18
19. palkan_tula palkan TEST_RUBY_PROF $ SAMPLE=10 TEST_RUBY_PROF=1 rspec Finished in 1 minute 12 seconds 90 examples, 0 failures $ 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 19
20. palkan_tula palkan Encryption in Tests # config/initializers/sorcery.rb config.user_config do |user| # default was 10 for bcrypt! user.stretches = 1 if Rails.env.test? end 20 $ SAMPLE=10 rspec Finished in 17 seconds 90 examples, 0 failures ~3.5x faster!
21. palkan_tula palkan Encryption in Tests https://github.com/Sorcery/sorcery/pull/81 21
22. palkan_tula palkan Test environment should be configured differently 22
23. palkan_tula palkan TEST_STACK_PROF 23 scenario "visit home page", :sprof do # … end $ bundle exec rspec StackProf report generated: tmp/stack-prof-visit-home-page.dump Run the following command to generate a flame graph report: stackprof --flamegraph tmp/stack-prof-visit-home-page.dump > \ tmp/stack-prof-visit-home-page.html && \ stackprof —flamegraph-viewer=tmp/stack-prof-visit-home-page.html
24. palkan_tula palkan TEST_STACK_PROF 24
25. Problem #2 database_cleaner
26. palkan_tula palkan Why database_cleaner? 26 One database connection per thread No way to use transactional tests with multiple threads* *e.g. Capybara browser tests
27. palkan_tula palkan One database connection per thread No way to use transactional tests with multiple threads Why database_cleaner? 27
28. palkan_tula palkan Rails 5.1 https://github.com/rails/rails/pull/28083 28
29. palkan_tula palkan ActiveRecordSharedConnection 29 https://test-prof.evilmartians.io/#/active_record_shared_connection # Rails 5.1+ # connection is shared out-of-the-box # Rails <5.1 require 'test_prof/recipes/active_record_one_love'
30. palkan_tula palkan Let’s measure the impact of removing database_cleaner with EventProf 30
31. palkan_tula palkan EventProf 31 rspec --profile + ActiveSupport ::Notifications
32. palkan_tula palkan EventProf 32 ruby test.rb --event-prof=sql.active_record + Custom Instrumentation
33. palkan_tula palkan With DatabaseCleaner 33 $ EVENT_PROF=sql.active_record rspec [TEST PROF INFO] EventProf for sql.active_record Total time: 00:04.146 Total events: 259 Top 5 slowest suites (by time): … Finished in 12.32 seconds 8 examples, 0 failures ~30% in database!
34. palkan_tula palkan With Shared Connection 34 $ EVENT_PROF=sql.active_record rspec [TEST PROF INFO] EventProf for sql.active_record Total time: 00:00.152 Total events: 216 Top 5 slowest suites (by time): … Finished in 7.99 seconds 8 examples, 0 failures ~0% in database => 30% faster!
35. palkan_tula palkan You (likely) don’t need database_cleaner 35
36. palkan_tula palkan TEST_STACK_PROF=boot 36
37. Problem #3 Boot Time
38. palkan_tula palkan TEST_STACK_PROF=boot 38
39. palkan_tula palkan EventProf 39 “sidekiq.inline" Jobs executed inline TestProf-provided events
40. Problem #4 Inlined Jobs
41. palkan_tula palkan https://gist.github.com/nateberkopec/3932fce995c9feddd411417fc9bf33bf Sidekiq Shame 41
42. palkan_tula palkan 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 ~25% executing inlined jobs
43. palkan_tula palkan 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 (and inline in-place) ~8% executing inlined jobs, ~15% faster
44. palkan_tula palkan Do not inline background jobs by default 44
45. palkan_tula palkan How to migrate? 45 https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests
46. palkan_tula palkan EventProf 46 User-provided events # lib/work.rb class Work def do(*args) # do something end end # spec_helper.rb TestProf ::EventProf.monitor(Work, 'my.work', :do) NEW!!!
47. Problem #5 Testability of Deps
48. palkan_tula palkan EventProf 48 # Profiling paper_trail functionality TestProf ::EventProf.monitor( PaperTrail ::RecordTrail, 'paper.trail', :record_create, :record_destroy, :record_update, :record_update_columns, :reset_timestamp_attrs_for_update_if_needed )
49. palkan_tula palkan paper.trail 49 $ EVENT_PROF=paper.trail rspec [TEST PROF INFO] EventProf for paper.trail Total time: 00:45.307 Total events: 24244 Finished in 4 minutes 52.3 seconds ~15% versioning model changes
50. palkan_tula palkan paper.trail 50 $ EVENT_PROF=paper.trail rspec [TEST PROF INFO] EventProf for paper.trail Total time: 00:00.339 Total events: 24290 Finished in 3 minutes 54.6 seconds # spec_helper.rb require 'paper_trail/frameworks/rspec ~0.1% versioning model changes
51. palkan_tula palkan Testability of dependencies affects your test suite run time 51
52. Problem #6 create vs. build_stubbed it "validates name" do user = create(:user) expect(user).not_to be_valid end it "validates name" do user = build_stubbed(:user) expect(user).not_to be_valid end
53. palkan_tula palkan Factory Doctor 53 $ 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 https://test-prof.evilmartians.io/#/factory_doctor
54. palkan_tula palkan Factory All Stub 54 require "test_prof/recipes/rspec/factory_all_stub" describe User do let(:user) { create(:user) } it "is valid", factory: :stub do # no database interactions here expect(user).to be_valid end end https://test-prof.evilmartians.io/#/factory_all_stub
55. palkan_tula palkan EventProf 55 “sidekiq.inline" “factory.create” Top-level factory calls TestProf-provided events
56. palkan_tula palkan factory.create 56 $ EVENT_PROF=factory.create rspec [TEST PROF INFO] EventProf for factory.create Total time: 00:58.043 Total events: 1483 Top 5 slowest suites (by time): … Finished in 1 minute 13.15 seconds ⁉
57. Problem #7 Factory Cascades
58. palkan_tula palkan Factory Cascade 58 factory :comment do answer author end factory :answer do question author end factory :question do author end create(:comment) # => creates 5 records
59. palkan_tula palkan Factory Stack 59 create(:comment) # stack = [ # :comment, # :answer, # :question, # :user, # :user, # :user # ]
60. palkan_tula palkan FactoryProf 60 https://test-prof.evilmartians.io/#/factory_prof
61. palkan_tula palkan Factory Story 61 [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!
62. palkan_tula palkan Factory Story 62
63. palkan_tula palkan Factory Story 63 From 54 seconds to 2 seconds!
64. palkan_tula palkan Factory Therapy 64 https://evilmartians.com/chronicles/testprof-2-factory-therapy-for-your-ruby-tests-rspec-minitest
65. palkan_tula palkan FactoryProf 65 $ 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?
66. Problem #8 Repetitive Data Generation
67. palkan_tula palkan –@dgilperez “Using a combination of FactoryDefault, AnyFixture and let_it_be we just reduced times … from 25 minutes to 16 seconds.” 67 https://github.com/palkan/test-prof/issues/73
68. palkan_tula palkan AnyFixture 68 Accepts any block of code as data generator Cleanups affected tables at the end of the whole suite run https://test-prof.evilmartians.io/#/any_fixture
69. palkan_tula palkan AnyFixture 69 using TestProf ::AnyFixture ::DSL using TestProf ::Ext ::ActiveRecordRefind shared_context "shared account", account: true do prepend_before(:all) do account = fixture(:account) { create :account, name: 'Star Wars' } funnel = fixture(:funnel) { create :funnel, account: account, name: 'Tatooine' } luke = fixture(:luke) { create :applicant, funnel: funnel, name: 'Luke Skywalker', email: 'luke@sw.spec' } end %i[account funnel luke].each { |id| let(id) { fixture(id).refind } end http://bit.ly/any-fixture
70. palkan_tula palkan AnyFixture 70 [TEST PROF INFO] AnyFixture stats: key build time hit count saved time account 00:00.143 2422 05:47.871 another_account 00:00.424 380 02:41.365 funnel 00:00.018 103 00:01.864 Total time spent: 00:00.794 Total time saved: 08:47.952 Finished in 7 minutes 52 seconds 3158 examples, 0 failures ~50% faster with AnyFixture
71. palkan_tula palkan Do not choose between factories and fixtures–use both! 71
72. Problem #9 Repetitive Setup test do setup exercise verify teardown end
73. palkan_tula palkan before 73 describe BeatleSearchQuery do before 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
74. palkan_tula palkan let 74 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
75. palkan_tula palkan RSpec Dissection 75 $ 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):… https://test-prof.evilmartians.io/#/rspec_dissect
76. palkan_tula palkan RSpec Dissection 76 $ RD_PROF=let rspec [TEST PROF INFO] RSpecDissect report Top 10 slowest suites (by `let` time): booking_spec.rb:3 – 00:05.843 of 00:06.832 (33) ↳ booking – 94 ↳ occupancy – 64 ↳ error – 21 https://test-prof.evilmartians.io/#/rspec_dissect
77. palkan_tula palkan 77
78. palkan_tula palkan 78 before_all let_it_be
79. palkan_tula palkan before_all 79 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 https://test-prof.evilmartians.io/#/before_all
80. palkan_tula palkan let_it_be 80 https://test-prof.evilmartians.io/#/let_it_be 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
81. palkan_tula palkan Use before_all and let_it_be to share setup between tests 81
82. palkan_tula palkan before_all 82 class MyBeatlesTest < Minitest ::Test include TestProf ::BeforeAll ::Minitest before_all do @paul = create(:beatle, name: 'Paul') @ringo = create(:beatle, name: 'Ringo') @george = create(:beatle, name: 'George') @john = create(:beatle, name: 'John') end # define tests which could access the object defined within `before_all` end https://test-prof.evilmartians.io/#/before_all NEW!!!
83. Problem #10 One Assertion per Test
84. palkan_tula palkan 84 # some_mailer_spec.rb subject { described_class.request_email(request) } it { is_expected.to have_subject(“Welcome") } it { is_expected.to be_delivered_from(“test@examle.com") } it { is_expected.to be_delivered_to('tester@foo.com') } it { is_expected.to have_body_text(request_link) } $ rspec spec/mailers/some_mailer_spec.rb Finished in 14.43 seconds 59 examples, 0 failures
85. palkan_tula palkan 85 # some_mailer_spec.rb subject { described_class.request_email(request) } it "works", :aggregate_failures do is_expected.to have_subject("Welcome") is_expected.to be_delivered_from("test@examle.com") is_expected.to be_delivered_to('tester@foo.com') is_expected.to have_body_text(request_link) end $ rspec spec/mailers/some_mailer_spec.rb Finished in 3.39 seconds 17 examples, 0 failures ~3.5x faster!
86. palkan_tula palkan RSpec/AggregateFailures 86 rubocop --only RSpec/AggregateFailures -a Offenses: create_spec.rb:277:7: C: RSpec/AggregateFailures: Use :aggregate_failures instead of one-liners. context 'not valid secure fields' do ... ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 1 offense detected, 1 offense corrected https://test-prof.evilmartians.io/#/rubocop
87. Problems #11-99 It’s You
88. palkan_tula palkan github.com/palkan/test-prof https://test-prof.evilmartians.io TestProf 88 v0.6.0 (2018-06-28)
89. Merci! Vladimir Dementyev evilmartians.com/blog @palkan @palkan_tula @evilmartians