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

[Helvetic Ruby 2023] Profiling Ruby tests with ...

[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. palkan_tula palkan + 1. 2. 3. 4. 5. 0 0

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

    39 2 WHY PROFILE TESTS? 2. REDUCE CI COSTS 39 39
  3. 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
  4. 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
  5. 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
  6. 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
  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 ≫ 16 × 3333 ≈ 53000
  8. –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
  9. palkan_tula palkan + 1. 2. 3. 4. 5. 0 0

    39 6 WHY PROFILE TESTS? 2. REDUCE (CI) COSTS 39 39
  10. 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
  11. 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
  12. 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
  13. 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
  14. 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
  15. 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
  16. –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
  17. –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
  18. palkan_tula palkan + 1. 2. 3. 4. 5. 137 0

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

    19 HOW DO YOU PROFILE TESTS? 99 1. bin/rspec - -profile 99 99
  20. 21

  21. –Steven Baker “On anything but the slowest of test suites,

    you get more mileage out of making often-used things faster .” 23
  22. palkan_tula palkan + 25 Specialized profiler for Ruby test suites

    Optimization toolbox to speed up tests with less refactoring TestProf test-prof.evilmartians.io
  23. 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
  24. palkan_tula palkan + 27 Used by GitHub, Discourse, Gitlab, Dev.to,

    and many more TestProf test-prof.evilmartians.io
  25. 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
  26. 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
  27. 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
  28. 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 ...
  29. 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
  30. palkan_tula palkan + 35 Next-gen Ruby sampling profiler Generates Firefox

    Profiler- compatible reports TEST_VERNIER 1 bin/rspec Vernier github.com/jhawthorn/vernier
  31. 36

  32. palkan_tula palkan + 37 General profilers are good in finding

    performance issues but fail to identify code patterns that make your tests slow
  33. 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
  34. 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
  35. 41

  36. 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
  37. 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
  38. 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%)
  39. 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
  40. 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
  41. 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)
  42. 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
  43. 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