[Helvetic Ruby 2023] Profiling Ruby tests with Swiss precision

by Vladimir Dementyev

Slide 1

Slide 1 text

Proﬁling Ruby tests with Swiss precision Vladimir Dementyev Evil Martians

Slide 2

Slide 2 text

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

Slide 3

Slide 3 text

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

Slide 4

Slide 4 text

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

Slide 5

Slide 5 text

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

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

–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

Slide 10

Slide 10 text

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

Slide 11

Slide 11 text

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

Slide 12

Slide 12 text

8 youtube.com/watch?v=VD51AkG8EZw

Slide 13

Slide 13 text

8 youtube.com/watch?v=VD51AkG8EZw

Slide 14

Slide 14 text

8 youtube.com/watch?v=VD51AkG8EZw

Slide 15

Slide 15 text

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

Slide 16

Slide 16 text

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

Slide 17

Slide 17 text

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

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

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

Slide 20

Slide 20 text

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

Slide 21

Slide 21 text

–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

Slide 22

Slide 22 text

–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

Slide 23

Slide 23 text

Did I introduce myself?

Slide 24

Slide 24 text

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

Slide 25

Slide 25 text

palkan_tula palkan + Ich komme vom Mars 16 evilmartians.com

Slide 26

Slide 26 text

palkan_tula palkan + Ich habe ein Buch 17

Slide 27

Slide 27 text

Proﬁling tests

Slide 28

Slide 28 text

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

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

20 Rails 7.1

Slide 31

Slide 31 text

Slide 32

Slide 32 text

22 evilmartians.com/events

Slide 33

Slide 33 text

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

Slide 34

Slide 34 text

Finding often-used things

Slide 35

Slide 35 text

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

Slide 36

Slide 36 text

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

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

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

Slide 39

Slide 39 text

The TestProf Way bundle add test-prof -g test

Slide 40

Slide 40 text

Think globally Step 1

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

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

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

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

Slide 45

Slide 45 text

palkan_tula palkan + 34

Slide 46

Slide 46 text

palkan_tula palkan + 35 Next-gen Ruby sampling proﬁler Generates Firefox Proﬁler- compatible reports TEST_VERNIER 1 bin/rspec Vernier github.com/jhawthorn/vernier

Slide 47

Slide 47 text

Slide 48

Slide 48 text

palkan_tula palkan + 37 General proﬁlers are good in ﬁnding performance issues but fail to identify code patterns that make your tests slow

Slide 49

Slide 49 text

Focus Step 2

Slide 50

Slide 50 text

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

Slide 51

Slide 51 text

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

Slide 52

Slide 52 text

Slide 53

Slide 53 text

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

Slide 54

Slide 54 text

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

Slide 55

Slide 55 text

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%)

Slide 56

Slide 56 text

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

Slide 57

Slide 57 text

Be speciﬁc Step 3

Slide 58

Slide 58 text

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

Slide 59

Slide 59 text

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)

Slide 60

Slide 60 text

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

Slide 61

Slide 61 text

palkan_tula palkan + FactoryProf 50

Slide 62

Slide 62 text

palkan_tula palkan + Factory Therapy 51 evilmartians.com/chronicles

Slide 63

Slide 63 text

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

Slide 64

Slide 64 text

palkan_tula palkan + 53

Slide 65

Slide 65 text

–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

Slide 66

Slide 66 text

No content

Slide 67

Slide 67 text

Repeat, please

Slide 68

Slide 68 text

57 Autopilot evilmartians.com/chronicles

Slide 69

Slide 69 text

palkan_tula palkan + 58 github.com/test-prof

Slide 70

Slide 70 text

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