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

WindyCityRails 2015 - How to Performance

WindyCityRails 2015 - How to Performance

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

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

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

Eileen M. Uchitelle

September 18, 2015
Tweet

More Decks by Eileen M. Uchitelle

Other Decks in Technology

Transcript

  1. How to
    Performance
    WindyCityRails 2015

    View full-size slide

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

    View full-size slide

  3. rails committers team &
    rails security team

    View full-size slide

  4. Arya
    @aryadog

    View full-size slide

  5. Kingston, NY

    View full-size slide

  6. VS
    BENCHMARKING
    PROFILING

    View full-size slide

  7. benchmarking
    how slow something is

    View full-size slide

  8. profiling
    what is slow

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  12. GET
    A
    BASELINE

    View full-size slide

  13. github.com/eileencodes/
    integration_performance_test

    View full-size slide

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

    View full-size slide

  15. Starting point:
    Ruby 2.1.5
    Rails 4.2.0

    View full-size slide

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

    View full-size slide

  17. $ 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

    View full-size slide

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

    View full-size slide

  19. $ 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

    View full-size slide

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

    View full-size slide

  21. time
    was not a good baseline

    View full-size slide

  22. GET
    A
    BASELINE

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  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

    View full-size slide

  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

    View full-size slide

  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

    View full-size slide

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

    View full-size slide

  31. $ 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

    View full-size slide

  32. $ 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

    View full-size slide

  33. 2.34x slower

    View full-size slide

  34. Sanity check:
    Ruby 2.1.5 2.2.0
    Rails 4.2.0 master

    View full-size slide

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

    View full-size slide

  36. $ 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

    View full-size slide

  37. 2.53x slower

    View full-size slide

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

    View full-size slide

  39. GOT
    A
    BASELINE

    View full-size slide

  40. FIND
    THE
    CULPRITS

    View full-size slide

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

    View full-size slide

  42. RubyProf Benefit:
    ✓ Industry standard

    View full-size slide

  43. 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)

    View full-size slide

  44. 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)

    View full-size slide

  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)

    View full-size slide

  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)

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  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 #directory?
    % time
    spent

    View full-size slide

  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 #directory?
    total time
    spent

    View full-size slide

  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 #directory?
    time spent
    in method

    View full-size slide

  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 #directory?
    wait time

    View full-size slide

  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 #directory?
    time spent
    in child

    View full-size slide

  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 #directory?
    # of calls

    View full-size slide

  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 #directory?
    method name

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  59. RubyProf Benefit:
    ✓ Shows the big picture

    View full-size slide

  60. RubyProf Disadvantage:
    Data is overwhelming

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  64. StackProf
    github.com/tmm1/stackprof

    View full-size slide

  65. StackProf Benefit:
    ✓ Focused profiling

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  69. $ 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.

    View full-size slide

  70. $ stackprof --text test_graphs/index_integration_stackprof.dump

    View full-size slide

  71. $ 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!

    View full-size slide

  72. $ 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

    View full-size slide

  73. $ 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

    View full-size slide

  74. $ 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

    View full-size slide

  75. $ 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

    View full-size slide

  76. $ 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

    View full-size slide

  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#...
    13 (0.2%) 13 (0.2%) ThreadSafe::NonConcurrentCacheBack...
    3414 (56.0%) 13 (0.2%) Minitest::Test#time_it

    View full-size slide

  78. # 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

    View full-size slide

  79. # 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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  82. ALWAYS
    BE
    BENCHMARKING

    View full-size slide

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

    View full-size slide

  84. $ 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

    View full-size slide

  85. $ 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...?

    View full-size slide

  86. StackProf Disadvantage:
    Bug in CPU time
    on OSX

    View full-size slide

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

    View full-size slide

  88. $ 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?

    View full-size slide

  89. $ 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::...

    View full-size slide

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

    View full-size slide

  91. $ 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

    View full-size slide

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

    View full-size slide

  93. $ 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

    View full-size slide

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

    View full-size slide

  95. StackProf Benefit:
    ✓ Helps pinpoint the

    problem quickly

    View full-size slide

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

    View full-size slide

  97. RubyVM.stat
    ruby standard library

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  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')
    puts RubyVM.stat
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    puts RubyVM.stat

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  103. 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
    [...]

    View full-size slide

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

    View full-size slide

  105. --- 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)

    View full-size slide

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

    View full-size slide

  107. $ 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

    View full-size slide

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

    View full-size slide

  109. CACHING
    IS
    EXPENSIVE

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  116. $ 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

    View full-size slide

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

    View full-size slide

  118. And then a lot more
    improvements were made...

    View full-size slide

  119. $ 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

    View full-size slide

  120. AllocationTracer
    github.com/ko1/allocation_tracer

    View full-size slide

  121. AllocationTracer Benefit:
    ✓ Focuses on a specific
    problem

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  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

    View full-size slide

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

    View full-size slide

  128. $ 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]]

    View full-size slide

  129. $ 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

    View full-size slide

  130. $ 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

    View full-size slide

  131. $ 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

    View full-size slide

  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]]
    total count

    View full-size slide

  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]]
    old count

    View full-size slide

  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]]
    total age
    of objects

    View full-size slide

  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]]
    minimum age
    of objects

    View full-size slide

  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]]
    maximum age
    of objects

    View full-size slide

  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]]
    total
    memory size

    View full-size slide

  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]]

    View full-size slide

  139. --- 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)

    View full-size slide

  140. $ 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]]

    View full-size slide

  141. $ 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]]

    View full-size slide

  142. PROVE
    ALLOCATIONS
    ARE A
    BOTTLENECK

    View full-size slide

  143. AllocationTracer:
    Helped us find unnecessary
    allocations of objects

    View full-size slide

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

    View full-size slide

  145. VS
    ITERATIONS
    BEFORE
    393.8
    ITERATIONS
    AFTER
    828.4

    View full-size slide

  146. KNOW
    YOUR
    TOOLS

    View full-size slide

  147. USE
    MULTIPLE
    TOOLS

    View full-size slide

  148. ALWAYS
    BE
    BENCHMARKING

    View full-size slide

  149. Thanks
    @tenderlove!

    View full-size slide

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

    View full-size slide

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

    View full-size slide