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

[Helvetic Ruby 2023] Profiling Ruby tests with Swiss precision

[Helvetic Ruby 2023] Profiling Ruby tests with Swiss precision

Tests occupy a significant amount of developers’ time. We write them, run locally, and wait for CI builds to complete—the latter can last from a cup of coffee to a good day nap. And unfortunately, such “naps” are pretty common in the Ruby and Rails world.

Luckily, the reasons for slow tests vary greatly between codebases: misconfigured environment, test-unfriendly dependencies, and, of course, factories and database interactions in general.
I like to demonstrate the tools and techniques to help you identify bottlenecks in test suites to help you stay awake.

Vladimir Dementyev

November 24, 2023
Tweet

More Decks by Vladimir Dementyev

Other Decks in Programming

Transcript

  1. Profiling Ruby
    tests with
    Swiss precision
    Vladimir Dementyev
    Evil Martians

    View full-size slide

  2. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    0
    - -
    2
    WHY PROFILE TESTS?

    View full-size slide

  3. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    39
    2
    WHY PROFILE TESTS?
    2. REDUCE CI COSTS 39
    39

    View full-size slide

  4. palkan_tula
    palkan
    +
    Reduce costs
    3
    d =
    (
    1 −
    T
    new
    Told )
    − test suite speed improvement
    C
    dev
    − cost of an hour of profiling/optimization work
    C
    build
    = avg(t
    minutes
    (b
    i
    )) × CI
    min
    − cost of a build
    N
    builds
    × C
    build
    × d ≫ N
    hours
    × C
    dev

    View full-size slide

  5. palkan_tula
    palkan
    +
    Example
    4
    N
    builds
    × C
    build
    × d ≫ N
    hours
    × C
    dev
    d =
    (
    1 −
    T
    new
    Told )
    = 0.2
    C
    dev
    = 200
    C
    build
    = avg(t
    minutes
    (b
    i
    )) × CI
    min
    = 30 × 0.01 = 0.3

    View full-size slide

  6. palkan_tula
    palkan
    +
    N
    builds
    × 0.3 × 0.2 ≫ N
    hours
    × 200
    Example
    4
    d =
    (
    1 −
    T
    new
    Told )
    = 0.2
    C
    dev
    = 200
    C
    build
    = avg(t
    minutes
    (b
    i
    )) × CI
    min
    = 30 × 0.01 = 0.3

    View full-size slide

  7. palkan_tula
    palkan
    +
    Example
    4
    d =
    (
    1 −
    T
    new
    Told )
    = 0.2
    C
    dev
    = 200
    C
    build
    = avg(t
    minutes
    (b
    i
    )) × CI
    min
    = 30 × 0.01 = 0.3
    N
    builds
    ≫ N
    hours
    × 3333

    View full-size slide

  8. palkan_tula
    palkan
    +
    Example
    4
    d =
    (
    1 −
    T
    new
    Told )
    = 0.2
    C
    dev
    = 200
    C
    build
    = avg(t
    minutes
    (b
    i
    )) × CI
    min
    = 30 × 0.01 = 0.3
    N
    builds
    ≫ 16 × 3333 ≈ 53000

    View full-size slide

  9. –Undisclosed TestProf user
    “Our CI pipeline currently takes about 2
    hours. We calculated that reducing from
    120 min to 30 min would be equivalent to
    adding 2 full-time engineers per year.”
    5

    View full-size slide

  10. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    39
    6
    WHY PROFILE TESTS?
    2. REDUCE (CI) COSTS 39
    39

    View full-size slide

  11. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    7
    WHY PROFILE TESTS?
    1. SPEED UP FEEDBACK LOOP 56
    2. REDUCE (CI) COSTS 39
    95
    95

    View full-size slide

  12. 8
    youtube.com/watch?v=VD51AkG8EZw

    View full-size slide

  13. 8
    youtube.com/watch?v=VD51AkG8EZw

    View full-size slide

  14. 8
    youtube.com/watch?v=VD51AkG8EZw

    View full-size slide

  15. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    9
    WHY PROFILE TESTS?
    1. SPEED UP FEEDBACK LOOP 56
    2. REDUCE (CI) COSTS 39
    95
    95

    View full-size slide

  16. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    9
    WHY PROFILE TESTS?
    1. SPEED UP FEEDBACK LOOP 56
    2. REDUCE (CI) COSTS 39
    4. MAKE TESTS USABLE 13
    108
    108

    View full-size slide

  17. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    10
    WHY PROFILE TESTS?
    1. SPEED UP FEEDBACK LOOP 56
    2. REDUCE (CI) COSTS 39
    4. MAKE TESTS USABLE 13
    5. APPLICATION PROFILING 9
    117
    117

    View full-size slide

  18. 11
    github.com/test-prof/test-prof/discussions/73

    View full-size slide

  19. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    12
    WHY PROFILE TESTS?
    1. SPEED UP FEEDBACK LOOP 56
    2. REDUCE CI COSTS 39
    4. MAKE TESTS USABLE 13
    5. APPLICATION PROFILING 9
    117
    117

    View full-size slide

  20. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    0 0
    137
    137
    12
    WHY PROFILE TESTS?
    1. SPEED UP FEEDBACK LOOP 56
    2. REDUCE CI COSTS 39
    3. DEVELOPER HAPPINESS (DX) 20
    4. MAKE TESTS USABLE 13
    5. APPLICATION PROFILING 9

    View full-size slide

  21. –Undisclosed TestProf user
    “When asked “How we can we improve the
    developer experience?”, top themes that
    emerged included speed (test suite is slow)
    and flaky specs”
    13

    View full-size slide

  22. –Undisclosed Evil Martians client
    “When asked “How we can we improve the
    developer experience?”, top themes that
    emerged included speed (test suite is slow)
    and flaky specs”
    13

    View full-size slide

  23. Did I introduce
    myself?

    View full-size slide

  24. palkan_tula
    palkan
    +
    Ich heiße Vova
    15
    github.com/palkan

    View full-size slide

  25. palkan_tula
    palkan
    +
    Ich komme vom Mars
    16
    evilmartians.com

    View full-size slide

  26. palkan_tula
    palkan
    +
    Ich habe ein Buch
    17

    View full-size slide

  27. Profiling
    tests

    View full-size slide

  28. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    137 0
    0
    - -
    19
    HOW DO YOU PROFILE TESTS?

    View full-size slide

  29. palkan_tula
    palkan
    +
    1.
    2.
    3.
    4.
    5.
    137 0
    19
    HOW DO YOU PROFILE TESTS?
    99
    1. bin/rspec - -profile 99
    99

    View full-size slide

  30. 22
    evilmartians.com/events

    View full-size slide

  31. –Steven Baker
    “On anything but the slowest of test
    suites, you get more mileage out of
    making often-used things faster .”
    23

    View full-size slide

  32. Finding
    often-used
    things

    View full-size slide

  33. palkan_tula
    palkan
    +
    25
    Specialized profiler for Ruby test
    suites
    Optimization toolbox to speed up
    tests with less refactoring
    TestProf
    test-prof.evilmartians.io

    View full-size slide

  34. palkan_tula
    palkan
    +
    26
    Based on techniques used in a
    large Rails monolith (Fountain)
    Helped to gain 4x test time
    reduction (from 170 to 700 TPM*)
    TestProf
    test-prof.evilmartians.io
    * TPM = Tests per minutes

    View full-size slide

  35. palkan_tula
    palkan
    +
    27
    Used by GitHub, Discourse,
    Gitlab, Dev.to, and many more
    TestProf
    test-prof.evilmartians.io

    View full-size slide

  36. palkan_tula
    palkan
    +
    27
    Used by GitHub, Discourse,
    Gitlab, Dev.to, and many more
    Used by YOU after this
    conference!
    TestProf
    test-prof.evilmartians.io

    View full-size slide

  37. The TestProf
    Way
    bundle add test-prof -g test

    View full-size slide

  38. Think
    globally
    Step 1

    View full-size slide

  39. palkan_tula
    palkan
    +
    30
    Give general Ruby profilers a try
    Profile with StackProf,
    RubyProf, or Vernier via
    TestProf integrations
    Use tests sampling
    Think globally
    Start with not-so-specialized profilers

    View full-size slide

  40. palkan_tula
    palkan
    +
    $
    31
    bundle add stackprof -g test -r false
    ...
    Using stackprof 0.2.25
    $ SAMPLE 100 TEST_STACK_PROF 1 bin/rspec
    [TEST PROF INFO] StackProf enabled: mode — wall, target — suite
    ................................................................
    ..................................
    [TEST PROF INFO] StackProf report: tmp/stack-prof-total.dump
    [TEST PROF INFO] StackProf JSON: tmp/stack-prof-total.json

    View full-size slide

  41. palkan_tula
    palkan
    +
    $
    32
    stackprof tmp/stack-prof-total.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
    ...

    View full-size slide

  42. palkan_tula
    palkan
    +
    The 6% phenomenon
    33
    # config/environments/test.rb
    config.logger = Logger.new(nil)
    config.log_level = :fatal
    Just two lines of code to make your Rails tests faster

    View full-size slide

  43. palkan_tula
    palkan
    +
    34

    View full-size slide

  44. palkan_tula
    palkan
    +
    35
    Next-gen Ruby sampling profiler
    Generates Firefox Profiler-
    compatible reports
    TEST_VERNIER 1 bin/rspec
    Vernier
    github.com/jhawthorn/vernier

    View full-size slide

  45. palkan_tula
    palkan
    +
    37
    General profilers are good in
    finding performance issues but
    fail to identify code patterns
    that make your tests slow

    View full-size slide

  46. palkan_tula
    palkan
    +
    39
    Tests of a similar type (model,
    request, etc.) have similar
    problems
    High chance to find one trick
    to fix them all
    Focus
    Don't try to fix everything, locate the suite's subset
    with the greatest improvement potential

    View full-size slide

  47. palkan_tula
    palkan
    +
    $
    40
    TagProf
    TAG_PROF=type TAG_PROF_FORMAT=html \
    TAG_PROF_EVENT=sql.active_record,factory.create \
    bin/rspec
    ................................................................
    ................................................................
    ................................................................
    ................................................................
    [TEST PROF INFO] TagProf enabled: type
    [TEST PROF INFO] TagProf report: tmp/tag-prof.html

    View full-size slide

  48. palkan_tula
    palkan
    +
    42
    Better version of rspec --profile
    Built-in events (sidekiq.inline,
    factory.create) and custom
    monitors
    Can auto-tag slow examples
    (RSpec)
    EventProf
    Instrumentation-driven profiler

    View full-size slide

  49. palkan_tula
    palkan
    +
    $
    43
    EventProf
    EVENT_PROF=factory.create EVENT_PROF_STAMP=slow:factory \
    EVENT_PROF_TOP 20 bin/rspec
    ................................................................
    ...............................................
    [TEST PROF INFO] EventProf enabled: factory.create

    View full-size slide

  50. palkan_tula
    palkan
    +
    $
    44
    EVENT_PROF=factory.create EVENT_PROF_STAMP=slow:factory \
    EVENT_PROF_TOP 20 bin/rspec
    Total time: 34 04.665 of 37 12.515 (91.59%)
    Total events: 15260
    Top 20 slowest suites (by time):
    User (./spec/models/user_spec.rb:3) – 02 32.577 (951 / 583) of
    02 50.654 (89.41%)
    Appointment (./spec/models/appointment_spec.rb:4) – 02 16.524
    (822 / 401) of 02 38.911 (85.91%)

    View full-size slide

  51. palkan_tula
    palkan
    +
    45
    Pick the most time-consuming
    group ("models" in our
    example)
    Continue profiling only within
    this group, ignore everything
    else (for now)
    Focus

    View full-size slide

  52. Be specific
    Step 3

    View full-size slide

  53. palkan_tula
    palkan
    +
    47
    Profile factories with
    FactoryDoctor and
    FactoryProf
    Profile specs layout with
    RSpecDissect
    Be specific
    It's time to dust off one of the specialized profilers

    View full-size slide

  54. palkan_tula
    palkan
    +
    $
    .....................................
    [TEST PROF INFO] FactoryDoctor enabled
    48
    FDOC 1 bin/rspec
    [TEST PROF INFO] FactoryDoctor report
    Total (potentially) bad examples: 1428
    Total wasted time: 07 06.446
    Group (./spec/models/group_spec.rb:3) (367 records created,
    00 09.312)
    Assignment (./spec/models/assignment_spec.rb:3) (217 records
    created, 00 05.749)

    View full-size slide

  55. palkan_tula
    palkan
    +
    FactoryDoctor
    49
    # bad
    it "validates name" do
    user = create(:user)
    expect(user).not_to be_valid
    end
    # good
    it "validates name" do
    user = build_stubbed(:user)
    expect(user).not_to be_valid
    end

    View full-size slide

  56. palkan_tula
    palkan
    +
    FactoryProf
    50

    View full-size slide

  57. palkan_tula
    palkan
    +
    Factory Therapy
    51
    evilmartians.com/chronicles

    View full-size slide

  58. palkan_tula
    palkan
    +
    $
    52
    RD_PROF 1 bin/rspec
    [TEST PROF INFO] RSpecDissect report
    Total time: 39 29
    Total `let` time: 35 32
    Total `before(:each)` time: 25 20
    Top 10 slowest suites (by `let` time):
    User (./spec/models/user_spec.rb) – 02 53 / 03 18 (583)
    Appointment (./spec/models/appointment_spec.rb) – 02 40 / 03 05 (401)
    .....................................
    [TEST PROF INFO] RSpecDissect enabled

    View full-size slide

  59. palkan_tula
    palkan
    +
    53

    View full-size slide

  60. –TestProf
    “build_stubbed instead of create,
    let_it_be instead of let/let!,
    before_all instead of before(:each),
    set log level to fatal”
    54

    View full-size slide

  61. Repeat,
    please

    View full-size slide

  62. 57
    Autopilot
    evilmartians.com/chronicles

    View full-size slide

  63. palkan_tula
    palkan
    +
    58
    github.com/test-prof

    View full-size slide

  64. Take care of
    your tests!
    Slides: evilmartians.com/events
    Twitter: @palkan_tula,
    @evilmartians

    View full-size slide