GORUCO 2015 - How to Performance

http://confreaks.tv/videos/goruco2015-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. wow such speed much performance very impressive amaze so awesome
2. How to Performance
3. ! eileencodes.com ! @eileencodes " @eileencodes EILEEN M. UCHITELLE Programmer at Basecamp
4. Arya @aryadog
5. Kingston, NY
6. catskillsconf.com Oct 23-25, 2015 Ashokan Center in NY
10. Hey Eileen, I drive race cars so, I really hate it when things are slowwwwwww... *not actual statement
11. Can you see what you can do about speeding up integration tests in Ruby on Rails? *not actual statement
12. Totes McGoats David! I <3 performance! *not actual statement
13. GET A BASELINE
14. github.com/eileencodes/ integration_performance_test
15. 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
16. Starting point: Ruby 2.1.5 Rails 4.2.0
17. $ time ruby -I lib:test test/controller/ documents_controller_test.rb -n test_index
18. $ 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
19. $ time ruby -I lib:test test/integration/ documents_integration_test.rb -n test_index
20. $ 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
21. 23% slower
22. Seconds 0 0.7 1.4 2.1 2.8 Runs 1 2 3 4 5 Controller Integration Controller vs. Integration Using Time
23. time
24. time was not a good baseline
25. GET A BASELINE
26. benchmark-ips github.com/evanphx/benchmark-ips
27. 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
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. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
34. $ 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
35. 2.34x slower
36. Sanity check: Ruby 2.1.5 2.2.0 Rails 4.2.0 master
37. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
38. $ 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
39. 2.53x slower
40. 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
41. GOT A BASELINE
42. FIND THE CULPRITS
43. RubyProf github.com/ruby-prof/ruby-prof
44. RubyProf Benefit: ✓ Industry standard
45. 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)
46. 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)
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. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb
50. $ 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 ...
51. $ 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?
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? % time spent
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? total time spent
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 in method
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? wait time
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 child
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? # of calls
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? method name
59. 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
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 File.open('graphs/callstack.html', 'w') do |file| - RubyProf::GraphHtmlPrinter.new(result).print(file) + RubyProf::CallStackPrinter.new(result).print(file) end
65. RubyProf Benefit: ✓ Shows the big picture
66. RubyProf Disadvantage: Data is overwhelming
67. RubyProf: Helped us compare integration and controller test stacks
68. That sounds like a great idea for my RailsConf talk! *not actual statement
69. That sounds like a great idea for my RailsConf talk! *not actual statement
70. StackProf github.com/tmm1/stackprof
71. StackProf Benefit: ✓ Focused profiling
72. 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
73. 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
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. $ 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.
76. $ stackprof --text test_graphs/index_integration_stackprof.dump
77. $ 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!
78. $ 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
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 % of total samples
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 samples where most time spent
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 samples where most time spent
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 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
84. # 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
85. # 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
86. # minitest/lib/minitest.rb def self.on_signal name, action # :nodoc: yield end
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 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
88. Done!
90. A B B
91. ALWAYS B B
92. ALWAYS BE B
93. ALWAYS BE BENCHMARKING
94. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
95. $ 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
96. $ 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 UHH...
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 IMPOSSIBLE.
99. StackProf Disadvantage: Bug in CPU time on OSX
100. 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
101. $ 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?
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... 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::...
103. --- 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
104. $ 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
105. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
106. $ 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
107. 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
108. StackProf Benefit: ✓ Helps pinpoint the
 problem quickly
109. StackProf Disadvantage: Difficult to pinpoint problems in dynamic methods
110. --- 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 - ... + @url_helpers ||= begin + routes = self ... + @_routes = routes + class << self + def url_for(options) + @_routes.url_for(options)
111. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
112. $ 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
113. 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
115. CACHING IS EXPENSIVE
116. 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
117. --- 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
118. 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
119. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
120. $ 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
121. 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
122. StackProf: Helped us find the biggest culprits of slowdown in Rails
123. $ 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
124. AllocationTracer github.com/ko1/allocation_tracer
125. AllocationTracer Benefit: ✓ Focuses on a specific problem
126. 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
127. 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
128. 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
129. 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
130. 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
131. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
132. $ 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]]
133. $ 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
134. $ 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
135. $ 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
136. $ 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
137. $ 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
138. $ 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
139. $ 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
140. $ 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
141. $ 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
142. $ 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]]
143. --- 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)
144. $ 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]]
145. $ 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]]
148. PROVE ALLOCATIONS ARE A BOTTLENECK
149. AllocationTracer: Helped us find unnecessary allocations of objects
150. 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
151. VS ITERATIONS BEFORE 393.8 ITERATIONS AFTER 828.4
152. ~3x faster
153. KNOW YOUR TOOLS
154. USE MULTIPLE TOOLS
155. ALWAYS BE BENCHMARKING
156. Thanks @tenderlove!
157. Thanks everyone! @ko1 @ruby-prof @tmm1 and YOU! @evanphx
158. # eileencodes.com ! @eileencodes " @eileencodes EILEEN M. UCHITELLE Programmer at Basecamp Slides: speakerdeck.com/eileencodes