[BalkanRuby 2018] Take your slow tests to the doctor

https://www.youtube.com/watch?v=rOcrme82vC8

https://test-prof.evilmartians.io/

Transcript

1. TestProf Vladimir Dementyev Take Your Slow Tests To The Doctor
2. /82 2 Vladimir Dementyev |> | ETA: 34:45:21
3. /82 3 ! Москва ✈ # София |> | ETA: 34:37:39
4. /82 4 @palkan @palkan_tula |=> | ETA: 34:21:00
5. /82 5 |==> | ETA: 34:05:56
6. /82 https://evilmartians.com 6 |==> | ETA: 33:57:21
7. /82 https://evilmartians.com 7 |===> | ETA: 33:41:04
8. This Talk
9. Part 1 The Story
10. RAISE YOUR HAND IF YOUR TESTS ARE SLOW
11. /82 The Story 11 fountain.com (October, 2016) ~3700 test examples ~30 minutes CI (no parallelism) ~22 minutes for RSpec |====> | ETA: 31:24:41
13. © sponsored by
14. /82 The Story 14 fountain.com (October, 2016) ~3700 test examples ~30 minutes CI (no parallelism) ~22 minutes for RSpec |=====> | ETA: 30:57:07
15. /82 parallelize_me! * @eileencodes at RailsConf 2018 15 |======> | ETA: 30:48:43
16. The End
17. /82 The Story 17 fountain.com (October, 2016) ~3700 test examples ~9 minutes CI (5x parallelism) ~5 minutes for RSpec |=======> | ETA: 30:13:30
18. /82 The Grow 18 Number of tests 0 2250 4500 6750 9000 Oct 16 Dec 16 Feb 17 Apr 17 June 17 Sep 17 Feb 18 May 18 |=======> | ETA: 29:20:38
19. /82 Horizontal Scaling? *https://speakerdeck.com/kirs/railsclub-2016 19 |========> | ETA: 29:03:00
20. /82 The Story 20 fountain.com (present) ~9000 test examples 7 minutes on CI (5x parallelism) 3 minutes RSpec 4x faster! |========> | ETA: 28:39:01
21. /82 How Did We Get Here? 21 |=========> | ETA: 28:30:44
22. Part 2 TestProf
23. /82 TestProf is a Doctor 23 |==========> | ETA: 27:53:15
24. /82 TestProf Map 24 |===========> | ETA: 27:21:48
25. Diagnostics #1 General Profilers
26. /82 General Profilers 26 RubyProf StackProf rbspy (not supported by TestProf yet) |============> | ETA: 26:54:19
27. /82 StackProf $ 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 27 |============> | ETA: 26:41:00
28. /82 PROTIP #0 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” 28 |=============> | ETA: 26:20:37
29. /82 PROTIP #0 “Log to standard output when necessary” 29 require 'test_prof/recipes/logging' https://test-prof.evilmartians.io/#/logging LOG=all bundle exec rspec |=============> | ETA: 26:03:56
30. /82 StackProf *single example profile 30 |==============> | ETA: 25:55:19
31. /82 PROTIP #1 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’ “Save up to 40% by getting rid of database_cleaner” 31 |==============> | ETA: 25:29:05
32. /82 RubyProf $ SAMPLE=10 TEST_RUBY_PROF=1 rspec $ more tmp/test_prof/ruby-prof—report-flat-total.log %self calls name 20.85 721 <Class ::BCrypt ::Engine># __bc_crypt 1.12 47489 Arel ::Visitors ::Visitor#dispatch 1.04 205208 String#to_s 32 |===============> | ETA: 24:31:47
33. /82 Encryption in Tests # Gemfile gem "sorcery" # config/initializers/sorcery.rb config.user_config do |user| # default was 10 for bcrypt! user.stretches = 1 if Rails.env.test? end 2x faster! 33 |===============> | ETA: 24:10:10
34. /82 Encryption in Tests https://github.com/Sorcery/sorcery/pull/81 34 |================> | ETA: 24:03:41
35. /82 What We Learned #1 35 Test environment should be different Make logging less verbose (or turn off completely) Relax encryption settings |=================> | ETA: 23:48:08
36. Diagnostics #2 Special Profilers
37. /82 Special Profilers 37 TagProf EventProf |==================> | ETA: 23:11:54
38. /82 TagProf $ TAG_PROF=type rspec [TEST PROF INFO] TagProf report for type type time total %total %time controller 05:34.465 2882 38.52 38.98 service 03:21.967 1421 18.99 23.54 model 02:03.604 1780 23.79 14.41 job 01:08.822 331 4.42 8.02 request 00:51.555 247 3.30 6.01 form 00:25.893 217 2.90 3.02 query 00:15.493 98 1.31 1.81 38 |===================> | ETA: 22:00:01
39. /82 TagProf 39 |===================> | ETA: 21:24:39
40. /82 EventProf 40 rspec --profile + ActiveSupport ::Notifications |====================> | ETA: 20:27:20
41. /82 EventProf 41 $ EVENT_PROF=sql.active_record rspec [TEST PROF INFO] EventProf for sql.active_record Total time: 00:00.256 Total events: 1031 Top 5 slowest suites (by time): AnswersController – 00:00.119 (549 / 20) QuestionsController – 00:00.105 (360 / 18) CommentsController – 00:00.032 (122 / 4) |====================> | ETA: 20:01:42
42. /82 EventProf 42 # Works with Minitest too ruby test.rb \ --event-prof=sql.active_record + # Easily integrates with your framework Custom Instrumentation |=====================> | ETA: 19:31:30
43. /82 EventProf 43 “factory.create” Top-level factory calls “sidekiq.inline" Jobs executed inline TestProf-provided events |=====================> | ETA: 18:28:13
44. /82 https://gist.github.com/nateberkopec/3932fce995c9feddd411417fc9bf33bf Sidekiq Shame 44 |======================> | ETA: 18:20:01
45. /82 Sidekiq Inline 45 $ 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 |======================> | ETA: 17:58:32
46. /82 Sidekiq Inline 46 $ 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 ~1.2x faster! |=======================> | ETA: 17:23:51
47. /82 PROTIP #2 Sidekiq ::Testing.fake! “If you want faster tests you can use fake mode and call WorkerUnderTest.drain.” –Nate 47 |========================> | ETA: 16:56:36
48. /82 How to migrate? 48 https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests |=========================> | ETA: 16:32:11
49. /82 What We Learned #2 49 TagProf and EventProf helps you to localize problems Sidekiq ::Testing.inline! is evil! |=========================> | ETA: 16:01:59
50. /82 The Story 50 Oct 2016 Feb 2018 0s 10s 20s 30s 40s 50s 60s 70s sql.active_record factory.create * profiles for the fixed tests sample |==========================> | ETA: 15:42:22
51. Diagnostics #3 Factory Profilers
52. /82 Factory Profilers 52 Factory Doctor FactoryProf |===========================> | ETA: 15:15:11
53. /82 Useless Data 53 it "validates name presence" do user = create(:user) expect(user).not_to be_valid end it "validates name presence" do user = build_stubbed(:user) expect(user).not_to be_valid end VS |============================> | ETA: 14:44:26
54. /82 Factory Doctor 54 $ 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 |============================> | ETA: 14:00:44
55. /82 Factory All Stub 55 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 |=============================> | ETA: 13:43:17
56. /82 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 ⁉ |=============================> | ETA: 13:05:13
57. Diagnostics #4 Factory Cascades
58. /82 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 |==============================> | ETA: 12:24:49
59. /82 Factory Stack 59 create(:comment) # stack = [ # :comment, # :answer, # :question, # :user, # :user, # :user # ] |==============================> | ETA: 12:00:07
60. /82 Factory Flame 60 |===============================> | ETA: 11:21:48
61. /82 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! |===============================> | ETA: 10:41:47
62. /82 Factory Story 62 |================================> | ETA: 10:10:34
63. /82 Cascade Fix #1 63 Explicit associations # before factory :embedded_signature_request do requests_set template … end create(:embedded_signature_request) |================================> | ETA: 09:45:10
64. /82 Cascade Fix #1 64 Explicit associations # after factory :embedded_signature_request do … end create(:embedded_signature_request, requests_set: set, template: template) # But create(:embedded_signature_request) # raise ActiveRecord ::Invalid |=================================> | ETA: 09:31:46
65. /82 Cascade Fix #2 65 factory :stage do funnel account do funnel&.account || build(:account) end end Association inference Doesn’t fit every data model |=================================> | ETA: 08:52:11
66. /82 Cascade Fix #3 66 describe MessageTemplates ::Deliver do let(:funnel) do create_default(:funnel) end let(:stage) do create_default(:stage, funnel: funnel) end end |==================================> | ETA: 08:41:01
67. /82 FactoryDefault 67 Fix cascades quickly (w/o touching factories) Use when many factories depend on some other factory https://test-prof.evilmartians.io/#/factory_default |===================================> | ETA: 08:29:13
68. /82 FactoryProf 68 $ 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? |===================================> | ETA: 08:02:09
69. /82 AnyFixture 69 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 |====================================> | ETA: 07:47:19
70. /82 AnyFixture 70 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 |====================================> | ETA: 06:41:22
71. /82 AnyFixture 71 [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 |====================================> | ETA: 06:10:46
72. /82 Factory Therapy 72 NEW!!! https://evilmartians.com/chronicles |=====================================> | ETA: 05:37:19
73. /82 What We Learned #3 73 Factory cascades are very harmful–diagnose & treat! Do not choose between factories and fixtures–use both! |======================================> | ETA: 05:00:11
74. Part 3 Let It Be On TestProf features in a nutshell
75. /82 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 |=======================================> | ETA: 04:22:06
76. /82 before_all 76 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 |=======================================> | ETA: 03:58:21
77. /82 let_it_be 77 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 https://test-prof.evilmartians.io/#/let_it_be |========================================> | ETA: 03:18:16
78. /82 RSpec/AggregateFailures 78 rubocop --only RSpec/AggregateFailures Offenses: create_spec.rb:277:7: C: RSpec/AggregateFailures: Use :aggregate_failures instead of one-liners. context 'not valid secure fields' do ... ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 18 files inspected, 1 offense detected https://test-prof.evilmartians.io/#/rubocop |=========================================> | ETA: 02:31:29
79. /82 Tests Could be Faster 79 … if configured properly … if code is testable … if you take care |==========================================> | ETA: 02:01:14
80. /82 github.com/palkan/test-prof https://test-prof.evilmartians.io TestProf 80 |===========================================> | ETA: 01:48:46 v0.5.0 (2018-05-25)
81. /82 Dreams, or what’s next? 81 Reporters API (formatters, etc.) Multi-threadedness (for Rails 6) Reports viewer UI TestProf CI https://github.com/palkan/test-prof/projects/1 |============================================> | ETA: 01:01:39
82. evilmartians.com @palkan @palkan_tula Vladimir Dementyev Take care of your tests!