Slide 1
Slide 1 text
TestProf
Vladimir Dementyev
Take Your Slow Tests
To The Doctor
Slide 2
Slide 2 text
/82
2
Vladimir
Dementyev
|> | ETA: 34:45:21
Slide 3
Slide 3 text
/82
3
! Москва
✈
# София
|> | ETA: 34:37:39
Slide 4
Slide 4 text
/82
4
@palkan
@palkan_tula
|=> | ETA: 34:21:00
Slide 5
Slide 5 text
/82
5 |==> | ETA: 34:05:56
Slide 6
Slide 6 text
/82
https://evilmartians.com
6 |==> | ETA: 33:57:21
Slide 7
Slide 7 text
/82
https://evilmartians.com
7 |===> | ETA: 33:41:04
Slide 8
Slide 8 text
This Talk
Slide 9
Slide 9 text
Part 1
The Story
Slide 10
Slide 10 text
RAISE YOUR HAND
IF YOUR TESTS ARE SLOW
Slide 11
Slide 11 text
/82
The Story
11
fountain.com (October, 2016)
~3700 test examples
~30 minutes CI (no parallelism)
~22 minutes for RSpec
|====> | ETA: 31:24:41
Slide 12
Slide 12 text
No content
Slide 13
Slide 13 text
© sponsored by
Slide 14
Slide 14 text
/82
The Story
14
fountain.com (October, 2016)
~3700 test examples
~30 minutes CI (no parallelism)
~22 minutes for RSpec
|=====> | ETA: 30:57:07
Slide 15
Slide 15 text
/82
parallelize_me!
* @eileencodes at RailsConf 2018
15 |======> | ETA: 30:48:43
Slide 16
Slide 16 text
The End
Slide 17
Slide 17 text
/82
The Story
17
fountain.com (October, 2016)
~3700 test examples
~9 minutes CI (5x parallelism)
~5 minutes for RSpec
|=======> | ETA: 30:13:30
Slide 18
Slide 18 text
/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
Slide 19
Slide 19 text
/82
Horizontal Scaling?
*https://speakerdeck.com/kirs/railsclub-2016
19 |========> | ETA: 29:03:00
Slide 20
Slide 20 text
/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
Slide 21
Slide 21 text
/82
How Did We Get Here?
21 |=========> | ETA: 28:30:44
Slide 22
Slide 22 text
Part 2
TestProf
Slide 23
Slide 23 text
/82
TestProf is a Doctor
23 |==========> | ETA: 27:53:15
Slide 24
Slide 24 text
/82
TestProf Map
24 |===========> | ETA: 27:21:48
Slide 25
Slide 25 text
Diagnostics #1
General
Profilers
Slide 26
Slide 26 text
/82
General Profilers
26
RubyProf
StackProf
rbspy (not supported by TestProf yet)
|============> | ETA: 26:54:19
Slide 27
Slide 27 text
/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
Slide 28
Slide 28 text
/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
Slide 29
Slide 29 text
/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
Slide 30
Slide 30 text
/82
StackProf
*single example profile
30 |==============> | ETA: 25:55:19
Slide 31
Slide 31 text
/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
Slide 32
Slide 32 text
/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 # __bc_crypt
1.12 47489 Arel ::Visitors ::Visitor#dispatch
1.04 205208 String#to_s
32 |===============> | ETA: 24:31:47
Slide 33
Slide 33 text
/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
Slide 34
Slide 34 text
/82
Encryption in Tests
https://github.com/Sorcery/sorcery/pull/81
34 |================> | ETA: 24:03:41
Slide 35
Slide 35 text
/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
Slide 36
Slide 36 text
Diagnostics #2
Special
Profilers
Slide 37
Slide 37 text
/82
Special Profilers
37
TagProf
EventProf
|==================> | ETA: 23:11:54
Slide 38
Slide 38 text
/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
Slide 39
Slide 39 text
/82
TagProf
39 |===================> | ETA: 21:24:39
Slide 40
Slide 40 text
/82
EventProf
40
rspec --profile
+
ActiveSupport ::Notifications
|====================> | ETA: 20:27:20
Slide 41
Slide 41 text
/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
Slide 42
Slide 42 text
/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
Slide 43
Slide 43 text
/82
EventProf
43
“factory.create”
Top-level factory calls
“sidekiq.inline"
Jobs executed inline
TestProf-provided events
|=====================> | ETA: 18:28:13
Slide 44
Slide 44 text
/82
https://gist.github.com/nateberkopec/3932fce995c9feddd411417fc9bf33bf
Sidekiq Shame
44 |======================> | ETA: 18:20:01
Slide 45
Slide 45 text
/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
Slide 46
Slide 46 text
/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
Slide 47
Slide 47 text
/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
Slide 48
Slide 48 text
/82
How to migrate?
48
https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests
|=========================> | ETA: 16:32:11
Slide 49
Slide 49 text
/82
What We Learned #2
49
TagProf and EventProf helps
you to localize problems
Sidekiq ::Testing.inline!
is evil!
|=========================> | ETA: 16:01:59
Slide 50
Slide 50 text
/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
Slide 51
Slide 51 text
Diagnostics #3
Factory
Profilers
Slide 52
Slide 52 text
/82
Factory Profilers
52
Factory Doctor
FactoryProf
|===========================> | ETA: 15:15:11
Slide 53
Slide 53 text
/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
Slide 54
Slide 54 text
/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
Slide 55
Slide 55 text
/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
Slide 56
Slide 56 text
/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
Slide 57
Slide 57 text
Diagnostics #4
Factory
Cascades
Slide 58
Slide 58 text
/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
Slide 59
Slide 59 text
/82
Factory Stack
59
create(:comment)
# stack = [
# :comment,
# :answer,
# :question,
# :user,
# :user,
# :user
# ]
|==============================> | ETA: 12:00:07
Slide 60
Slide 60 text
/82
Factory Flame
60 |===============================> | ETA: 11:21:48
Slide 61
Slide 61 text
/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
Slide 62
Slide 62 text
/82
Factory Story
62 |================================> | ETA: 10:10:34
Slide 63
Slide 63 text
/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
Slide 64
Slide 64 text
/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
Slide 65
Slide 65 text
/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
Slide 66
Slide 66 text
/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
Slide 67
Slide 67 text
/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
Slide 68
Slide 68 text
/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
Slide 69
Slide 69 text
/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
Slide 70
Slide 70 text
/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: '[email protected]'
}
end
%i[account funnel luke].each { |id| let(id) { fixture(id).refind }
end
http://bit.ly/any-fixture
|====================================> | ETA: 06:41:22
Slide 71
Slide 71 text
/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
Slide 72
Slide 72 text
/82
Factory Therapy
72
NEW!!!
https://evilmartians.com/chronicles
|=====================================> | ETA: 05:37:19
Slide 73
Slide 73 text
/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
Slide 74
Slide 74 text
Part 3
Let It Be
On TestProf features
in a nutshell
Slide 75
Slide 75 text
/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
Slide 76
Slide 76 text
/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
Slide 77
Slide 77 text
/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
Slide 78
Slide 78 text
/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
Slide 79
Slide 79 text
/82
Tests Could be Faster
79
… if configured properly
… if code is testable
… if you take care
|==========================================> | ETA: 02:01:14
Slide 80
Slide 80 text
/82
github.com/palkan/test-prof
https://test-prof.evilmartians.io
TestProf
80 |===========================================> | ETA: 01:48:46
v0.5.0 (2018-05-25)
Slide 81
Slide 81 text
/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
Slide 82
Slide 82 text
evilmartians.com
@palkan
@palkan_tula
Vladimir Dementyev
Take care of
your tests!