[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
   

   View Slide

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

   View Slide

3. palkan_tula
   palkan
   3
   

   View Slide

4. palkan_tula
   palkan
   https://evilmartians.com
   4
   

   View Slide

5. palkan_tula
   palkan
   https://evilmartians.com
   5
   

   View Slide

6. palkan_tula
   palkan
   https://evilmartians.com
   6
   

   View Slide

7. This Talk
   

   View Slide

8. palkan_tula
   palkan
   99 problems of
   slow tests
   8
   

   View Slide

9. RAISE YOUR HAND
   IF YOUR TESTS ARE SLOW
   

   View Slide

10. View Slide

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

    View Slide

12. TestProf
    

    View Slide

13. View Slide

14. Problem #1
    Misconfigured
    Environment
    TODO: картинко
    

    View Slide

15. palkan_tula
    palkan
    Use general profilers to diagnose
    environment problems
    15
    

    View Slide

16. palkan_tula
    palkan
    General Profilers
    16
    RubyProf
    StackProf
    rbspy
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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

    View Slide

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!
    

    View Slide

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

    View Slide

22. palkan_tula
    palkan
    Test environment should be
    configured differently
    22
    

    View Slide

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
    

    View Slide

24. palkan_tula
    palkan
    TEST_STACK_PROF
    24
    

    View Slide

25. Problem #2
    database_cleaner
    

    View Slide

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
    

    View Slide

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

    View Slide

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

    View Slide

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'
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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!
    

    View Slide

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!
    

    View Slide

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

    View Slide

36. palkan_tula
    palkan
    TEST_STACK_PROF=boot
    36
    

    View Slide

37. Problem #3
    Boot Time
    

    View Slide

38. palkan_tula
    palkan
    TEST_STACK_PROF=boot
    38
    

    View Slide

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

    View Slide

40. Problem #4
    Inlined Jobs
    

    View Slide

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

    View Slide

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
    

    View Slide

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
    

    View Slide

44. palkan_tula
    palkan
    Do not inline background jobs
    by default
    44
    

    View Slide

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

    View Slide

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

    View Slide

47. Problem #5
    Testability of
    Deps
    

    View Slide

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
    )
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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

    View Slide

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
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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

    View Slide

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 ⁉
    

    View Slide

57. Problem #7
    Factory
    Cascades
    

    View Slide

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
    

    View Slide

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

    View Slide

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

    View Slide

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!
    

    View Slide

62. palkan_tula
    palkan
    Factory Story
    62
    

    View Slide

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

    View Slide

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

    View Slide

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?
    

    View Slide

66. Problem #8
    Repetitive
    Data
    Generation
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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
    

    View Slide

71. palkan_tula
    palkan
    Do not choose between factories
    and fixtures–use both!
    71
    

    View Slide

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

    View Slide

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
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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
    

    View Slide

77. palkan_tula
    palkan
    77
    

    View Slide

78. palkan_tula
    palkan
    78
    before_all
    let_it_be
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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

    View Slide

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

    View Slide

83. Problem #10
    One Assertion
    per Test
    

    View Slide

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
    

    View Slide

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!
    

    View Slide

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
    

    View Slide

87. Problems #11-99
    It’s You
    

    View Slide

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

    View Slide

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

    View Slide