Upgrade to Pro — share decks privately, control downloads, hide ads and more …

[BalkanRuby 2018] Take your slow tests to the doctor

[BalkanRuby 2018] Take your slow tests to the doctor

52cc8a838bf44a589d2572833b2dd1b9?s=128

Vladimir Dementyev

May 25, 2018
Tweet

Transcript

  1. TestProf Vladimir Dementyev Take Your Slow Tests To The Doctor

  2. /82 2 Vladimir Dementyev |> | ETA: 34:45:21

  3. /82 3 ! Москва ✈ # София |> | ETA:

    34:37:39
  4. /82 4 @palkan @palkan_tula |=> | ETA: 34:21:00

  5. /82 5 |==> | ETA: 34:05:56

  6. /82 https://evilmartians.com 6 |==> | ETA: 33:57:21

  7. /82 https://evilmartians.com 7 |===> | ETA: 33:41:04

  8. This Talk

  9. Part 1 The Story

  10. RAISE YOUR HAND IF YOUR TESTS ARE SLOW

  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
  12. None
  13. © sponsored by

  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
  15. /82 parallelize_me! * @eileencodes at RailsConf 2018 15 |======> |

    ETA: 30:48:43
  16. The End

  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
  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
  19. /82 Horizontal Scaling? *https://speakerdeck.com/kirs/railsclub-2016 19 |========> | ETA: 29:03:00

  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
  21. /82 How Did We Get Here? 21 |=========> | ETA:

    28:30:44
  22. Part 2 TestProf

  23. /82 TestProf is a Doctor 23 |==========> | ETA: 27:53:15

  24. /82 TestProf Map 24 |===========> | ETA: 27:21:48

  25. Diagnostics #1 General Profilers

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

    TestProf yet) |============> | ETA: 26:54:19
  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
  28. /82 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” 28 |=============> | ETA: 26:20:37
  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
  30. /82 StackProf *single example profile 30 |==============> | ETA: 25:55:19

  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
  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
  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
  34. /82 Encryption in Tests https://github.com/Sorcery/sorcery/pull/81 34 |================> | ETA: 24:03:41

  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
  36. Diagnostics #2 Special Profilers

  37. /82 Special Profilers 37 TagProf EventProf |==================> | ETA: 23:11:54

  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
  39. /82 TagProf 39 |===================> | ETA: 21:24:39

  40. /82 EventProf 40 rspec --profile + ActiveSupport ::Notifications |====================> |

    ETA: 20:27:20
  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
  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
  43. /82 EventProf 43 “factory.create” Top-level factory calls “sidekiq.inline" Jobs executed

    inline TestProf-provided events |=====================> | ETA: 18:28:13
  44. /82 https://gist.github.com/nateberkopec/3932fce995c9feddd411417fc9bf33bf Sidekiq Shame 44 |======================> | ETA: 18:20:01

  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
  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
  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
  48. /82 How to migrate? 48 https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests |=========================> | ETA: 16:32:11

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

    you to localize problems Sidekiq ::Testing.inline! is evil! |=========================> | ETA: 16:01:59
  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
  51. Diagnostics #3 Factory Profilers

  52. /82 Factory Profilers 52 Factory Doctor FactoryProf |===========================> | ETA:

    15:15:11
  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
  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
  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
  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
  57. Diagnostics #4 Factory Cascades

  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
  59. /82 Factory Stack 59 create(:comment) # stack = [ #

    :comment, # :answer, # :question, # :user, # :user, # :user # ] |==============================> | ETA: 12:00:07
  60. /82 Factory Flame 60 |===============================> | ETA: 11:21:48

  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
  62. /82 Factory Story 62 |================================> | ETA: 10:10:34

  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
  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
  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
  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
  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
  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
  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
  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
  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
  72. /82 Factory Therapy 72 NEW!!! https://evilmartians.com/chronicles |=====================================> | ETA: 05:37:19

  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
  74. Part 3 Let It Be On TestProf features in a

    nutshell
  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
  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
  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
  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
  79. /82 Tests Could be Faster 79 … if configured properly

    … if code is testable … if you take care |==========================================> | ETA: 02:01:14
  80. /82 github.com/palkan/test-prof https://test-prof.evilmartians.io TestProf 80 |===========================================> | ETA: 01:48:46 v0.5.0

    (2018-05-25)
  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
  82. evilmartians.com @palkan @palkan_tula Vladimir Dementyev Take care of your tests!