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

FullStackFest 2015 - How to Performance

FullStackFest 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 01, 2015
Tweet

More Decks by Eileen M. Uchitelle

Other Decks in Technology

Transcript

  1. How to
    Performance
    Baruco/FullStackFest 2015

    View Slide

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

    View Slide

  3. rails committers team &
    rails security team

    View Slide

  4. Arya
    @aryadog

    View Slide

  5. Kingston, NY

    View Slide

  6. View Slide

  7. View Slide

  8. VS
    BENCHMARKING
    PROFILING

    View Slide

  9. benchmarking
    how slow something is

    View Slide

  10. profiling
    what is slow

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

  14. GET
    A
    BASELINE

    View Slide

  15. github.com/eileencodes/
    integration_performance_test

    View Slide

  16. CONTROLLER TEST
    class DocumentsControllerTest <
    ActionController::Testcase
    test "index" do
    get :index
    assert_equal 200, response.status
    end
    end
    INTEGRATION TEST
    class DocumentsIntegrationTest <
    ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end

    View Slide

  17. Starting point:
    Ruby 2.1.5
    Rails 4.2.0

    View Slide

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

    View Slide

  19. $ time ruby -I lib:test test/controller/
    documents_controller_test.rb -n test_index
    # Running:
    .
    Finished in 0.035099s, 28.4908 runs/s, 28.4908
    assertions/s.
    1 runs, 1 assertions, 0 failures, 0 errors, 0 skips
    real 0m1.625s
    user 0m1.346s
    sys 0m0.274s

    View Slide

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

    View Slide

  21. $ time ruby -I lib:test test/integration/
    documents_integration_test.rb -n test_index
    # Running:
    .
    Finished in 0.047088s, 21.2368 runs/s, 21.2368
    assertions/s.
    1 runs, 1 assertions, 0 failures, 0 errors, 0 skips
    real 0m2.120s
    user 0m1.486s
    sys 0m0.370s

    View Slide

  22. 23% slower

    View Slide

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

    View Slide

  24. time

    View Slide

  25. time
    was not a good baseline

    View Slide

  26. GET
    A
    BASELINE

    View Slide

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

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

  30. class DocumentsControllerTest < ActionController::Testcase
    test "index" do
    get :index
    assert_equal 200, response.status
    end
    end
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Benchmark.ips do |bm|
    bm.report 'INDEX: Integration Test' do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    bm.report 'INDEX: Functional Test' do
    Minitest.run_one_method(DocumentsControllerTest, 'test_index')
    end
    bm.compare!
    end

    View Slide

  31. class DocumentsControllerTest < ActionController::Testcase
    test "index" do
    get :index
    assert_equal 200, response.status
    end
    end
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Benchmark.ips do |bm|
    bm.report 'INDEX: Integration Test' do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    bm.report 'INDEX: Functional Test' do
    Minitest.run_one_method(DocumentsControllerTest, 'test_index')
    end
    bm.compare!
    end

    View Slide

  32. class DocumentsControllerTest < ActionController::Testcase
    test "index" do
    get :index
    assert_equal 200, response.status
    end
    end
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Benchmark.ips do |bm|
    bm.report 'INDEX: Integration Test' do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    bm.report 'INDEX: Functional Test' do
    Minitest.run_one_method(DocumentsControllerTest, 'test_index')
    end
    bm.compare!
    end

    View Slide

  33. class DocumentsControllerTest < ActionController::Testcase
    test "index" do
    get :index
    assert_equal 200, response.status
    end
    end
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Benchmark.ips do |bm|
    bm.report 'INDEX: Integration Test' do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    bm.report 'INDEX: Functional Test' do
    Minitest.run_one_method(DocumentsControllerTest, 'test_index')
    end
    bm.compare!
    end

    View Slide

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

    View Slide

  35. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    36.000 i/100ms
    INDEX: Functional Test
    98.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    393.837 (± 8.1%) i/s - 1.980k
    INDEX: Functional Test
    920.765 (± 7.2%) i/s - 4.606k
    Comparison:
    INDEX: Functional Test: 920.8 i/s
    INDEX: Integration Test: 393.8 i/s - 2.34x slower

    View Slide

  36. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    36.000 i/100ms
    INDEX: Functional Test
    98.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    393.837 (± 8.1%) i/s - 1.980k
    INDEX: Functional Test
    920.765 (± 7.2%) i/s - 4.606k
    Comparison:
    INDEX: Functional Test: 920.8 i/s
    INDEX: Integration Test: 393.8 i/s - 2.34x slower

    View Slide

  37. 2.34x slower

    View Slide

  38. Sanity check:
    Ruby 2.1.5 2.2.0
    Rails 4.2.0 master

    View Slide

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

    View Slide

  40. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    37.000 i/100ms
    INDEX: Functional Test
    99.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    395.025 (±11.1%) i/s - 1.961k
    INDEX: Functional Test
    998.641 (±10.6%) i/s - 4.950k
    Comparison:
    INDEX: Functional Test: 998.6 i/s
    INDEX: Integration Test: 395.0 i/s - 2.53x slower

    View Slide

  41. 2.53x slower

    View Slide

  42. Iterations
    0
    250
    500
    750
    1000
    Rails / Ruby Changes
    Rails 4.2

    Ruby 2.1.5
    Rails master

    Ruby 2.2.0
    Controller Integration
    Controller vs. Integration Iterations
    2.34x 2.53x

    View Slide

  43. GOT
    A
    BASELINE

    View Slide

  44. FIND
    THE
    CULPRITS

    View Slide

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

    View Slide

  46. RubyProf Benefit:
    ✓ Industry standard

    View Slide

  47. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    result = RubyProf.profile do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    printer = RubyProf::FlatPrinter.new(result)
    printer.print(STDOUT)

    View Slide

  48. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    result = RubyProf.profile do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    printer = RubyProf::FlatPrinter.new(result)
    printer.print(STDOUT)

    View Slide

  49. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    result = RubyProf.profile do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    printer = RubyProf::FlatPrinter.new(result)
    printer.print(STDOUT)

    View Slide

  50. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    result = RubyProf.profile do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    printer = RubyProf::FlatPrinter.new(result)
    printer.print(STDOUT)

    View Slide

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

    View 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?
    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 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?
    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
    ...
    ¿QUE?
    ´

    View 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

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

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

    View Slide

  57. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb
    Measure Mode: wall_time
    Thread ID: 70361098355200
    Fiber ID: 70361103069320
    Total: 0.000332
    Sort by: self_time
    %self total self wait child calls name
    14.21 0.000 0.000 0.000 0.000 7 #directory?
    wait time

    View Slide

  58. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb
    Measure Mode: wall_time
    Thread ID: 70361098355200
    Fiber ID: 70361103069320
    Total: 0.000332
    Sort by: self_time
    %self total self wait child calls name
    14.21 0.000 0.000 0.000 0.000 7 #directory?
    time spent
    in child

    View Slide

  59. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb
    Measure Mode: wall_time
    Thread ID: 70361098355200
    Fiber ID: 70361103069320
    Total: 0.000332
    Sort by: self_time
    %self total self wait child calls name
    14.21 0.000 0.000 0.000 0.000 7 #directory?
    # of calls

    View Slide

  60. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb
    Measure Mode: wall_time
    Thread ID: 70361098355200
    Fiber ID: 70361103069320
    Total: 0.000332
    Sort by: self_time
    %self total self wait child calls name
    14.21 0.000 0.000 0.000 0.000 7 #directory?
    method name

    View Slide

  61. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    result = RubyProf.profile do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    - printer = RubyProf::FlatPrinter.new(result)
    - printer.print(STDOUT)
    + File.open('graphs/callstack.html', 'w') do |file|
    + RubyProf::GraphHtmlPrinter.new(result).print(file)
    + end

    View Slide

  62. View Slide

  63. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    result = RubyProf.profile do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    File.open('graphs/callstack.html', 'w') do |file|
    - RubyProf::GraphHtmlPrinter.new(result).print(file)
    + RubyProf::CallStackPrinter.new(result).print(file)
    end

    View Slide

  64. View Slide

  65. View Slide

  66. View Slide

  67. RubyProf Benefit:
    ✓ Shows the big picture

    View Slide

  68. RubyProf Disadvantage:
    Data is overwhelming

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

  72. StackProf
    github.com/tmm1/stackprof

    View Slide

  73. StackProf Benefit:
    ✓ Focused profiling

    View Slide

  74. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump’) do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end

    View Slide

  75. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump') do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end

    View Slide

  76. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump') do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end

    View Slide

  77. $ ruby -Ilib:test test/integration/documents_stackprof_index_test.rb
    Run options: --seed 28534
    # Running:
    .
    Finished in 0.008557s, 116.8634 runs/s, 116.8634 assertions/s.

    View Slide

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

    View Slide

  79. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: cpu(1000)
    Samples: 6097 (0.00% miss rate)
    GC: 194 (3.18%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal
    2487 (14.7%) 2487 (14.7%) Dependencies#search_for_file
    287 (4.7%) 124 (2.0%) block in Module#delegate
    60 (1.0%) 44 (0.7%) ActiveSupport::Subscriber#start
    36 (0.6%) 36 (0.6%) Rack::Utils::HeaderHash#[]=
    42 (0.7%) 34 (0.6%) SQLite3::Database#prepare
    23 (0.4%) 23 (0.4%) Set#include?
    17 (0.3%) 17 (0.3%) String#blank?
    32 (0.5%) 16 (0.3%) Rack::MockRequest.env_for
    15 (0.2%) 15 (0.2%) Rack::BodyProxy#initialize
    20 (0.3%) 14 (0.2%) Rack::Utils#parse_nested_query
    14 (0.2%) 14 (0.2%) ActiveSupport::PerThreadRegistry#instance
    13 (0.2%) 13 (0.2%) ThreadSafe::NonConcurrentCacheBackend#[]
    3414 (56.0%) 13 (0.2%) Minitest::Test#time_it
    13 (0.2%) 13 (0.2%) URI::Parser#split
    12 (0.2%) 12 (0.2%) ActiveSupport::Notifications::Event#initialize
    10 (0.2%) 10 (0.2%) ActiveSupport::Configurable::ClassMethods#config
    10 (0.2%) 9 (0.1%) Rack::Utils#parse_query
    25 (0.4%) 9 (0.1%) ActiveSupport::Subscriber#finish
    9 (0.1%) 9 (0.1%) ActiveRecord::Base.logger
    8 (0.1%) 8 (0.1%) block in Rack::Utils#clean_path_info
    12 (0.2%) 8 (0.1%) URI::Generic#initialize
    2888 (47.4%) 8 (0.1%) ActionDispatch::Integration::Session#process
    8 (0.1%) 8 (0.1%) ActionDispatch::Response#merge_default_headers
    9 (0.1%) 7 (0.1%) block in ActiveSupport::Notifications::Fanout#unsubscribe
    7 (0.1%) 7 (0.1%) Rack::Utils::KeySpaceConstrainedParams#to_params_hash
    7 (0.1%) 7 (0.1%) block (4 levels) in Class#class_attribute
    6 (0.1%) 6 (0.1%) Rack::BodyProxy#respond_to?
    6 (0.1%) 6 (0.1%) Minitest::Assertions#message
    6 (0.1%) 6 (0.1%) ActionDispatch::Integration::Session#reset!

    View Slide

  80. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: cpu(1000)
    Samples: 6097 (0.00% miss rate)
    GC: 194 (3.18%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal
    total
    samples

    View 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
    5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal
    % of total
    samples

    View Slide

  82. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: cpu(1000)
    Samples: 6097 (0.00% miss rate)
    GC: 194 (3.18%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal
    samples where
    most time spent

    View Slide

  83. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: cpu(1000)
    Samples: 6097 (0.00% miss rate)
    GC: 194 (3.18%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal
    samples where
    most time spent

    View Slide

  84. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: cpu(1000)
    Samples: 6097 (0.00% miss rate)
    GC: 194 (3.18%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal
    samples where
    most time spent

    View Slide

  85. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: cpu(1000)
    Samples: 6097 (0.00% miss rate)
    GC: 194 (3.18%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    5903 (95.9%) 2489 (53.0%) Minitest::Runnable.on_signal
    2487 (14.7%) 2487 (14.7%) Dependencies#search_for_file
    287 (4.7%) 124 (2.0%) block in Module#delegate
    60 (1.0%) 44 (0.7%) ActiveSupport::Subscriber#start
    36 (0.6%) 36 (0.6%) Rack::Utils::HeaderHash#[]=
    42 (0.7%) 34 (0.6%) SQLite3::Database#prepare
    23 (0.4%) 23 (0.4%) Set#include?
    17 (0.3%) 17 (0.3%) String#blank?
    32 (0.5%) 16 (0.3%) Rack::MockRequest.env_for
    15 (0.2%) 15 (0.2%) Rack::BodyProxy#initialize
    20 (0.3%) 14 (0.2%) Rack::Utils#parse_nested_query
    14 (0.2%) 14 (0.2%) ActiveSupport::PerThreadRegistry#...
    13 (0.2%) 13 (0.2%) ThreadSafe::NonConcurrentCacheBack...
    3414 (56.0%) 13 (0.2%) Minitest::Test#time_it

    View Slide

  86. # minitest/lib/minitest.rb
    def self.on_signal name, action # :nodoc:
    supported = SIGNALS[name]
    old_trap = trap name do
    old_trap.call if old_trap.respond_to? :call
    action.call
    end if supported
    yield
    ensure
    trap name, old_trap if supported
    end

    View Slide

  87. # minitest/lib/minitest.rb
    def self.on_signal name, action # :nodoc:
    - supported = SIGNALS[name]
    - old_trap = trap name do
    - old_trap.call if old_trap.respond_to? :call
    - action.call
    - end if supported
    yield
    - ensure
    - trap name, old_trap if supported
    end

    View Slide

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

    View Slide

  89. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: cpu(1000)
    Samples: 6097 (0.00% miss rate)
    GC: 194 (3.18%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    2487 (14.7%) 2487 (14.7%) Dependencies#search_for_file
    287 (4.7%) 124 (2.0%) block in Module#delegate
    60 (1.0%) 44 (0.7%) ActiveSupport::Subscriber#start
    36 (0.6%) 36 (0.6%) Rack::Utils::HeaderHash#[]=
    42 (0.7%) 34 (0.6%) SQLite3::Database#prepare
    23 (0.4%) 23 (0.4%) Set#include?
    17 (0.3%) 17 (0.3%) String#blank?
    32 (0.5%) 16 (0.3%) Rack::MockRequest.env_for
    15 (0.2%) 15 (0.2%) Rack::BodyProxy#initialize
    20 (0.3%) 14 (0.2%) Rack::Utils#parse_nested_query
    14 (0.2%) 14 (0.2%) ActiveSupport::PerThreadRegistry#...
    13 (0.2%) 13 (0.2%) ThreadSafe::NonConcurrentCacheBack...
    3414 (56.0%) 13 (0.2%) Minitest::Test#time_it

    View Slide

  90. Done!

    View Slide

  91. View Slide

  92. A
    B
    B

    View Slide

  93. ALWAYS
    B
    B

    View Slide

  94. ALWAYS
    BE
    B

    View Slide

  95. ALWAYS
    BE
    BENCHMARKING

    View Slide

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

    View Slide

  97. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    37.000 i/100ms
    INDEX: Functional Test
    99.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    395.025 (±11.1%) i/s - 1.961k
    INDEX: Functional Test
    998.641 (±10.6%) i/s - 4.950k
    Comparison:
    INDEX: Functional Test: 998.6 i/s
    INDEX: Integration Test: 395.0 i/s - 2.53x slower

    View Slide

  98. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    37.000 i/100ms
    INDEX: Functional Test
    99.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    395.025 (±11.1%) i/s - 1.961k
    INDEX: Functional Test
    998.641 (±10.6%) i/s - 4.950k
    Comparison:
    INDEX: Functional Test: 998.6 i/s
    INDEX: Integration Test: 395.0 i/s - 2.53x slower
    ¿EH...?

    View Slide

  99. View Slide

  100. StackProf Disadvantage:
    Bug in CPU time
    on OSX

    View Slide

  101. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    - StackProf.run(mode: :cpu, out: ‘graphs/stackprof.dump') do
    + StackProf.run(mode: :wall, out: ‘graphs/stackprof.dump') do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end

    View Slide

  102. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: wall(1000)
    Samples: 7869 (0.34% miss rate)
    GC: 544 (6.91%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    2512 (31.9%) 2230 (28.3%) block in Module#delegate
    185 (2.4%) 185 (2.4%) ActiveSupport::PerThreadRegistry#instance
    143 (1.8%) 143 (1.8%) Set#include?
    116 (1.5%) 116 (1.5%) ThreadSafe::NonConcurrentCacheBackend#[]
    97 (1.2%) 97 (1.2%) block (4 levels) in Class#class_attribute
    92 (1.2%) 92 (1.2%) Rack::Utils::HeaderHash#[]=
    129 (1.6%) 82 (1.0%) block (2 levels) in Class#class_attribute
    145 (1.8%) 64 (0.8%) Rack::BodyProxy#respond_to?
    62 (0.8%) 62 (0.8%) MonitorMixin#mon_enter
    61 (0.8%) 61 (0.8%) URI::RFC3986_Parser#split
    115 (1.5%) 61 (0.8%) SQLite3::Database#prepare
    57 (0.7%) 57 (0.7%) String#blank?
    56 (0.7%) 56 (0.7%) block in ActionDispatch::FileHandler#match?
    55 (0.7%) 55 (0.7%) ActiveSupport::Notifications::Fanout::Subscribers::Evented#subscribed_to?
    54 (0.7%) 54 (0.7%) ActiveRecord::Base.logger
    2713 (34.5%) 53 (0.7%) block in ActionDispatch::Routing::RouteSet#url_helpers
    137 (1.7%) 52 (0.7%) Rack::MockRequest.env_for
    49 (0.6%) 49 (0.6%) Rack::Request#initialize
    46 (0.6%) 46 (0.6%) ActiveSupport::Configurable::ClassMethods#config
    43 (0.5%) 43 (0.5%) ActiveSupport::Notifications::Event#initialize
    37 (0.5%) 37 (0.5%) MonitorMixin#mon_initialize
    75 (1.0%) 37 (0.5%) URI::Generic#initialize
    46 (0.6%) 34 (0.4%) Rack::Utils#parse_nested_query
    34 (0.4%) 34 (0.4%) ActiveSupport::InheritableOptions#initialize
    33 (0.4%) 33 (0.4%) ActionDispatch::Integration::Runner#integration_session
    33 (0.4%) 33 (0.4%) block in Rack::Utils#clean_path_info
    33 (0.4%) 33 (0.4%) Rails::Engine#routes
    259 (3.3%) 33 (0.4%) Rack::Test::Session#env_for
    61 (0.8%) 29 (0.4%) ActiveSupport::Concern#append_features
    28 (0.4%) 28 (0.4%) NilClass#blank?

    View Slide

  103. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: wall(1000)
    Samples: 7869 (0.34% miss rate)
    GC: 544 (6.91%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    2512 (31.9%) 2230 (28.3%) block in Module#delegate
    185 (2.4%) 185 (2.4%) ActiveSupport::PerThreadRegistry...
    143 (1.8%) 143 (1.8%) Set#include?
    116 (1.5%) 116 (1.5%) ThreadSafe::NonConcurrentCache...
    97 (1.2%) 97 (1.2%) block (4 levels) in Class#...
    92 (1.2%) 92 (1.2%) Rack::Utils::HeaderHash#[]=
    129 (1.6%) 82 (1.0%) block (2 levels) in Class#class_...
    145 (1.8%) 64 (0.8%) Rack::BodyProxy#respond_to?
    62 (0.8%) 62 (0.8%) MonitorMixin#mon_enter
    61 (0.8%) 61 (0.8%) URI::RFC3986_Parser#split
    115 (1.5%) 61 (0.8%) SQLite3::Database#prepare
    57 (0.7%) 57 (0.7%) String#blank?
    56 (0.7%) 56 (0.7%) block in ActionDispatch::File...
    55 (0.7%) 55 (0.7%) ActiveSupport::Notifications::...

    View Slide

  104. --- a/actionpack/lib/action_dispatch/routing/route_set.rb
    +++ b/actionpack/lib/action_dispatch/routing/route_set.rb
    class << self
    - delegate :url_for, :optimize_routes_generation?, to: '@_routes'
    + def url_for(options)
    + @_routes.url_for(options)
    + end
    +
    + def optimize_routes_generation?
    + @_routes.optimize_routes_generation?
    + end
    +
    attr_reader :_routes
    def url_options; {}; end
    end

    View Slide

  105. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: wall(1000)
    Samples: 4383 (0.02% miss rate)
    GC: 488 (11.13%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    176 (4.0%) 176 (4.0%) ActiveSupport::PerThreadRegistry#...
    138 (3.1%) 138 (3.1%) ThreadSafe::NonConcurrentCacheBa...
    91 (2.1%) 91 (2.1%) Rack::Utils::HeaderHash#[]=
    95 (2.2%) 68 (1.6%) block (2 levels) in Class#class_...
    63 (1.4%) 63 (1.4%) block (4 levels) in Class#class_...
    62 (1.4%) 62 (1.4%) ActiveSupport::Notifications::Fan...
    112 (2.6%) 62 (1.4%) SQLite3::Database#prepare
    57 (1.3%) 57 (1.3%) URI::RFC3986_Parser#split
    51 (1.2%) 51 (1.2%) String#blank?
    46 (1.0%) 46 (1.0%) ActiveRecord::Base.logger
    95 (2.2%) 45 (1.0%) Rack::BodyProxy#respond_to?
    45 (1.0%) 45 (1.0%) ActiveSupport::Notifications::...
    43 (1.0%) 43 (1.0%) MonitorMixin#mon_enter
    41 (0.9%) 41 (0.9%) Rack::Request#initialize

    View Slide

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

    View Slide

  107. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    53.000 i/100ms
    INDEX: Functional Test
    72.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    549.617 (±12.4%) i/s - 2.703k
    INDEX: Functional Test
    768.021 (± 9.2%) i/s - 3.816k
    Comparison:
    INDEX: Functional Test: 768.0 i/s
    INDEX: Integration Test: 549.6 i/s - 1.40x slower

    View Slide

  108. Iterations
    0
    250
    500
    750
    1000
    Changes to Ruby / Rails
    Rails master

    Ruby 2.2.0
    Expand

    Methods
    Controller Integration
    Controller vs. Integration Iterations
    2.53x 1.40x

    View Slide

  109. StackProf Benefit:
    ✓ Helps pinpoint the

    problem quickly

    View Slide

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

    View Slide

  111. RubyVM.stat
    ruby standard library

    View Slide

  112. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    puts RubyVM.stat
    Minitest.run_one_method(DocumentsIntegrationTest, ‘test_index')
    puts RubyVM.stat

    View Slide

  113. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    puts RubyVM.stat
    Minitest.run_one_method(DocumentsIntegrationTest, ‘test_index')
    puts RubyVM.stat

    View Slide

  114. require 'test_helper'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    puts RubyVM.stat
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    puts RubyVM.stat

    View Slide

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

    View Slide

  116. {:global_method_state=>198, :global_constant_state=>7823,
    :class_serial=>181492}
    {:global_method_state=>198, :global_constant_state=>7824,
    :class_serial=>181522}
    creating an
    extra constant

    View Slide

  117. def url_helpers(supports_path = true)
    routes = self
    Module.new do
    extend ActiveSupport::Concern
    include UrlFor
    # Define url_for in the singleton level so one can do:
    # Rails.application.routes.url_helpers.url_for(args)
    @_routes = routes
    class << self
    delegate :url_for, :optimize_routes_generation?, to: '@_routes'
    attr_reader :_routes
    def url_options; {}; end
    end
    url_helpers = routes.named_routes.url_helpers_module
    # Make named_routes available in the module singleton
    # as well, so one can do:
    # Rails.application.routes.url_helpers.posts_path
    [...]

    View Slide

  118. def url_helpers(supports_path = true)
    routes = self
    Module.new do
    extend ActiveSupport::Concern
    include UrlFor
    # Define url_for in the singleton level so one can do:
    # Rails.application.routes.url_helpers.url_for(args)
    @_routes = routes
    class << self
    delegate :url_for, :optimize_routes_generation?, to: '@_routes'
    attr_reader :_routes
    def url_options; {}; end
    end
    url_helpers = routes.named_routes.url_helpers_module
    # Make named_routes available in the module singleton
    # as well, so one can do:
    # Rails.application.routes.url_helpers.posts_path
    [...]
    anonymous module

    View Slide

  119. --- a/actionpack/lib/action_dispatch/routing/route_set.rb
    +++ b/actionpack/lib/action_dispatch/routing/route_set.rb
    def url_helpers(supports_path = true)
    - routes = self
    -
    - Module new do
    ...
    + @url_helpers ||= begin
    + routes = self
    +
    + Module.new do
    ...
    + @_routes = routes
    + class << self
    + def url_for(options)
    + @_routes.url_for(options)

    View Slide

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

    View Slide

  121. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    74.000 i/100ms
    INDEX: Functional Test
    99.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    752.377 (± 6.9%) i/s - 3.774k
    INDEX: Functional Test
    1.021k (± 6.7%) i/s - 5.148k
    Comparison:
    INDEX: Functional Test: 1021.1 i/s
    INDEX: Integration Test: 752.4 i/s - 1.36x slower

    View Slide

  122. Iterations
    0
    275
    550
    825
    1100
    Changes to Rails
    Before Changes Expand Methods Caching url_helpers
    Controller Integration
    Controller vs. Integration Iterations
    2.53x 1.40x
    1.36x

    View Slide

  123. View Slide

  124. CACHING
    IS
    EXPENSIVE

    View Slide

  125. diff --git a/actionpack/lib/action_dispatch/routing/route_set.rb b/actionpack/lib/action_dispatch/routing/route_set.rb
    index 948cbdc..65d6a5e 100644
    --- a/actionpack/lib/action_dispatch/routing/route_set.rb
    +++ b/actionpack/lib/action_dispatch/routing/route_set.rb
    @@ -409,14 +409,6 @@ module ActionDispatch
    end
    def url_helpers(supports_path = true)
    - if supports_path
    - @url_helpers_with_paths ||= generate_url_helpers(supports_path)
    - else
    - @url_helpers_without_paths ||= generate_url_helpers(supports_path)
    - end
    - end
    -
    - def generate_url_helpers(supports_path)
    routes = self
    Module.new do
    diff --git a/actionpack/lib/action_dispatch/testing/integration.rb b/actionpack/lib/action_dispatch/testing/integration.rb
    index 876a980..f9ef806 100644
    --- a/actionpack/lib/action_dispatch/testing/integration.rb
    +++ b/actionpack/lib/action_dispatch/testing/integration.rb
    @@ -222,15 +222,6 @@ module ActionDispatch
    super()
    @app = app
    - # If the app is a Rails app, make url_helpers available on the session
    - # This makes app.url_for and app.foo_path available in the console
    - if app.respond_to?(:routes)
    - singleton_class.class_eval do
    - include app.routes.url_helpers
    - include app.routes.mounted_helpers
    - end
    - end
    -
    reset!
    end
    @@ -396,6 +387,8 @@ module ActionDispatch
    module Runner
    include ActionDispatch::Assertions
    + APP_SESSIONS = {}
    +
    def app
    @app ||= nil
    end
    @@ -403,7 +396,19 @@ module ActionDispatch
    # Reset the current session. This is useful for testing multiple sessions
    # in a single test case.
    def reset!
    - @integration_session = Integration::Session.new(app)
    + @integration_session = create_session(app)
    + end
    +
    + def create_session(app)
    + klass = APP_SESSIONS[app] ||= Class.new(Integration::Session) {
    + # If the app is a Rails app, make url_helpers available on the session
    + # This makes app.url_for and app.foo_path available in the console
    + if app.respond_to?(:routes)
    + include app.routes.url_helpers
    + include app.routes.mounted_helpers
    + end
    + }
    + klass.new(app)
    end

    View Slide

  126. --- a/actionpack/lib/action_dispatch/testing/integration.rb
    +++ b/actionpack/lib/action_dispatch/testing/integration.rb
    super()
    @app = app
    - # If the app is a Rails app, make url_helpers available on the session
    - # This makes app.url_for and app.foo_path available in the console
    - if app.respond_to?(:routes)
    - singleton_class.class_eval do
    - include app.routes.url_helpers
    - include app.routes.mounted_helpers
    - end
    - end
    -
    reset!
    end

    View Slide

  127. def reset!
    - @integration_session = Integration::Session.new(app)
    + @integration_session = create_session(app)
    + end
    +
    + def create_session(app)
    + klass = APP_SESSIONS[app] ||= Class.new(Integration::Session) {
    + # If the app is a Rails app, make url_helpers available on the
    + # This makes app.url_for and app.foo_path available in the console
    + if app.respond_to?(:routes)
    + include app.routes.url_helpers
    + include app.routes.mounted_helpers
    + end
    + }
    + klass.new(app)
    end

    View Slide

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

    View Slide

  129. {:global_method_state=>198, :global_constant_state=>7822,
    :class_serial=>181492}
    {:global_method_state=>198, :global_constant_state=>7822,
    :class_serial=>181522}
    no new
    constants

    View Slide

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

    View Slide

  131. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    Calculating -------------------------------------
    INDEX: Integration Test
    87.000 i/100ms
    INDEX: Functional Test
    97.000 i/100ms
    -------------------------------------------------
    INDEX: Integration Test
    828.433 (± 6.4%) i/s - 4.176k
    INDEX: Functional Test
    926.763 (± 7.2%) i/s - 4.656k
    Comparison:
    INDEX: Functional Test: 926.8 i/s
    INDEX: Integration Test: 828.4 i/s - 1.12x slower

    View Slide

  132. Iterations
    0
    275
    550
    825
    1100
    Changes to Rails/Rack
    Start Expand Methods Caching Move #url_helpers
    Controller Integration
    Controller vs. Integration Iterations
    2.53x 1.40x
    1.36x 1.12x

    View Slide

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

    View Slide

  134. $ stackprof --text test_graphs/index_integration_stackprof.dump
    ==================================
    Mode: wall(1000)
    Samples: 4383 (0.02% miss rate)
    GC: 488 (11.13%)
    ==================================
    TOTAL (pct) SAMPLES (pct) FRAME
    176 (4.0%) 176 (4.0%) ActiveSupport::PerThreadRegistry#...
    138 (3.1%) 138 (3.1%) ThreadSafe::NonConcurrentCacheBa...
    91 (2.1%) 91 (2.1%) Rack::Utils::HeaderHash#[]=
    95 (2.2%) 68 (1.6%) block (2 levels) in Class#class_...
    63 (1.4%) 63 (1.4%) block (4 levels) in Class#class_...
    62 (1.4%) 62 (1.4%) ActiveSupport::Notifications::Fan...
    112 (2.6%) 62 (1.4%) SQLite3::Database#prepare
    57 (1.3%) 57 (1.3%) URI::RFC3986_Parser#split
    51 (1.2%) 51 (1.2%) String#blank?
    46 (1.0%) 46 (1.0%) ActiveRecord::Base.logger
    95 (2.2%) 45 (1.0%) Rack::BodyProxy#respond_to?
    45 (1.0%) 45 (1.0%) ActiveSupport::Notifications::...
    43 (1.0%) 43 (1.0%) MonitorMixin#mon_enter
    41 (0.9%) 41 (0.9%) Rack::Request#initialize

    View Slide

  135. AllocationTracer
    github.com/ko1/allocation_tracer

    View Slide

  136. AllocationTracer Benefit:
    ✓ Focuses on a specific
    problem

    View Slide

  137. require 'test_helper'
    require 'objspace'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    ObjectSpace::AllocationTracer.setup(%i{path line type})
    result = ObjectSpace::AllocationTracer.trace do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end
    result.sort_by { |info, counts| counts.first }
    .reverse.first(5).each do |r|
    puts r
    end

    View Slide

  138. require 'test_helper'
    require 'objspace'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    ObjectSpace::AllocationTracer.setup(%i{path line type})
    result = ObjectSpace::AllocationTracer.trace do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end
    result.sort_by { |info, counts| counts.first }
    .reverse.first(5).each do |r|
    puts r
    end

    View Slide

  139. require 'test_helper'
    require 'objspace'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    ObjectSpace::AllocationTracer.setup(%i{path line type})
    result = ObjectSpace::AllocationTracer.trace do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end
    result.sort_by { |info, counts| counts.first }
    .reverse.first(5).each do |r|
    puts r
    end

    View Slide

  140. require 'test_helper'
    require 'objspace'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    ObjectSpace::AllocationTracer.setup(%i{path line type})
    result = ObjectSpace::AllocationTracer.trace do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end
    result.sort_by { |info, counts| counts.first }
    .reverse.first(5).each do |r|
    puts r
    end

    View Slide

  141. require 'test_helper'
    require 'objspace'
    class DocumentsIntegrationTest < ActionDispatch::IntegrationTest
    test "index" do
    get '/documents'
    assert_equal 200, response.status
    end
    end
    ObjectSpace::AllocationTracer.setup(%i{path line type})
    result = ObjectSpace::AllocationTracer.trace do
    3000.times do
    Minitest.run_one_method(DocumentsIntegrationTest, 'test_index')
    end
    end
    result.sort_by { |info, counts| counts.first }
    .reverse.first(5).each do |r|
    puts r
    end

    View Slide

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

    View Slide

  143. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]

    View Slide

  144. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    path

    View Slide

  145. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    line number

    View Slide

  146. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    type

    View Slide

  147. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    total count

    View Slide

  148. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    old count

    View Slide

  149. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    total age
    of objects

    View Slide

  150. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    minimum age
    of objects

    View Slide

  151. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    maximum age
    of objects

    View Slide

  152. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]
    total
    memory size

    View Slide

  153. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 500, :T_STRING], [56981, 4303, 78980, 0, 13, 2032240]]
    [["rack/lib/rack/utils.rb", 498, :T_STRING], [51000, 0, 45775, 0, 2, 1904680]]
    [["rack/lib/rack/utils.rb", 114, :T_STRING], [39123, 0, 35116, 0, 1, 4711600]]
    [["rack/lib/rack/utils.rb", 661, :T_STRING], [32993, 0, 29621, 0, 1, 1232289]]
    [["rack/lib/rack/body_proxy.rb", 34, :T_ARRAY], [30000, 0, 26930, 0, 1, 1120400]]

    View Slide

  154. --- a/lib/rack/utils.rb
    +++ b/lib/rack/utils.rb
    def []=(k, v)
    - canonical = k.downcase
    + canonical = k.downcase.freeze
    delete k if @names[canonical] && @names[canonical] != k
    @names[k] = @names[canonical] = k
    super k, v
    --- a/lib/rack/runtime.rb
    +++ b/lib/rack/runtime.rb
    class Runtime
    + FORMAT_STRING = "%0.6f".freeze # :nodoc:
    + HEADER_NAME = "X-Runtime".freeze # :nodoc:
    def initialize(app, name = nil)

    View Slide

  155. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 499, :T_STRING], [51034, 4539, 71559, 0, 12, 1791120]]
    [["rack/lib/rack/utils.rb", 662, :T_STRING], [33012, 0, 27930, 0, 1, 1226009]]
    [["rails/activesupport/lib/active_support/notifications/fanout.rb", 55, :T_DATA],
    [29998, 0, 25380, 0, 1, 3230600]]
    [["rails/activesupport/lib/active_support/subscriber.rb", 99, :T_STRING],
    [29996, 0, 25378, 0, 2, 1113840]]
    [["rails/activesupport/lib/active_support/notifications/instrumenter.rb",
    52, :T_HASH], [29994, 147, 27014, 0, 11, 4897784]]

    View Slide

  156. $ ruby -Ilib:test test/integration/documents_allocations_index_test.rb
    [["rack/lib/rack/utils.rb", 499, :T_STRING], [51034, 4539, 71559, 0, 12, 1791120]]
    [["rack/lib/rack/utils.rb", 662, :T_STRING], [33012, 0, 27930, 0, 1, 1226009]]
    [["rails/activesupport/lib/active_support/notifications/fanout.rb", 55, :T_DATA],
    [29998, 0, 25380, 0, 1, 3230600]]
    [["rails/activesupport/lib/active_support/subscriber.rb", 99, :T_STRING],
    [29996, 0, 25378, 0, 2, 1113840]]
    [["rails/activesupport/lib/active_support/notifications/instrumenter.rb",
    52, :T_HASH], [29994, 147, 27014, 0, 11, 4897784]]

    View Slide

  157. View Slide

  158. View Slide

  159. PROVE
    ALLOCATIONS
    ARE A
    BOTTLENECK

    View Slide

  160. AllocationTracer:
    Helped us find unnecessary
    allocations of objects

    View Slide

  161. Controller vs. Integration Iterations
    Iterations
    0
    275
    550
    825
    1100
    Changes to Rails/Rack
    Start Expand Methods Caching Move #url_helpers
    Controller Integration
    2.53x 1.40x
    1.36x 1.12x

    View Slide

  162. VS
    ITERATIONS
    BEFORE
    393.8
    ITERATIONS
    AFTER
    828.4

    View Slide

  163. ~3x faster

    View Slide

  164. KNOW
    YOUR
    TOOLS

    View Slide

  165. USE
    MULTIPLE
    TOOLS

    View Slide

  166. ALWAYS
    BE
    BENCHMARKING

    View Slide

  167. Thanks
    @tenderlove!

    View Slide

  168. ¡Gracias!
    @ko1
    @ruby-prof
    @tmm1
    and YOU!
    @evanphx

    View Slide

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

    View Slide