[BalkanRuby 2018] Take your slow tests to the doctor

[BalkanRuby 2018] Take your slow tests to the doctor

52cc8a838bf44a589d2572833b2dd1b9?s=128

Vlad Dem

May 25, 2018
Tweet

Transcript

  1. 11.

    /82 The Story 11 fountain.com (October, 2016) ~3700 test examples

    ~30 minutes CI (no parallelism) ~22 minutes for RSpec |====> | ETA: 31:24:41
  2. 12.
  3. 14.

    /82 The Story 14 fountain.com (October, 2016) ~3700 test examples

    ~30 minutes CI (no parallelism) ~22 minutes for RSpec |=====> | ETA: 30:57:07
  4. 16.
  5. 17.

    /82 The Story 17 fountain.com (October, 2016) ~3700 test examples

    ~9 minutes CI (5x parallelism) ~5 minutes for RSpec |=======> | ETA: 30:13:30
  6. 18.

    /82 The Grow 18 Number of tests 0 2250 4500

    6750 9000 Oct 16 Dec 16 Feb 17 Apr 17 June 17 Sep 17 Feb 18 May 18 |=======> | ETA: 29:20:38
  7. 20.

    /82 The Story 20 fountain.com (present) ~9000 test examples 7

    minutes on CI (5x parallelism) 3 minutes RSpec 4x faster! |========> | ETA: 28:39:01
  8. 26.

    /82 General Profilers 26 RubyProf StackProf rbspy (not supported by

    TestProf yet) |============> | ETA: 26:54:19
  9. 27.

    /82 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 27 |============> | ETA: 26:41:00
  10. 29.

    /82 PROTIP #0 “Log to standard output when necessary” 29

    require 'test_prof/recipes/logging' https://test-prof.evilmartians.io/#/logging LOG=all bundle exec rspec |=============> | ETA: 26:03:56
  11. 31.

    /82 PROTIP #1 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’ “Save up to 40% by getting rid of database_cleaner” 31 |==============> | ETA: 25:29:05
  12. 32.

    /82 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 32 |===============> | ETA: 24:31:47
  13. 33.

    /82 Encryption in Tests # Gemfile gem "sorcery" # config/initializers/sorcery.rb

    config.user_config do |user| # default was 10 for bcrypt! user.stretches = 1 if Rails.env.test? end 2x faster! 33 |===============> | ETA: 24:10:10
  14. 35.

    /82 What We Learned #1 35 Test environment should be

    different Make logging less verbose (or turn off completely) Relax encryption settings |=================> | ETA: 23:48:08
  15. 38.

    /82 TagProf $ TAG_PROF=type rspec [TEST PROF INFO] TagProf report

    for type type time total %total %time controller 05:34.465 2882 38.52 38.98 service 03:21.967 1421 18.99 23.54 model 02:03.604 1780 23.79 14.41 job 01:08.822 331 4.42 8.02 request 00:51.555 247 3.30 6.01 form 00:25.893 217 2.90 3.02 query 00:15.493 98 1.31 1.81 38 |===================> | ETA: 22:00:01
  16. 41.

    /82 EventProf 41 $ 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: 20:01:42
  17. 42.

    /82 EventProf 42 # Works with Minitest too ruby test.rb

    \ --event-prof=sql.active_record + # Easily integrates with your framework Custom Instrumentation |=====================> | ETA: 19:31:30
  18. 43.

    /82 EventProf 43 “factory.create” Top-level factory calls “sidekiq.inline" Jobs executed

    inline TestProf-provided events |=====================> | ETA: 18:28:13
  19. 45.

    /82 Sidekiq Inline 45 $ 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: 17:58:32
  20. 46.

    /82 Sidekiq Inline 46 $ 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: 17:23:51
  21. 47.

    /82 PROTIP #2 Sidekiq ::Testing.fake! “If you want faster tests

    you can use fake mode and call WorkerUnderTest.drain.” –Nate 47 |========================> | ETA: 16:56:36
  22. 49.

    /82 What We Learned #2 49 TagProf and EventProf helps

    you to localize problems Sidekiq ::Testing.inline! is evil! |=========================> | ETA: 16:01:59
  23. 50.

    /82 The Story 50 Oct 2016 Feb 2018 0s 10s

    20s 30s 40s 50s 60s 70s sql.active_record factory.create * profiles for the fixed tests sample |==========================> | ETA: 15:42:22
  24. 53.

    /82 Useless Data 53 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: 14:44:26
  25. 54.

    /82 Factory Doctor 54 $ 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: 14:00:44
  26. 55.

    /82 Factory All Stub 55 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 |=============================> | ETA: 13:43:17
  27. 56.

    /82 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 ⁉ |=============================> | ETA: 13:05:13
  28. 58.

    /82 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 |==============================> | ETA: 12:24:49
  29. 59.

    /82 Factory Stack 59 create(:comment) # stack = [ #

    :comment, # :answer, # :question, # :user, # :user, # :user # ] |==============================> | ETA: 12:00:07
  30. 61.

    /82 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! |===============================> | ETA: 10:41:47
  31. 63.

    /82 Cascade Fix #1 63 Explicit associations # before factory

    :embedded_signature_request do requests_set template … end create(:embedded_signature_request) |================================> | ETA: 09:45:10
  32. 64.

    /82 Cascade Fix #1 64 Explicit associations # 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:31:46
  33. 65.

    /82 Cascade Fix #2 65 factory :stage do funnel account

    do funnel&.account || build(:account) end end Association inference Doesn’t fit every data model |=================================> | ETA: 08:52:11
  34. 66.

    /82 Cascade Fix #3 66 describe MessageTemplates ::Deliver do let(:funnel)

    do create_default(:funnel) end let(:stage) do create_default(:stage, funnel: funnel) end end |==================================> | ETA: 08:41:01
  35. 67.

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

    when many factories depend on some other factory https://test-prof.evilmartians.io/#/factory_default |===================================> | ETA: 08:29:13
  36. 68.

    /82 FactoryProf 68 $ 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: 08:02:09
  37. 69.

    /82 AnyFixture 69 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 |====================================> | ETA: 07:47:19
  38. 70.

    /82 AnyFixture 70 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 |====================================> | ETA: 06:41:22
  39. 71.

    /82 AnyFixture 71 [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 |====================================> | ETA: 06:10:46
  40. 73.

    /82 What We Learned #3 73 Factory cascades are very

    harmful–diagnose & treat! Do not choose between factories and fixtures–use both! |======================================> | ETA: 05:00:11
  41. 75.

    /82 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 |=======================================> | ETA: 04:22:06
  42. 76.

    /82 before_all 76 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 |=======================================> | ETA: 03:58:21
  43. 77.

    /82 let_it_be 77 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 https://test-prof.evilmartians.io/#/let_it_be |========================================> | ETA: 03:18:16
  44. 78.

    /82 RSpec/AggregateFailures 78 rubocop --only RSpec/AggregateFailures Offenses: create_spec.rb:277:7: C: RSpec/AggregateFailures:

    Use :aggregate_failures instead of one-liners. context 'not valid secure fields' do ... ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 18 files inspected, 1 offense detected https://test-prof.evilmartians.io/#/rubocop |=========================================> | ETA: 02:31:29
  45. 79.

    /82 Tests Could be Faster 79 … if configured properly

    … if code is testable … if you take care |==========================================> | ETA: 02:01:14
  46. 81.

    /82 Dreams, or what’s next? 81 Reporters API (formatters, etc.)

    Multi-threadedness (for Rails 6) Reports viewer UI TestProf CI https://github.com/palkan/test-prof/projects/1 |============================================> | ETA: 01:01:39