WindyCityRails 2015 - How to Performance

WindyCityRails 2015 - How to Performance

Understanding performance output can feel like reading tea leaves. It makes sense to a few people, but many of us are left in the dark; overwhelmed and frustrated by the data. On top of that there are a ton of performance tools to choose from; StackProf, RubyProf, AllocationTracer. Where do you even start?

While working on speeding up integration tests in Rails source, I learned that the key to improving the performance of Ruby code is having a baseline, not relying on one profiler and understanding the advantages and limitations of your tools. By utilizing these methods, integration tests are now 3 times faster than they were in Rails 4.2.0, with more improvements being made every day.

In this talk we will not only look at how to read performance output, but when and how to use the right profilers for the job. We'll discuss a variety of methods and techniques for benchmarking and profiling so you can get the most out of any performance tool.

C44e1f7e22c3f23cff7bc130871047ef?s=128

Eileen M. Uchitelle

September 18, 2015
Tweet

Transcript

  1. How to Performance WindyCityRails 2015

  2. ! eileencodes.com " @eileencodes # @eileencodes EILEEN M. UCHITELLE Programmer

    at Basecamp
  3. rails committers team & rails security team

  4. Arya @aryadog

  5. Kingston, NY

  6. None
  7. None
  8. VS BENCHMARKING PROFILING

  9. benchmarking how slow something is

  10. profiling what is slow

  11. Hey Eileen, I drive race cars so, I really hate

    it when things are slowwwwwww... *not actual statement
  12. Can you see what you can do about speeding up

    integration tests in Ruby on Rails? *not actual statement
  13. Totes McGoats David! I <3 performance! *not actual statement

  14. GET A BASELINE

  15. github.com/eileencodes/ integration_performance_test

  16. 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
  17. Starting point: Ruby 2.1.5 Rails 4.2.0

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

  19. $ 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
  20. $ time ruby -I lib:test test/integration/ documents_integration_test.rb -n test_index

  21. $ 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
  22. 23% slower

  23. Seconds 0 0.7 1.4 2.1 2.8 Runs 1 2 3

    4 5 Controller Integration Controller vs. Integration Using Time
  24. time

  25. time was not a good baseline

  26. GET A BASELINE

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

  28. 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
  29. 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
  30. 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
  31. 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
  32. 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
  33. 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
  34. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

  35. $ 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
  36. $ 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
  37. 2.34x slower

  38. Sanity check: Ruby 2.1.5 2.2.0 Rails 4.2.0 master

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

  40. $ 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
  41. 2.53x slower

  42. 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
  43. GOT A BASELINE

  44. FIND THE CULPRITS

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

  46. RubyProf Benefit: ✓ Industry standard

  47. 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)
  48. 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)
  49. 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)
  50. 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)
  51. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb

  52. $ 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 <Class::File>#directory? 10.41 0.000 0.000 0.000 0.000 7 <Class::File>#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 <Class::File>#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 <Module::QualifiedConstUtils>#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 ...
  53. $ 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 <Class::File>#directory? 10.41 0.000 0.000 0.000 0.000 7 <Class::File>#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 <Class::File>#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 <Module::QualifiedConstUtils>#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.
  54. $ 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 <Class::File>#directory? % time spent
  55. $ 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 <Class::File>#directory? total time spent
  56. $ 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 <Class::File>#directory? time spent in method
  57. $ 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 <Class::File>#directory? wait time
  58. $ 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 <Class::File>#directory? time spent in child
  59. $ 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 <Class::File>#directory? # of calls
  60. $ 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 <Class::File>#directory? method name
  61. 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
  62. None
  63. 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
  64. None
  65. None
  66. None
  67. RubyProf Benefit: ✓ Shows the big picture

  68. RubyProf Disadvantage: Data is overwhelming

  69. RubyProf: Helped us compare integration and controller test stacks

  70. That sounds like a great idea for my RailsConf talk!

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

    *not actual statement
  72. StackProf github.com/tmm1/stackprof

  73. StackProf Benefit: ✓ Focused profiling

  74. 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
  75. 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
  76. 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
  77. $ 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.
  78. $ stackprof --text test_graphs/index_integration_stackprof.dump

  79. $ 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!
  80. $ 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
  81. $ 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
  82. $ 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
  83. $ 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
  84. $ 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
  85. $ 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
  86. # 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
  87. # 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
  88. # minitest/lib/minitest.rb def self.on_signal name, action # :nodoc: yield end

  89. $ 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
  90. Done!

  91. None
  92. A B B

  93. ALWAYS B B

  94. ALWAYS BE B

  95. ALWAYS BE BENCHMARKING

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

  97. $ 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
  98. $ 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...?
  99. None
  100. StackProf Disadvantage: Bug in CPU time on OSX

  101. 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
  102. $ 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?
  103. $ 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::...
  104. --- 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
  105. $ 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
  106. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

  107. $ 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
  108. 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
  109. StackProf Benefit: ✓ Helps pinpoint the
 problem quickly

  110. StackProf Disadvantage: Difficult to pinpoint problems in anonymous modules

  111. RubyVM.stat ruby standard library

  112. 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
  113. 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
  114. 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
  115. {:global_method_state=>198, :global_constant_state=>7823, :class_serial=>181492} {:global_method_state=>198, :global_constant_state=>7824, :class_serial=>181522}

  116. {: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

  117. 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 [...]
  118. 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
  119. --- 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)
  120. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb

  121. $ 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
  122. 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
  123. None
  124. CACHING IS EXPENSIVE

  125. 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
  126. --- 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
  127. 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
  128. $ ruby -Ilib:test test/integration/ documents_rubyvm_index_test.rb

  129. {: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

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

  131. $ 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
  132. 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
  133. And then a lot more improvements were made...

  134. $ 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
  135. AllocationTracer github.com/ko1/allocation_tracer

  136. AllocationTracer Benefit: ✓ Focuses on a specific problem

  137. 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
  138. 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
  139. 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
  140. 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
  141. 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
  142. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb

  143. $ 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]]
  144. $ 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
  145. $ 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
  146. $ 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
  147. $ 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
  148. $ 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
  149. $ 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
  150. $ 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
  151. $ 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
  152. $ 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
  153. $ 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]]
  154. --- 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)
  155. $ 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]]
  156. $ 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]]
  157. None
  158. None
  159. PROVE ALLOCATIONS ARE A BOTTLENECK

  160. AllocationTracer: Helped us find unnecessary allocations of objects

  161. 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
  162. VS ITERATIONS BEFORE 393.8 ITERATIONS AFTER 828.4

  163. ~3x faster

  164. KNOW YOUR TOOLS

  165. USE MULTIPLE TOOLS

  166. ALWAYS BE BENCHMARKING

  167. Thanks @tenderlove!

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

  169. ! eileencodes.com " @eileencodes # @eileencodes EILEEN M. UCHITELLE Programmer

    at Basecamp Slides: speakerdeck.com/eileencodes