Upgrade to Pro — share decks privately, control downloads, hide ads and more …

GORUCO 2015 - How to Performance

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.

Eileen M. Uchitelle

June 20, 2015
Tweet

More Decks by Eileen M. Uchitelle

Other Decks in Technology

Transcript

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

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

    integration tests in Ruby on Rails? *not actual statement
  3. 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
  4. $ 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
  5. $ 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
  6. Seconds 0 0.7 1.4 2.1 2.8 Runs 1 2 3

    4 5 Controller Integration Controller vs. Integration Using Time
  7. 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
  8. 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
  9. 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
  10. 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
  11. 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
  12. 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
  13. $ 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
  14. $ 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
  15. 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
  16. 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)
  17. 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)
  18. 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)
  19. 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)
  20. $ 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 ...
  21. $ 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?
  22. $ 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
  23. $ 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
  24. $ 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
  25. $ 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
  26. $ 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
  27. $ 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
  28. $ 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
  29. 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
  30. 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
  31. 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
  32. 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
  33. 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
  34. $ 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!
  35. $ 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
  36. $ 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
  37. $ 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
  38. $ 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
  39. $ 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
  40. $ 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
  41. # 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
  42. # 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
  43. $ 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
  44. $ 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
  45. $ 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...
  46. $ 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.
  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') - 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
  48. $ 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?
  49. $ 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::...
  50. --- 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
  51. $ 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
  52. $ 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
  53. 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
  54. --- 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)
  55. $ 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
  56. 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
  57. 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
  58. --- 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
  59. 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
  60. $ 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
  61. 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
  62. $ 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
  63. 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
  64. 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
  65. 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
  66. 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
  67. 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
  68. $ 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]]
  69. $ 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
  70. $ 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
  71. $ 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
  72. $ 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
  73. $ 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
  74. $ 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
  75. $ 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
  76. $ 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
  77. $ 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
  78. $ 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]]
  79. --- 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)
  80. $ 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]]
  81. $ 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]]
  82. 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