[Paris.rb 2018] 99 problems of slow tests

by Vladimir Dementyev

Slide 1

Slide 1 text

TestProf Vladimir Dementyev I GOT 99 PROBLEMS BUT MY TEST AIN’T ONE 99 problems of slow tests

Slide 2

Slide 2 text

palkan_tula palkan 2 @palkan @palkan_tula Vladimir Dementyev 694 489 259 359

Slide 3

Slide 3 text

palkan_tula palkan 3

Slide 4

Slide 4 text

palkan_tula palkan https://evilmartians.com 4

Slide 5

Slide 5 text

palkan_tula palkan https://evilmartians.com 5

Slide 6

Slide 6 text

palkan_tula palkan https://evilmartians.com 6

Slide 7

Slide 7 text

This Talk

Slide 8

Slide 8 text

palkan_tula palkan 99 problems of slow tests 8

Slide 9

Slide 9 text

RAISE YOUR HAND IF YOUR TESTS ARE SLOW

Slide 10

Slide 10 text

No content

Slide 11

Slide 11 text

palkan_tula palkan fountain.com 11 3700 tests / 22 minutes = 170 TPM 9800 tests / 14 minutes = 700 TPM

Slide 12

Slide 12 text

TestProf

Slide 13

Slide 13 text

No content

Slide 14

Slide 14 text

Problem #1 Misconﬁgured Environment TODO: картинко

Slide 15

Slide 15 text

palkan_tula palkan Use general proﬁlers to diagnose environment problems 15

Slide 16

Slide 16 text

palkan_tula palkan General Proﬁlers 16 RubyProf StackProf rbspy

Slide 17

Slide 17 text

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

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

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 # __bc_crypt 1.12 47489 Arel ::Visitors ::Visitor#dispatch 1.04 205208 String#to_s 19

Slide 20

Slide 20 text

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!

Slide 21

Slide 21 text

palkan_tula palkan Encryption in Tests https://github.com/Sorcery/sorcery/pull/81 21

Slide 22

Slide 22 text

palkan_tula palkan Test environment should be conﬁgured differently 22

Slide 23

Slide 23 text

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

Slide 24

Slide 24 text

palkan_tula palkan TEST_STACK_PROF 24

Slide 25

Slide 25 text

Problem #2 database_cleaner

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

palkan_tula palkan One database connection per thread No way to use transactional tests with multiple threads Why database_cleaner? 27

Slide 28

Slide 28 text

palkan_tula palkan Rails 5.1 https://github.com/rails/rails/pull/28083 28

Slide 29

Slide 29 text

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'

Slide 30

Slide 30 text

palkan_tula palkan Let’s measure the impact of removing database_cleaner with EventProf 30

Slide 31

Slide 31 text

palkan_tula palkan EventProf 31 rspec --profile + ActiveSupport ::Notifications

Slide 32

Slide 32 text

palkan_tula palkan EventProf 32 ruby test.rb --event-prof=sql.active_record + Custom Instrumentation

Slide 33

Slide 33 text

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!

Slide 34

Slide 34 text

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!

Slide 35

Slide 35 text

palkan_tula palkan You (likely) don’t need database_cleaner 35

Slide 36

Slide 36 text

palkan_tula palkan TEST_STACK_PROF=boot 36

Slide 37

Slide 37 text

Problem #3 Boot Time

Slide 38

Slide 38 text

palkan_tula palkan TEST_STACK_PROF=boot 38

Slide 39

Slide 39 text

palkan_tula palkan EventProf 39 “sidekiq.inline" Jobs executed inline TestProf-provided events

Slide 40

Slide 40 text

Problem #4 Inlined Jobs

Slide 41

Slide 41 text

palkan_tula palkan https://gist.github.com/nateberkopec/3932fce995c9feddd411417fc9bf33bf Sidekiq Shame 41

Slide 42

Slide 42 text

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

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

palkan_tula palkan Do not inline background jobs by default 44

Slide 45

Slide 45 text

palkan_tula palkan How to migrate? 45 https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

Problem #5 Testability of Deps

Slide 48

Slide 48 text

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 )

Slide 49

Slide 49 text

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

Slide 50

Slide 50 text

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

Slide 51

Slide 51 text

palkan_tula palkan Testability of dependencies affects your test suite run time 51

Slide 52

Slide 52 text

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

Slide 53

Slide 53 text

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

Slide 54

Slide 54 text

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

Slide 55

Slide 55 text

palkan_tula palkan EventProf 55 “sidekiq.inline" “factory.create” Top-level factory calls TestProf-provided events

Slide 56

Slide 56 text

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 ⁉

Slide 57

Slide 57 text

Problem #7 Factory Cascades

Slide 58

Slide 58 text

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

Slide 59

Slide 59 text

palkan_tula palkan Factory Stack 59 create(:comment) # stack = [ # :comment, # :answer, # :question, # :user, # :user, # :user # ]

Slide 60

Slide 60 text

palkan_tula palkan FactoryProf 60 https://test-prof.evilmartians.io/#/factory_prof

Slide 61

Slide 61 text

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!

Slide 62

Slide 62 text

palkan_tula palkan Factory Story 62

Slide 63

Slide 63 text

palkan_tula palkan Factory Story 63 From 54 seconds to 2 seconds!

Slide 64

Slide 64 text

palkan_tula palkan Factory Therapy 64 https://evilmartians.com/chronicles/testprof-2-factory-therapy-for-your-ruby-tests-rspec-minitest

Slide 65

Slide 65 text

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 ﬁxtures?

Slide 66

Slide 66 text

Problem #8 Repetitive Data Generation

Slide 67

Slide 67 text

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

Slide 68

Slide 68 text

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_ﬁxture

Slide 69

Slide 69 text

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: '[email protected]' } end %i[account funnel luke].each { |id| let(id) { fixture(id).refind } end http://bit.ly/any-ﬁxture

Slide 70

Slide 70 text

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

Slide 71

Slide 71 text

palkan_tula palkan Do not choose between factories and ﬁxtures–use both! 71

Slide 72

Slide 72 text

Problem #9 Repetitive Setup test do setup exercise verify teardown end

Slide 73

Slide 73 text

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

Slide 74

Slide 74 text

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

Slide 75

Slide 75 text

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

Slide 76

Slide 76 text

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

Slide 77

Slide 77 text

palkan_tula palkan 77

Slide 78

Slide 78 text

palkan_tula palkan 78 before_all let_it_be

Slide 79

Slide 79 text

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

Slide 80

Slide 80 text

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

Slide 81

Slide 81 text

palkan_tula palkan Use before_all and let_it_be to share setup between tests 81

Slide 82

Slide 82 text

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

Slide 83

Slide 83 text

Problem #10 One Assertion per Test

Slide 84

Slide 84 text

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(“[email protected]") } it { is_expected.to be_delivered_to('[email protected]') } 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

Slide 85

Slide 85 text

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("[email protected]") is_expected.to be_delivered_to('[email protected]') 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!

Slide 86

Slide 86 text

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

Slide 87

Slide 87 text

Problems #11-99 It’s You

Slide 88

Slide 88 text

palkan_tula palkan github.com/palkan/test-prof https://test-prof.evilmartians.io TestProf 88 v0.6.0 (2018-06-28)

Slide 89

Slide 89 text

Merci! Vladimir Dementyev evilmartians.com/blog @palkan @palkan_tula @evilmartians