Tweet
Tweet

Slide 1

Slide 1 text

How to Performance WindyCityRails 2015

Slide 2

Slide 2 text

! eileencodes.com " @eileencodes # @eileencodes EILEEN M. UCHITELLE Programmer at Basecamp

Slide 3

Slide 3 text

rails committers team & rails security team

Slide 4

Slide 4 text

Arya @aryadog

Slide 5

Slide 5 text

Kingston, NY

Slide 6

Slide 6 text

No content

Slide 7

Slide 7 text

No content

Slide 8

Slide 8 text

VS BENCHMARKING PROFILING

Slide 9

Slide 9 text

benchmarking how slow something is

Slide 10

Slide 10 text

profiling what is slow

Slide 11

Slide 11 text

Hey Eileen, I drive race cars so, I really hate it when things are slowwwwwww... *not actual statement

Slide 12

Slide 12 text

Can you see what you can do about speeding up integration tests in Ruby on Rails? *not actual statement

Slide 13

Slide 13 text

Totes McGoats David! I <3 performance! *not actual statement

Slide 14

Slide 14 text

GET A BASELINE

Slide 15

Slide 15 text

github.com/eileencodes/ integration_performance_test

Slide 16

Slide 16 text

CONTROLLER TEST class DocumentsControllerTest < ActionController::Testcase test "index" do get :index assert_equal 200, response.status end end INTEGRATION TEST class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end

Slide 17

Slide 17 text

Starting point: Ruby 2.1.5 Rails 4.2.0

Slide 18

Slide 18 text

$ time ruby -I lib:test test/controller/ documents_controller_test.rb -n test_index

Slide 19

Slide 19 text

$ time ruby -I lib:test test/controller/ documents_controller_test.rb -n test_index # Running: . Finished in 0.035099s, 28.4908 runs/s, 28.4908 assertions/s. 1 runs, 1 assertions, 0 failures, 0 errors, 0 skips real 0m1.625s user 0m1.346s sys 0m0.274s

Slide 20

Slide 20 text

$ time ruby -I lib:test test/integration/ documents_integration_test.rb -n test_index

Slide 21

Slide 21 text

$ time ruby -I lib:test test/integration/ documents_integration_test.rb -n test_index # Running: . Finished in 0.047088s, 21.2368 runs/s, 21.2368 assertions/s. 1 runs, 1 assertions, 0 failures, 0 errors, 0 skips real 0m2.120s user 0m1.486s sys 0m0.370s

Slide 22

Slide 22 text

23% slower

Slide 23

Slide 23 text

Seconds 0 0.7 1.4 2.1 2.8 Runs 1 2 3 4 5 Controller Integration Controller vs. Integration Using Time

Slide 24

Slide 24 text

time

Slide 25

Slide 25 text

time was not a good baseline

Slide 26

Slide 26 text

GET A BASELINE

Slide 27

Slide 27 text

benchmark-ips github.com/evanphx/benchmark-ips

Slide 28

Slide 28 text

class DocumentsControllerTest < ActionController::Testcase test "index" do get :index assert_equal 200, response.status end end class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Benchmark.ips do |bm| bm.report 'INDEX: Integration Test' do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end bm.report 'INDEX: Functional Test' do Minitest.run_one_method(DocumentsControllerTest, 'test_index') end bm.compare! end

Slide 29

Slide 29 text

class DocumentsControllerTest < ActionController::Testcase test "index" do get :index assert_equal 200, response.status end end class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Benchmark.ips do |bm| bm.report 'INDEX: Integration Test' do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end bm.report 'INDEX: Functional Test' do Minitest.run_one_method(DocumentsControllerTest, 'test_index') end bm.compare! end

Slide 30

Slide 30 text

class DocumentsControllerTest < ActionController::Testcase test "index" do get :index assert_equal 200, response.status end end class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Benchmark.ips do |bm| bm.report 'INDEX: Integration Test' do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end bm.report 'INDEX: Functional Test' do Minitest.run_one_method(DocumentsControllerTest, 'test_index') end bm.compare! end

Slide 31

Slide 31 text

class DocumentsControllerTest < ActionController::Testcase test "index" do get :index assert_equal 200, response.status end end class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Benchmark.ips do |bm| bm.report 'INDEX: Integration Test' do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end bm.report 'INDEX: Functional Test' do Minitest.run_one_method(DocumentsControllerTest, 'test_index') end bm.compare! end

Slide 32

Slide 32 text

class DocumentsControllerTest < ActionController::Testcase test "index" do get :index assert_equal 200, response.status end end class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Benchmark.ips do |bm| bm.report 'INDEX: Integration Test' do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end bm.report 'INDEX: Functional Test' do Minitest.run_one_method(DocumentsControllerTest, 'test_index') end bm.compare! end

Slide 33

Slide 33 text

class DocumentsControllerTest < ActionController::Testcase test "index" do get :index assert_equal 200, response.status end end class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Benchmark.ips do |bm| bm.report 'INDEX: Integration Test' do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end bm.report 'INDEX: Functional Test' do Minitest.run_one_method(DocumentsControllerTest, 'test_index') end bm.compare! end

Slide 34

Slide 34 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

Slide 35

Slide 35 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 36.000 i/100ms INDEX: Functional Test 98.000 i/100ms ------------------------------------------------- INDEX: Integration Test 393.837 (± 8.1%) i/s - 1.980k INDEX: Functional Test 920.765 (± 7.2%) i/s - 4.606k Comparison: INDEX: Functional Test: 920.8 i/s INDEX: Integration Test: 393.8 i/s - 2.34x slower

Slide 36

Slide 36 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 36.000 i/100ms INDEX: Functional Test 98.000 i/100ms ------------------------------------------------- INDEX: Integration Test 393.837 (± 8.1%) i/s - 1.980k INDEX: Functional Test 920.765 (± 7.2%) i/s - 4.606k Comparison: INDEX: Functional Test: 920.8 i/s INDEX: Integration Test: 393.8 i/s - 2.34x slower

Slide 37

Slide 37 text

2.34x slower

Slide 38

Slide 38 text

Sanity check: Ruby 2.1.5 2.2.0 Rails 4.2.0 master

Slide 39

Slide 39 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

Slide 40

Slide 40 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 37.000 i/100ms INDEX: Functional Test 99.000 i/100ms ------------------------------------------------- INDEX: Integration Test 395.025 (±11.1%) i/s - 1.961k INDEX: Functional Test 998.641 (±10.6%) i/s - 4.950k Comparison: INDEX: Functional Test: 998.6 i/s INDEX: Integration Test: 395.0 i/s - 2.53x slower

Slide 41

Slide 41 text

2.53x slower

Slide 42

Slide 42 text

Iterations 0 250 500 750 1000 Rails / Ruby Changes Rails 4.2
 Ruby 2.1.5 Rails master
 Ruby 2.2.0 Controller Integration Controller vs. Integration Iterations 2.34x 2.53x

Slide 43

Slide 43 text

GOT A BASELINE

Slide 44

Slide 44 text

FIND THE CULPRITS

Slide 45

Slide 45 text

RubyProf github.com/ruby-prof/ruby-prof

Slide 46

Slide 46 text

RubyProf Benefit: ✓ Industry standard

Slide 47

Slide 47 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') result = RubyProf.profile do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT)

Slide 48

Slide 48 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') result = RubyProf.profile do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT)

Slide 49

Slide 49 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') result = RubyProf.profile do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT)

Slide 50

Slide 50 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') result = RubyProf.profile do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT)

Slide 51

Slide 51 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb

Slide 52

Slide 52 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? 10.41 0.000 0.000 0.000 0.000 7 #file? 9.33 0.000 0.000 0.000 0.000 1 ActiveSupport::Inflector#underscore 5.96 0.000 0.000 0.000 0.000 1 ActiveSupport::Dependencies#load_missing_constant 5.17 0.000 0.000 0.000 0.000 1 Global#[No method] 4.74 0.000 0.000 0.000 0.000 4 Array#each 4.52 0.000 0.000 0.000 0.000 1 Class#new 4.38 0.000 0.000 0.000 0.000 14 #join 3.02 0.000 0.000 0.000 0.000 3 String#gsub! 2.73 0.000 0.000 0.000 0.000 1 Kernel#caller 2.15 0.000 0.000 0.000 0.000 2 String#sub 1.79 0.000 0.000 0.000 0.000 1 ActiveSupport::Dependencies#search_for_file 1.58 0.000 0.000 0.000 0.000 1 Module#qualified_const_defined? 1.58 0.000 0.000 0.000 0.000 1 ActiveSupport::Dependencies#to_constant_name 1.51 0.000 0.000 0.000 0.000 1 Kernel#nil? 1.51 0.000 0.000 0.000 0.000 1 Array#reject 1.29 0.000 0.000 0.000 0.000 2 Module#const_get 1.15 0.000 0.000 0.000 0.000 1 #raise_if_absolute 1.15 0.000 0.000 0.000 0.000 1 Module#parent_name 0.93 0.000 0.000 0.000 0.000 1 Module#parent ...

Slide 53

Slide 53 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? 10.41 0.000 0.000 0.000 0.000 7 #file? 9.33 0.000 0.000 0.000 0.000 1 ActiveSupport::Inflector#underscore 5.96 0.000 0.000 0.000 0.000 1 ActiveSupport::Dependencies#load_missing_constant 5.17 0.000 0.000 0.000 0.000 1 Global#[No method] 4.74 0.000 0.000 0.000 0.000 4 Array#each 4.52 0.000 0.000 0.000 0.000 1 Class#new 4.38 0.000 0.000 0.000 0.000 14 #join 3.02 0.000 0.000 0.000 0.000 3 String#gsub! 2.73 0.000 0.000 0.000 0.000 1 Kernel#caller 2.15 0.000 0.000 0.000 0.000 2 String#sub 1.79 0.000 0.000 0.000 0.000 1 ActiveSupport::Dependencies#search_for_file 1.58 0.000 0.000 0.000 0.000 1 Module#qualified_const_defined? 1.58 0.000 0.000 0.000 0.000 1 ActiveSupport::Dependencies#to_constant_name 1.51 0.000 0.000 0.000 0.000 1 Kernel#nil? 1.51 0.000 0.000 0.000 0.000 1 Array#reject 1.29 0.000 0.000 0.000 0.000 2 Module#const_get 1.15 0.000 0.000 0.000 0.000 1 #raise_if_absolute 1.15 0.000 0.000 0.000 0.000 1 Module#parent_name 0.93 0.000 0.000 0.000 0.000 1 Module#parent ... wat.

Slide 54

Slide 54 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? % time spent

Slide 55

Slide 55 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? total time spent

Slide 56

Slide 56 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? time spent in method

Slide 57

Slide 57 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? wait time

Slide 58

Slide 58 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? time spent in child

Slide 59

Slide 59 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? # of calls

Slide 60

Slide 60 text

$ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb Measure Mode: wall_time Thread ID: 70361098355200 Fiber ID: 70361103069320 Total: 0.000332 Sort by: self_time %self total self wait child calls name 14.21 0.000 0.000 0.000 0.000 7 #directory? method name

Slide 61

Slide 61 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end result = RubyProf.profile do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end - printer = RubyProf::FlatPrinter.new(result) - printer.print(STDOUT) + File.open('graphs/callstack.html', 'w') do |file| + RubyProf::GraphHtmlPrinter.new(result).print(file) + end

Slide 62

Slide 62 text

No content

Slide 63

Slide 63 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end result = RubyProf.profile do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end File.open('graphs/callstack.html', 'w') do |file| - RubyProf::GraphHtmlPrinter.new(result).print(file) + RubyProf::CallStackPrinter.new(result).print(file) end

Slide 64

Slide 64 text

No content

Slide 65

Slide 65 text

No content

Slide 66

Slide 66 text

No content

Slide 67

Slide 67 text

RubyProf Benefit: ✓ Shows the big picture

Slide 68

Slide 68 text

RubyProf Disadvantage: Data is overwhelming

Slide 69

Slide 69 text

RubyProf: Helped us compare integration and controller test stacks

Slide 70

Slide 70 text

That sounds like a great idea for my RailsConf talk! *not actual statement

Slide 71

Slide 71 text

That sounds like a great idea for my RailsConf talk! *not actual statement

Slide 72

Slide 72 text

StackProf github.com/tmm1/stackprof

Slide 73

Slide 73 text

StackProf Benefit: ✓ Focused profiling

Slide 74

Slide 74 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump’) do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end

Slide 75

Slide 75 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump') do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end

Slide 76

Slide 76 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump') do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end

Slide 77

Slide 77 text

$ ruby -Ilib:test test/integration/documents_stackprof_index_test.rb Run options: --seed 28534 # Running: . Finished in 0.008557s, 116.8634 runs/s, 116.8634 assertions/s.

Slide 78

Slide 78 text

$ stackprof --text test_graphs/index_integration_stackprof.dump

Slide 79

Slide 79 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal 2487 (14.7%) 2487 (14.7%) Dependencies#search_for_file 287 (4.7%) 124 (2.0%) block in Module#delegate 60 (1.0%) 44 (0.7%) ActiveSupport::Subscriber#start 36 (0.6%) 36 (0.6%) Rack::Utils::HeaderHash#[]= 42 (0.7%) 34 (0.6%) SQLite3::Database#prepare 23 (0.4%) 23 (0.4%) Set#include? 17 (0.3%) 17 (0.3%) String#blank? 32 (0.5%) 16 (0.3%) Rack::MockRequest.env_for 15 (0.2%) 15 (0.2%) Rack::BodyProxy#initialize 20 (0.3%) 14 (0.2%) Rack::Utils#parse_nested_query 14 (0.2%) 14 (0.2%) ActiveSupport::PerThreadRegistry#instance 13 (0.2%) 13 (0.2%) ThreadSafe::NonConcurrentCacheBackend#[] 3414 (56.0%) 13 (0.2%) Minitest::Test#time_it 13 (0.2%) 13 (0.2%) URI::Parser#split 12 (0.2%) 12 (0.2%) ActiveSupport::Notifications::Event#initialize 10 (0.2%) 10 (0.2%) ActiveSupport::Configurable::ClassMethods#config 10 (0.2%) 9 (0.1%) Rack::Utils#parse_query 25 (0.4%) 9 (0.1%) ActiveSupport::Subscriber#finish 9 (0.1%) 9 (0.1%) ActiveRecord::Base.logger 8 (0.1%) 8 (0.1%) block in Rack::Utils#clean_path_info 12 (0.2%) 8 (0.1%) URI::Generic#initialize 2888 (47.4%) 8 (0.1%) ActionDispatch::Integration::Session#process 8 (0.1%) 8 (0.1%) ActionDispatch::Response#merge_default_headers 9 (0.1%) 7 (0.1%) block in ActiveSupport::Notifications::Fanout#unsubscribe 7 (0.1%) 7 (0.1%) Rack::Utils::KeySpaceConstrainedParams#to_params_hash 7 (0.1%) 7 (0.1%) block (4 levels) in Class#class_attribute 6 (0.1%) 6 (0.1%) Rack::BodyProxy#respond_to? 6 (0.1%) 6 (0.1%) Minitest::Assertions#message 6 (0.1%) 6 (0.1%) ActionDispatch::Integration::Session#reset!

Slide 80

Slide 80 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal total samples

Slide 81

Slide 81 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal % of total samples

Slide 82

Slide 82 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal samples where most time spent

Slide 83

Slide 83 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal samples where most time spent

Slide 84

Slide 84 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal samples where most time spent

Slide 85

Slide 85 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal 2487 (14.7%) 2487 (14.7%) Dependencies#search_for_file 287 (4.7%) 124 (2.0%) block in Module#delegate 60 (1.0%) 44 (0.7%) ActiveSupport::Subscriber#start 36 (0.6%) 36 (0.6%) Rack::Utils::HeaderHash#[]= 42 (0.7%) 34 (0.6%) SQLite3::Database#prepare 23 (0.4%) 23 (0.4%) Set#include? 17 (0.3%) 17 (0.3%) String#blank? 32 (0.5%) 16 (0.3%) Rack::MockRequest.env_for 15 (0.2%) 15 (0.2%) Rack::BodyProxy#initialize 20 (0.3%) 14 (0.2%) Rack::Utils#parse_nested_query 14 (0.2%) 14 (0.2%) ActiveSupport::PerThreadRegistry#... 13 (0.2%) 13 (0.2%) ThreadSafe::NonConcurrentCacheBack... 3414 (56.0%) 13 (0.2%) Minitest::Test#time_it

Slide 86

Slide 86 text

# minitest/lib/minitest.rb def self.on_signal name, action # :nodoc: supported = SIGNALS[name] old_trap = trap name do old_trap.call if old_trap.respond_to? :call action.call end if supported yield ensure trap name, old_trap if supported end

Slide 87

Slide 87 text

# minitest/lib/minitest.rb def self.on_signal name, action # :nodoc: - supported = SIGNALS[name] - old_trap = trap name do - old_trap.call if old_trap.respond_to? :call - action.call - end if supported yield - ensure - trap name, old_trap if supported end

Slide 88

Slide 88 text

# minitest/lib/minitest.rb def self.on_signal name, action # :nodoc: yield end

Slide 89

Slide 89 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: cpu(1000) Samples: 6097 (0.00% miss rate) GC: 194 (3.18%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 2487 (14.7%) 2487 (14.7%) Dependencies#search_for_file 287 (4.7%) 124 (2.0%) block in Module#delegate 60 (1.0%) 44 (0.7%) ActiveSupport::Subscriber#start 36 (0.6%) 36 (0.6%) Rack::Utils::HeaderHash#[]= 42 (0.7%) 34 (0.6%) SQLite3::Database#prepare 23 (0.4%) 23 (0.4%) Set#include? 17 (0.3%) 17 (0.3%) String#blank? 32 (0.5%) 16 (0.3%) Rack::MockRequest.env_for 15 (0.2%) 15 (0.2%) Rack::BodyProxy#initialize 20 (0.3%) 14 (0.2%) Rack::Utils#parse_nested_query 14 (0.2%) 14 (0.2%) ActiveSupport::PerThreadRegistry#... 13 (0.2%) 13 (0.2%) ThreadSafe::NonConcurrentCacheBack... 3414 (56.0%) 13 (0.2%) Minitest::Test#time_it

Slide 90

Slide 90 text

Done!

Slide 91

Slide 91 text

No content

Slide 92

Slide 92 text

A B B

Slide 93

Slide 93 text

ALWAYS B B

Slide 94

Slide 94 text

ALWAYS BE B

Slide 95

Slide 95 text

ALWAYS BE BENCHMARKING

Slide 96

Slide 96 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

Slide 97

Slide 97 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 37.000 i/100ms INDEX: Functional Test 99.000 i/100ms ------------------------------------------------- INDEX: Integration Test 395.025 (±11.1%) i/s - 1.961k INDEX: Functional Test 998.641 (±10.6%) i/s - 4.950k Comparison: INDEX: Functional Test: 998.6 i/s INDEX: Integration Test: 395.0 i/s - 2.53x slower

Slide 98

Slide 98 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 37.000 i/100ms INDEX: Functional Test 99.000 i/100ms ------------------------------------------------- INDEX: Integration Test 395.025 (±11.1%) i/s - 1.961k INDEX: Functional Test 998.641 (±10.6%) i/s - 4.950k Comparison: INDEX: Functional Test: 998.6 i/s INDEX: Integration Test: 395.0 i/s - 2.53x slower Huh...?

Slide 99

Slide 99 text

No content

Slide 100

Slide 100 text

StackProf Disadvantage: Bug in CPU time on OSX

Slide 101

Slide 101 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') - StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump') do + StackProf.run(mode: :wall, out: ‘graphs/stackprof.dump') do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end

Slide 102

Slide 102 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: wall(1000) Samples: 7869 (0.34% miss rate) GC: 544 (6.91%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 2512 (31.9%) 2230 (28.3%) block in Module#delegate 185 (2.4%) 185 (2.4%) ActiveSupport::PerThreadRegistry#instance 143 (1.8%) 143 (1.8%) Set#include? 116 (1.5%) 116 (1.5%) ThreadSafe::NonConcurrentCacheBackend#[] 97 (1.2%) 97 (1.2%) block (4 levels) in Class#class_attribute 92 (1.2%) 92 (1.2%) Rack::Utils::HeaderHash#[]= 129 (1.6%) 82 (1.0%) block (2 levels) in Class#class_attribute 145 (1.8%) 64 (0.8%) Rack::BodyProxy#respond_to? 62 (0.8%) 62 (0.8%) MonitorMixin#mon_enter 61 (0.8%) 61 (0.8%) URI::RFC3986_Parser#split 115 (1.5%) 61 (0.8%) SQLite3::Database#prepare 57 (0.7%) 57 (0.7%) String#blank? 56 (0.7%) 56 (0.7%) block in ActionDispatch::FileHandler#match? 55 (0.7%) 55 (0.7%) ActiveSupport::Notifications::Fanout::Subscribers::Evented#subscribed_to? 54 (0.7%) 54 (0.7%) ActiveRecord::Base.logger 2713 (34.5%) 53 (0.7%) block in ActionDispatch::Routing::RouteSet#url_helpers 137 (1.7%) 52 (0.7%) Rack::MockRequest.env_for 49 (0.6%) 49 (0.6%) Rack::Request#initialize 46 (0.6%) 46 (0.6%) ActiveSupport::Configurable::ClassMethods#config 43 (0.5%) 43 (0.5%) ActiveSupport::Notifications::Event#initialize 37 (0.5%) 37 (0.5%) MonitorMixin#mon_initialize 75 (1.0%) 37 (0.5%) URI::Generic#initialize 46 (0.6%) 34 (0.4%) Rack::Utils#parse_nested_query 34 (0.4%) 34 (0.4%) ActiveSupport::InheritableOptions#initialize 33 (0.4%) 33 (0.4%) ActionDispatch::Integration::Runner#integration_session 33 (0.4%) 33 (0.4%) block in Rack::Utils#clean_path_info 33 (0.4%) 33 (0.4%) Rails::Engine#routes 259 (3.3%) 33 (0.4%) Rack::Test::Session#env_for 61 (0.8%) 29 (0.4%) ActiveSupport::Concern#append_features 28 (0.4%) 28 (0.4%) NilClass#blank?

Slide 103

Slide 103 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: wall(1000) Samples: 7869 (0.34% miss rate) GC: 544 (6.91%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 2512 (31.9%) 2230 (28.3%) block in Module#delegate 185 (2.4%) 185 (2.4%) ActiveSupport::PerThreadRegistry... 143 (1.8%) 143 (1.8%) Set#include? 116 (1.5%) 116 (1.5%) ThreadSafe::NonConcurrentCache... 97 (1.2%) 97 (1.2%) block (4 levels) in Class#... 92 (1.2%) 92 (1.2%) Rack::Utils::HeaderHash#[]= 129 (1.6%) 82 (1.0%) block (2 levels) in Class#class_... 145 (1.8%) 64 (0.8%) Rack::BodyProxy#respond_to? 62 (0.8%) 62 (0.8%) MonitorMixin#mon_enter 61 (0.8%) 61 (0.8%) URI::RFC3986_Parser#split 115 (1.5%) 61 (0.8%) SQLite3::Database#prepare 57 (0.7%) 57 (0.7%) String#blank? 56 (0.7%) 56 (0.7%) block in ActionDispatch::File... 55 (0.7%) 55 (0.7%) ActiveSupport::Notifications::...

Slide 104

Slide 104 text

--- a/actionpack/lib/action_dispatch/routing/route_set.rb +++ b/actionpack/lib/action_dispatch/routing/route_set.rb class << self - delegate :url_for, :optimize_routes_generation?, to: '@_routes' + def url_for(options) + @_routes.url_for(options) + end + + def optimize_routes_generation? + @_routes.optimize_routes_generation? + end + attr_reader :_routes def url_options; {}; end end

Slide 105

Slide 105 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: wall(1000) Samples: 4383 (0.02% miss rate) GC: 488 (11.13%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 176 (4.0%) 176 (4.0%) ActiveSupport::PerThreadRegistry#... 138 (3.1%) 138 (3.1%) ThreadSafe::NonConcurrentCacheBa... 91 (2.1%) 91 (2.1%) Rack::Utils::HeaderHash#[]= 95 (2.2%) 68 (1.6%) block (2 levels) in Class#class_... 63 (1.4%) 63 (1.4%) block (4 levels) in Class#class_... 62 (1.4%) 62 (1.4%) ActiveSupport::Notifications::Fan... 112 (2.6%) 62 (1.4%) SQLite3::Database#prepare 57 (1.3%) 57 (1.3%) URI::RFC3986_Parser#split 51 (1.2%) 51 (1.2%) String#blank? 46 (1.0%) 46 (1.0%) ActiveRecord::Base.logger 95 (2.2%) 45 (1.0%) Rack::BodyProxy#respond_to? 45 (1.0%) 45 (1.0%) ActiveSupport::Notifications::... 43 (1.0%) 43 (1.0%) MonitorMixin#mon_enter 41 (0.9%) 41 (0.9%) Rack::Request#initialize

Slide 106

Slide 106 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

Slide 107

Slide 107 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 53.000 i/100ms INDEX: Functional Test 72.000 i/100ms ------------------------------------------------- INDEX: Integration Test 549.617 (±12.4%) i/s - 2.703k INDEX: Functional Test 768.021 (± 9.2%) i/s - 3.816k Comparison: INDEX: Functional Test: 768.0 i/s INDEX: Integration Test: 549.6 i/s - 1.40x slower

Slide 108

Slide 108 text

Iterations 0 250 500 750 1000 Changes to Ruby / Rails Rails master
 Ruby 2.2.0 Expand
 Methods Controller Integration Controller vs. Integration Iterations 2.53x 1.40x

Slide 109

Slide 109 text

StackProf Benefit: ✓ Helps pinpoint the
 problem quickly

Slide 110

Slide 110 text

StackProf Disadvantage: Difficult to pinpoint problems in anonymous modules

Slide 111

Slide 111 text

RubyVM.stat ruby standard library

Slide 112

Slide 112 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') puts RubyVM.stat Minitest.run_one_method(DocumentsIntegrationTest, ‘test_index') puts RubyVM.stat

Slide 113

Slide 113 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') puts RubyVM.stat Minitest.run_one_method(DocumentsIntegrationTest, ‘test_index') puts RubyVM.stat

Slide 114

Slide 114 text

require 'test_helper' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') puts RubyVM.stat Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') puts RubyVM.stat

Slide 115

Slide 115 text

{:global_method_state=>198, :global_constant_state=>7823, :class_serial=>181492} {:global_method_state=>198, :global_constant_state=>7824, :class_serial=>181522}

Slide 116

Slide 116 text

{:global_method_state=>198, :global_constant_state=>7823, :class_serial=>181492} {:global_method_state=>198, :global_constant_state=>7824, :class_serial=>181522} creating an extra constant

Slide 117

Slide 117 text

def url_helpers(supports_path = true) routes = self Module.new do extend ActiveSupport::Concern include UrlFor # Define url_for in the singleton level so one can do: # Rails.application.routes.url_helpers.url_for(args) @_routes = routes class << self delegate :url_for, :optimize_routes_generation?, to: '@_routes' attr_reader :_routes def url_options; {}; end end url_helpers = routes.named_routes.url_helpers_module # Make named_routes available in the module singleton # as well, so one can do: # Rails.application.routes.url_helpers.posts_path [...]

Slide 118

Slide 118 text

def url_helpers(supports_path = true) routes = self Module.new do extend ActiveSupport::Concern include UrlFor # Define url_for in the singleton level so one can do: # Rails.application.routes.url_helpers.url_for(args) @_routes = routes class << self delegate :url_for, :optimize_routes_generation?, to: '@_routes' attr_reader :_routes def url_options; {}; end end url_helpers = routes.named_routes.url_helpers_module # Make named_routes available in the module singleton # as well, so one can do: # Rails.application.routes.url_helpers.posts_path [...] anonymous module

Slide 119

Slide 119 text

--- a/actionpack/lib/action_dispatch/routing/route_set.rb +++ b/actionpack/lib/action_dispatch/routing/route_set.rb def url_helpers(supports_path = true) - routes = self - - Module new do ... + @url_helpers ||= begin + routes = self + + Module.new do ... + @_routes = routes + class << self + def url_for(options) + @_routes.url_for(options)

Slide 120

Slide 120 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

Slide 121

Slide 121 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 74.000 i/100ms INDEX: Functional Test 99.000 i/100ms ------------------------------------------------- INDEX: Integration Test 752.377 (± 6.9%) i/s - 3.774k INDEX: Functional Test 1.021k (± 6.7%) i/s - 5.148k Comparison: INDEX: Functional Test: 1021.1 i/s INDEX: Integration Test: 752.4 i/s - 1.36x slower

Slide 122

Slide 122 text

Iterations 0 275 550 825 1100 Changes to Rails Before Changes Expand Methods Caching url_helpers Controller Integration Controller vs. Integration Iterations 2.53x 1.40x 1.36x

Slide 123

Slide 123 text

No content

Slide 124

Slide 124 text

CACHING IS EXPENSIVE

Slide 125

Slide 125 text

diff --git a/actionpack/lib/action_dispatch/routing/route_set.rb b/actionpack/lib/action_dispatch/routing/route_set.rb index 948cbdc..65d6a5e 100644 --- a/actionpack/lib/action_dispatch/routing/route_set.rb +++ b/actionpack/lib/action_dispatch/routing/route_set.rb @@ -409,14 +409,6 @@ module ActionDispatch end def url_helpers(supports_path = true) - if supports_path - @url_helpers_with_paths ||= generate_url_helpers(supports_path) - else - @url_helpers_without_paths ||= generate_url_helpers(supports_path) - end - end - - def generate_url_helpers(supports_path) routes = self Module.new do diff --git a/actionpack/lib/action_dispatch/testing/integration.rb b/actionpack/lib/action_dispatch/testing/integration.rb index 876a980..f9ef806 100644 --- a/actionpack/lib/action_dispatch/testing/integration.rb +++ b/actionpack/lib/action_dispatch/testing/integration.rb @@ -222,15 +222,6 @@ module ActionDispatch super() @app = app - # If the app is a Rails app, make url_helpers available on the session - # This makes app.url_for and app.foo_path available in the console - if app.respond_to?(:routes) - singleton_class.class_eval do - include app.routes.url_helpers - include app.routes.mounted_helpers - end - end - reset! end @@ -396,6 +387,8 @@ module ActionDispatch module Runner include ActionDispatch::Assertions + APP_SESSIONS = {} + def app @app ||= nil end @@ -403,7 +396,19 @@ module ActionDispatch # Reset the current session. This is useful for testing multiple sessions # in a single test case. def reset! - @integration_session = Integration::Session.new(app) + @integration_session = create_session(app) + end + + def create_session(app) + klass = APP_SESSIONS[app] ||= Class.new(Integration::Session) { + # If the app is a Rails app, make url_helpers available on the session + # This makes app.url_for and app.foo_path available in the console + if app.respond_to?(:routes) + include app.routes.url_helpers + include app.routes.mounted_helpers + end + } + klass.new(app) end

Slide 126

Slide 126 text

--- a/actionpack/lib/action_dispatch/testing/integration.rb +++ b/actionpack/lib/action_dispatch/testing/integration.rb super() @app = app - # If the app is a Rails app, make url_helpers available on the session - # This makes app.url_for and app.foo_path available in the console - if app.respond_to?(:routes) - singleton_class.class_eval do - include app.routes.url_helpers - include app.routes.mounted_helpers - end - end - reset! end

Slide 127

Slide 127 text

def reset! - @integration_session = Integration::Session.new(app) + @integration_session = create_session(app) + end + + def create_session(app) + klass = APP_SESSIONS[app] ||= Class.new(Integration::Session) { + # If the app is a Rails app, make url_helpers available on the + # This makes app.url_for and app.foo_path available in the console + if app.respond_to?(:routes) + include app.routes.url_helpers + include app.routes.mounted_helpers + end + } + klass.new(app) end

Slide 128

Slide 128 text

$ ruby -Ilib:test test/integration/ documents_rubyvm_index_test.rb

Slide 129

Slide 129 text

{:global_method_state=>198, :global_constant_state=>7822, :class_serial=>181492} {:global_method_state=>198, :global_constant_state=>7822, :class_serial=>181522} no new constants

Slide 130

Slide 130 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

Slide 131

Slide 131 text

$ ruby -Ilib:test test/controllers/documents_benchmark_test.rb Calculating ------------------------------------- INDEX: Integration Test 87.000 i/100ms INDEX: Functional Test 97.000 i/100ms ------------------------------------------------- INDEX: Integration Test 828.433 (± 6.4%) i/s - 4.176k INDEX: Functional Test 926.763 (± 7.2%) i/s - 4.656k Comparison: INDEX: Functional Test: 926.8 i/s INDEX: Integration Test: 828.4 i/s - 1.12x slower

Slide 132

Slide 132 text

Iterations 0 275 550 825 1100 Changes to Rails/Rack Start Expand Methods Caching Move #url_helpers Controller Integration Controller vs. Integration Iterations 2.53x 1.40x 1.36x 1.12x

Slide 133

Slide 133 text

And then a lot more improvements were made...

Slide 134

Slide 134 text

$ stackprof --text test_graphs/index_integration_stackprof.dump ================================== Mode: wall(1000) Samples: 4383 (0.02% miss rate) GC: 488 (11.13%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 176 (4.0%) 176 (4.0%) ActiveSupport::PerThreadRegistry#... 138 (3.1%) 138 (3.1%) ThreadSafe::NonConcurrentCacheBa... 91 (2.1%) 91 (2.1%) Rack::Utils::HeaderHash#[]= 95 (2.2%) 68 (1.6%) block (2 levels) in Class#class_... 63 (1.4%) 63 (1.4%) block (4 levels) in Class#class_... 62 (1.4%) 62 (1.4%) ActiveSupport::Notifications::Fan... 112 (2.6%) 62 (1.4%) SQLite3::Database#prepare 57 (1.3%) 57 (1.3%) URI::RFC3986_Parser#split 51 (1.2%) 51 (1.2%) String#blank? 46 (1.0%) 46 (1.0%) ActiveRecord::Base.logger 95 (2.2%) 45 (1.0%) Rack::BodyProxy#respond_to? 45 (1.0%) 45 (1.0%) ActiveSupport::Notifications::... 43 (1.0%) 43 (1.0%) MonitorMixin#mon_enter 41 (0.9%) 41 (0.9%) Rack::Request#initialize

Slide 135

Slide 135 text

AllocationTracer github.com/ko1/allocation_tracer

Slide 136

Slide 136 text

AllocationTracer Benefit: ✓ Focuses on a specific problem

Slide 137

Slide 137 text

require 'test_helper' require 'objspace' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end ObjectSpace::AllocationTracer.setup(%i{path line type}) result = ObjectSpace::AllocationTracer.trace do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end result.sort_by { |info, counts| counts.first } .reverse.first(5).each do |r| puts r end

Slide 138

Slide 138 text

require 'test_helper' require 'objspace' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end ObjectSpace::AllocationTracer.setup(%i{path line type}) result = ObjectSpace::AllocationTracer.trace do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end result.sort_by { |info, counts| counts.first } .reverse.first(5).each do |r| puts r end

Slide 139

Slide 139 text

require 'test_helper' require 'objspace' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end ObjectSpace::AllocationTracer.setup(%i{path line type}) result = ObjectSpace::AllocationTracer.trace do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end result.sort_by { |info, counts| counts.first } .reverse.first(5).each do |r| puts r end

Slide 140

Slide 140 text

require 'test_helper' require 'objspace' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end ObjectSpace::AllocationTracer.setup(%i{path line type}) result = ObjectSpace::AllocationTracer.trace do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end result.sort_by { |info, counts| counts.first } .reverse.first(5).each do |r| puts r end

Slide 141

Slide 141 text

require 'test_helper' require 'objspace' class DocumentsIntegrationTest < ActionDispatch::IntegrationTest test "index" do get '/documents' assert_equal 200, response.status end end ObjectSpace::AllocationTracer.setup(%i{path line type}) result = ObjectSpace::AllocationTracer.trace do 3000.times do Minitest.run_one_method(DocumentsIntegrationTest, 'test_index') end end result.sort_by { |info, counts| counts.first } .reverse.first(5).each do |r| puts r end

Slide 142

Slide 142 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb

Slide 143

Slide 143 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]

Slide 144

Slide 144 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] path

Slide 145

Slide 145 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] line number

Slide 146

Slide 146 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] type

Slide 147

Slide 147 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] total count

Slide 148

Slide 148 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] old count

Slide 149

Slide 149 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] total age of objects

Slide 150

Slide 150 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] minimum age of objects

Slide 151

Slide 151 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] maximum age of objects

Slide 152

Slide 152 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]] total memory size

Slide 153

Slide 153 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]] [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]] [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]] [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]] [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]

Slide 154

Slide 154 text

--- a/lib/rack/utils.rb +++ b/lib/rack/utils.rb def []=(k, v) - canonical = k.downcase + canonical = k.downcase.freeze delete k if @names[canonical] && @names[canonical] != k @names[k] = @names[canonical] = k super k, v --- a/lib/rack/runtime.rb +++ b/lib/rack/runtime.rb class Runtime + FORMAT_STRING = "%0.6f".freeze # :nodoc: + HEADER_NAME = "X-Runtime".freeze # :nodoc: def initialize(app, name = nil)

Slide 155

Slide 155 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 499, :T_STRING], [51034, 4539, 71559, 0, 12, 1791120]] [["rack/lib/rack/utils.rb", 662, :T_STRING], [33012, 0, 27930, 0, 1, 1226009]] [["rails/activesupport/lib/active_support/notifications/fanout.rb", 55, :T_DATA], [29998, 0, 25380, 0, 1, 3230600]] [["rails/activesupport/lib/active_support/subscriber.rb", 99, :T_STRING], [29996, 0, 25378, 0, 2, 1113840]] [["rails/activesupport/lib/active_support/notifications/instrumenter.rb", 52, :T_HASH], [29994, 147, 27014, 0, 11, 4897784]]

Slide 156

Slide 156 text

$ ruby -Ilib:test test/integration/documents_allocations_index_test.rb [["rack/lib/rack/utils.rb", 499, :T_STRING], [51034, 4539, 71559, 0, 12, 1791120]] [["rack/lib/rack/utils.rb", 662, :T_STRING], [33012, 0, 27930, 0, 1, 1226009]] [["rails/activesupport/lib/active_support/notifications/fanout.rb", 55, :T_DATA], [29998, 0, 25380, 0, 1, 3230600]] [["rails/activesupport/lib/active_support/subscriber.rb", 99, :T_STRING], [29996, 0, 25378, 0, 2, 1113840]] [["rails/activesupport/lib/active_support/notifications/instrumenter.rb", 52, :T_HASH], [29994, 147, 27014, 0, 11, 4897784]]

Slide 157

Slide 157 text

No content

Slide 158

Slide 158 text

No content

Slide 159

Slide 159 text

PROVE ALLOCATIONS ARE A BOTTLENECK

Slide 160

Slide 160 text

AllocationTracer: Helped us find unnecessary allocations of objects

Slide 161

Slide 161 text

Controller vs. Integration Iterations Iterations 0 275 550 825 1100 Changes to Rails/Rack Start Expand Methods Caching Move #url_helpers Controller Integration 2.53x 1.40x 1.36x 1.12x

Slide 162

Slide 162 text

VS ITERATIONS BEFORE 393.8 ITERATIONS AFTER 828.4

Slide 163

Slide 163 text

~3x faster

Slide 164

Slide 164 text

KNOW YOUR TOOLS

Slide 165

Slide 165 text

USE MULTIPLE TOOLS

Slide 166

Slide 166 text

ALWAYS BE BENCHMARKING

Slide 167

Slide 167 text

Thanks @tenderlove!

Slide 168

Slide 168 text

Thank you! @ko1 @ruby-prof @tmm1 and YOU! @evanphx

Slide 169

Slide 169 text

! eileencodes.com " @eileencodes # @eileencodes EILEEN M. UCHITELLE Programmer at Basecamp Slides: speakerdeck.com/eileencodes