[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.

Transcript

1. Profiling Ruby tests with Swiss precision Vladimir Dementyev Evil Martians
2. palkan_tula palkan + 1. 2. 3. 4. 5. 0 0 0 - - 2 WHY PROFILE TESTS?
3. palkan_tula palkan + 1. 2. 3. 4. 5. 0 0 39 2 WHY PROFILE TESTS? 2. REDUCE CI COSTS 39 39
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
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
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
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
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
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
10. palkan_tula palkan + 1. 2. 3. 4. 5. 0 0 39 6 WHY PROFILE TESTS? 2. REDUCE (CI) COSTS 39 39
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
12. 8 youtube.com/watch?v=VD51AkG8EZw
13. 8 youtube.com/watch?v=VD51AkG8EZw
14. 8 youtube.com/watch?v=VD51AkG8EZw
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
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
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
18. 11 github.com/test-prof/test-prof/discussions/73
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
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
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
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
23. Did I introduce myself?
24. palkan_tula palkan + Ich heiße Vova 15 github.com/palkan
25. palkan_tula palkan + Ich komme vom Mars 16 evilmartians.com
26. palkan_tula palkan + Ich habe ein Buch 17
27. Profiling tests
28. palkan_tula palkan + 1. 2. 3. 4. 5. 137 0 0 - - 19 HOW DO YOU PROFILE TESTS?
29. palkan_tula palkan + 1. 2. 3. 4. 5. 137 0 19 HOW DO YOU PROFILE TESTS? 99 1. bin/rspec - -profile 99 99
30. 20 Rails 7.1
32. 22 evilmartians.com/events
33. –Steven Baker “On anything but the slowest of test suites, you get more mileage out of making often-used things faster .” 23
34. Finding often-used things
35. palkan_tula palkan + 25 Specialized profiler for Ruby test suites Optimization toolbox to speed up tests with less refactoring TestProf test-prof.evilmartians.io
36. 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
37. palkan_tula palkan + 27 Used by GitHub, Discourse, Gitlab, Dev.to, and many more TestProf test-prof.evilmartians.io
38. 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
39. The TestProf Way bundle add test-prof -g test
40. Think globally Step 1
41. 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
42. 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
43. 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 ...
44. 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
45. palkan_tula palkan + 34
46. palkan_tula palkan + 35 Next-gen Ruby sampling profiler Generates Firefox Profiler- compatible reports TEST_VERNIER 1 bin/rspec Vernier github.com/jhawthorn/vernier
48. palkan_tula palkan + 37 General profilers are good in finding performance issues but fail to identify code patterns that make your tests slow
49. Focus Step 2
50. 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
51. 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
53. 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
54. 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
55. 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%)
56. 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
57. Be specific Step 3
58. 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
59. 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)
60. 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
61. palkan_tula palkan + FactoryProf 50
62. palkan_tula palkan + Factory Therapy 51 evilmartians.com/chronicles
63. 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
64. palkan_tula palkan + 53
65. –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
67. Repeat, please
68. 57 Autopilot evilmartians.com/chronicles
69. palkan_tula palkan + 58 github.com/test-prof
70. Take care of your tests! Slides: evilmartians.com/events Twitter: @palkan_tula, @evilmartians