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

Transcript

1. How to Performance RubyConf 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
8. Why?
9. CONSOLIDATE CODE
10. DEMONSTRATING OUR PROCESS
11. VS BENCHMARKING PROFILING
12. benchmarking how slow something is
13. profiling what is slow
14. Hey Eileen, I drive race cars so, I really hate it when things are slowwwwwww... *not actual statement
15. Can you see what you can do about speeding up integration tests in Ruby on Rails? *not actual statement
16. Totes McGoats David! I <3 performance! *not actual statement
17. GET A BASELINE
18. github.com/eileencodes/ integration_performance_test
19. 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
20. Starting point: Ruby 2.1.5 Rails 4.2.0
21. $ time ruby -I lib:test test/controller/ documents_controller_test.rb -n test_index
22. $ 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
23. $ time ruby -I lib:test test/integration/ documents_integration_test.rb -n test_index
24. $ 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
25. 23% slower
26. Seconds 0 0.7 1.4 2.1 2.8 Runs 1 2 3 4 5 Controller Integration Controller vs. Integration Using Time
27. time
28. time was not a good baseline
29. GET A BASELINE
30. benchmark-ips github.com/evanphx/benchmark-ips
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. 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
35. 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
36. 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
37. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
38. $ 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
39. $ 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
40. 2.34x slower
41. Sanity check: Ruby 2.1.5 2.2.0 Rails 4.2.0 master
42. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
43. $ 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
44. 2.53x slower
45. 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
46. GOT A BASELINE
47. FIND THE CULPRITS
48. RubyProf github.com/ruby-prof/ruby-prof
49. RubyProf Benefit: ✓ Industry standard
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. 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)
52. 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)
53. 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)
54. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb
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? 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 ...
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? 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.
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? % time spent
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? total time spent
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? time spent in method
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? wait time
61. $ 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
62. $ 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
63. $ 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
64. 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
66. 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
70. RubyProf Benefit: ✓ Shows the big picture
71. RubyProf Disadvantage: Data is overwhelming
72. RubyProf: Helped us compare integration and controller test stacks
73. That sounds like a great idea for my RailsConf talk! *not actual statement
74. That sounds like a great idea for my RailsConf talk! *not actual statement
75. StackProf github.com/tmm1/stackprof
76. StackProf Benefit: ✓ Focused profiling
77. 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
78. 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
79. 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
80. $ 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.
81. $ stackprof --text test_graphs/index_integration_stackprof.dump
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 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!
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 total samples
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 % of total samples
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 samples where most time spent
86. $ 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
87. $ 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
88. $ 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
89. # 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
90. # 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
91. # minitest/lib/minitest.rb def self.on_signal name, action # :nodoc: yield end
92. $ 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
93. Done!
95. A B B
96. ALWAYS B B
97. ALWAYS BE B
98. ALWAYS BE BENCHMARKING
99. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
100. $ 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
101. $ 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...?
103. StackProf Disadvantage: Bug in CPU time on OSX
104. 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
105. $ 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?
106. $ 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::...
107. --- 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
108. $ 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
109. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
110. $ 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
111. 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
112. StackProf Benefit: ✓ Helps pinpoint the
 problem quickly
113. StackProf Disadvantage: Difficult to pinpoint problems in anonymous modules
114. RubyVM.stat ruby standard library
115. 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
116. 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
117. 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
118. {:global_method_state=>198, :global_constant_state=>7823, :class_serial=>181492} {:global_method_state=>198, :global_constant_state=>7824, :class_serial=>181522}
119. {: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
120. 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 [...]
121. 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
122. --- 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)
123. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
124. $ 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
125. 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
127. CACHING IS EXPENSIVE
128. 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
129. --- 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
130. 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
131. $ ruby -Ilib:test test/integration/ documents_rubyvm_index_test.rb
132. {: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
133. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
134. $ 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
135. 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
136. And then a lot more improvements were made...
137. $ 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
138. AllocationTracer github.com/ko1/allocation_tracer
139. AllocationTracer Benefit: ✓ Focuses on a specific problem
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. 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
143. 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
144. 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
145. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
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]]
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]] path
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]] line number
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]] type
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]] total count
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]] old count
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 age of objects
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]] minimum age of objects
154. $ 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
155. $ 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
156. $ 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]]
157. --- 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)
158. $ 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]]
159. $ 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]]
162. PROVE ALLOCATIONS ARE A BOTTLENECK
163. AllocationTracer: Helped us find unnecessary allocations of objects
164. 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
165. VS ITERATIONS BEFORE 393.8 ITERATIONS AFTER 828.4
166. ~3x faster
167. KNOW YOUR TOOLS
168. USE MULTIPLE TOOLS
169. ALWAYS BE BENCHMARKING
170. Thanks @tenderlove!
171. Thank you! @ko1 @ruby-prof @tmm1 and YOU! @evanphx
173. ! eileencodes.com " @eileencodes # @eileencodes EILEEN M. UCHITELLE Programmer at Basecamp Slides: speakerdeck.com/eileencodes