GORUCO 2015 - How to Performance

http://confreaks.tv/videos/goruco2015-how-to-performance

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

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

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

Transcript

1. wow
   such speed
   much performance
   very impressive
   amaze
   so awesome
   

   View Slide

2. How to
   Performance
   

   View Slide

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

   View Slide

4. Arya
   @aryadog
   

   View Slide

5. Kingston, NY
   

   View Slide

6. catskillsconf.com Oct 23-25, 2015
   Ashokan Center in NY
   

   View Slide

7. View Slide

8. View Slide

9. View Slide

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

    View Slide

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

    View Slide

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

    View Slide

13. GET
    A
    BASELINE
    

    View Slide

14. github.com/eileencodes/
    integration_performance_test
    

    View Slide

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

    View Slide

16. Starting point:
    Ruby 2.1.5
    Rails 4.2.0
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

21. 23% slower
    

    View Slide

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

23. time
    

    View Slide

24. time
    was not a good baseline
    

    View Slide

25. GET
    A
    BASELINE
    

    View Slide

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

    View 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 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. $ ruby -Ilib:test test/controllers/documents_benchmark_test.rb
    

    View Slide

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

    View Slide

35. 2.34x slower
    

    View Slide

36. Sanity check:
    Ruby 2.1.5 2.2.0
    Rails 4.2.0 master
    

    View Slide

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

    View Slide

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

    View Slide

39. 2.53x slower
    

    View Slide

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

    Ruby 2.1.5
    Rails master

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

    View Slide

41. GOT
    A
    BASELINE
    

    View Slide

42. FIND
    THE
    CULPRITS
    

    View Slide

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

    View Slide

44. RubyProf Benefit:
    ✓ Industry standard
    

    View 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 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 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. $ ruby -Ilib:test test/integration/documents_rubyprof_index_test.rb
    

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

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

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

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

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

    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 child
    

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

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

    View Slide

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

    View Slide

60. 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
    File.open('graphs/callstack.html', 'w') do |file|
    - RubyProf::GraphHtmlPrinter.new(result).print(file)
    + RubyProf::CallStackPrinter.new(result).print(file)
    end
    

    View Slide

62. View Slide

63. View Slide

64. View Slide

65. RubyProf Benefit:
    ✓ Shows the big picture
    

    View Slide

66. RubyProf Disadvantage:
    Data is overwhelming
    
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

70. StackProf
    github.com/tmm1/stackprof
    

    View Slide

71. StackProf Benefit:
    ✓ Focused profiling
    

    View Slide

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

    View Slide

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

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

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

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

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

    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
    % of total
    samples
    

    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
    samples where
    most time spent
    

    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
    samples where
    most time spent
    

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

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

88. Done!
    

    View Slide

89. View Slide

90. A
    B
    B
    

    View Slide

91. ALWAYS
    B
    B
    

    View Slide

92. ALWAYS
    BE
    B
    

    View Slide

93. ALWAYS
    BE
    BENCHMARKING
    

    View Slide

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

    View Slide

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

    View Slide

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

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

    View Slide

98. View Slide

99. StackProf Disadvantage:
    Bug in CPU time
    on OSX
    
    

    View 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')
     - 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

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

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

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     Ruby 2.2.0
     Expand

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

     View Slide

108. StackProf Benefit:
     ✓ Helps pinpoint the

     problem quickly
     

     View Slide

109. StackProf Disadvantage:
     Difficult to pinpoint
     problems in dynamic
     methods
     
     

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

114. View Slide

115. CACHING
     IS
     EXPENSIVE
     

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

122. StackProf:
     Helped us find the biggest
     culprits of slowdown in Rails
     

     View Slide

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

     View Slide

124. AllocationTracer
     github.com/ko1/allocation_tracer
     

     View Slide

125. AllocationTracer Benefit:
     ✓ Focuses on a specific
     problem
     

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

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

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

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

     View 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]]
     line number
     

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

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

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

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

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

     View Slide

146. View Slide

147. View Slide

148. PROVE
     ALLOCATIONS
     ARE A
     BOTTLENECK
     

     View Slide

149. AllocationTracer:
     Helped us find unnecessary
     allocations of objects
     

     View Slide

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

     View Slide

151. VS
     ITERATIONS
     BEFORE
     393.8
     ITERATIONS
     AFTER
     828.4
     

     View Slide

152. ~3x faster
     

     View Slide

153. KNOW
     YOUR
     TOOLS
     

     View Slide

154. USE
     MULTIPLE
     TOOLS
     

     View Slide

155. ALWAYS
     BE
     BENCHMARKING
     

     View Slide

156. Thanks
     @tenderlove!
     

     View Slide

157. Thanks everyone!
     @ko1
     @ruby-prof
     @tmm1
     and YOU!
     @evanphx
     

     View Slide

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

     View Slide