$30 off During Our Annual Pro Sale. View Details »

Real Time Salami

Real Time Salami

RubyConf2012 talk about real time applications, salami making, and much more.

Aaron Patterson

November 02, 2012
Tweet

More Decks by Aaron Patterson

Other Decks in Technology

Transcript

  1. Ingredients
    ❤ Pork
    ❤ Salt, nitrate, nitrite
    ❤ Dextose, Sugar
    ❤ White Pepper, Black Pepper
    ❤ Garlic, Fennel
    ❤ Chianti

    View Slide

  2. Aaron Patterson
    @tenderlove

    View Slide

  3. Aaron Patterson
    @tenderlove
    NO TIME

    View Slide

  4. AT&T, AT&T logo and all AT&T related marks are trademarks of AT&T Intellectual Property and/or AT&T affiliated companies.

    View Slide

  5. AT&T, AT&T logo and all AT&T related marks are trademarks of AT&T Intellectual Property and/or AT&T affiliated companies.
    NO TIME

    View Slide

  6. WWFMD

    View Slide

  7. WWFMD
    NO TIME

    View Slide

  8. View Slide

  9. ALWAYS
    IME

    View Slide

  10. Gorbachev
    Puff-Puff
    Thunderhorse

    View Slide

  11. View Slide

  12. View Slide

  13. View Slide

  14. View Slide

  15. View Slide

  16. View Slide

  17. @gorbypuff

    View Slide

  18. View Slide

  19. View Slide

  20. FOOD STUFF
    WORK STUFF
    HACKER STUFF

    View Slide

  21. FOOD
    STUFF

    View Slide

  22. Meat Curing
    Fermented Sausages

    View Slide

  23. Botulism

    View Slide

  24. Great Robot
    Uprising of 1863

    View Slide

  25. PSA: Use Metric
    no, seriously

    View Slide

  26. Hardware

    View Slide

  27. Wine
    Fridge

    View Slide

  28. Temp Controller
    20ºF - 80ºF

    View Slide

  29. Ionizing Humidifier

    View Slide

  30. Humidity Controller

    View Slide

  31. Fans

    View Slide

  32. Grinding

    View Slide

  33. Stuffing

    View Slide

  34. Ingredients

    View Slide

  35. Meat (80%)
    Pork Shoulder

    View Slide

  36. Fat (20%)
    Pork back fat

    View Slide

  37. Sugar (0.5%)
    Dextrose (glucose) and Sucrose

    View Slide

  38. Salt (3%)
    NaCL + Nitrate + Nitrite

    View Slide

  39. Pink Salt (Cure #2)

    View Slide

  40. Nitrates release Nitrites

    View Slide

  41. Nitrites prevent
    Botulism

    View Slide

  42. Nitrites change
    the meat color.

    View Slide

  43. 0hrs
    24hrs

    View Slide

  44. Bacteria (0.012%)
    Bactoferm T-SPX
    (Pediococcus pentosaceus & Staphylococcus xylosus)
    30
    DAYS

    View Slide

  45. Bactoferm F-RM-52
    (Lactobacillus sakei & Staphylococcus carnosus)
    7
    DAYS

    View Slide

  46. Spices

    View Slide

  47. Curing Environment

    View Slide

  48. Windspeed

    View Slide

  49. Temperature
    50
    55
    60
    65
    70
    Day 1 Day 2 Day 3 Day 4 Day 5 Day 6 Day 7
    Temperature (F)

    View Slide

  50. Wine Fridge
    55ºF - 65ºF

    View Slide

  51. Hack Your Fridge

    View Slide

  52. Humidity
    0
    22.5
    45
    67.5
    90
    Day 1 Day 2 Day 3 Day 4 Day 5 Day 6 Day 7
    Relative Humidity

    View Slide

  53. Humidity Controller

    View Slide

  54. Humidity Controller

    View Slide

  55. Humidity
    Feed

    View Slide

  56. Addiction

    View Slide

  57. Safety

    View Slide

  58. Salt

    View Slide

  59. Nitrite
    Prevents Botulism

    View Slide

  60. 22 mg / kg
    lethal dose

    View Slide

  61. Pink Salt
    for safety

    View Slide

  62. Acid

    View Slide

  63. 4
    4.75
    5.5
    6.25
    7
    Day 1 Day 2 Day 3 Day 4 Day 5 Day 6 Day 7
    pH
    pH (0.3% sugar)

    View Slide

  64. pH Meter

    View Slide

  65. Water
    ~45% weight loss (30% minimum)

    View Slide

  66. Salt
    Nitrite
    Acid
    Water
    Activity
    Short Medium Long

    View Slide

  67. Molds

    View Slide

  68. WORK
    STUFF

    View Slide

  69. Streaming
    Fermented Sausages

    View Slide

  70. Template
    Rendering Today

    View Slide

  71. Templates Results
    are Buffered

    View Slide

  72. Clients are blocked
    while Rails works

    View Slide

  73. The entire page
    must fit in memory

    View Slide

  74. We can do I/O and
    CPU in parallel.

    View Slide

  75. So why buffer?

    View Slide

  76. ActionController::Live

    View Slide

  77. Example
    class BrowserController < ApplicationController
    include ActionController::Live
    def index
    100.times do
    response.stream.write "hello!\n"
    end
    response.stream.close
    end
    end

    View Slide

  78. Example
    class BrowserController < ApplicationController
    include ActionController::Live
    def index
    100.times do
    response.stream.write "hello!\n"
    end
    response.stream.close
    end
    end
    Mix in
    Stream

    View Slide

  79. response.stream
    acts like
    an I/O object

    View Slide

  80. Everything
    Is a File

    View Slide

  81. How does it work?

    View Slide

  82. Our API
    def index
    response.status = 200
    response.headers[‘X-Whatever’] = ‘<3’
    response.stream.write ‘hello’
    response.stream.write ‘ world’
    response.stream.close
    end

    View Slide

  83. Rack API
    def call(env)
    return [200,
    {‘X-Whatever’ => ‘<3’},
    [‘hello world’]]
    end

    View Slide

  84. Wrapped Response
    class Response
    attr_accessor :status
    attr_reader :headers, :stream
    def initialize
    @status = 200
    @headers = {}
    @stream = StringIO.new
    end
    end
    def call(env)
    res = Response.new
    controller.response = res
    controller.index
    [res.status, res.headers, res.stream]
    end

    View Slide

  85. Threaded action
    def call(env)
    res = Response.new
    controller.response = res
    Thread.new { controller.index }
    [res.status, res.headers, res.stream]
    end

    View Slide

  86. Block until write
    def call(env)
    res = Response.new
    controller.response = res
    Thread.new { controller.index }
    res.stream.await
    [res.status, res.headers, res.stream]
    end

    View Slide

  87. Block until write
    def call(env)
    res = Response.new
    controller.response = res
    Thread.new { controller.index }
    res.stream.await
    [res.status, res.headers, res.stream]
    end
    Block

    View Slide

  88. Blocking Buffer
    class Buffer
    def initialize
    @latch = Latch.new
    @buffer = Queue.new
    end
    def await # wait for write
    @latch.await
    end
    def write(str)
    @latch.release
    @buffer << str
    end
    end

    View Slide

  89. Blocking Buffer
    class Buffer
    def initialize
    @latch = Latch.new
    @buffer = Queue.new
    end
    def await # wait for write
    @latch.await
    end
    def write(str)
    @latch.release
    @buffer << str
    end
    end
    `call` blocks here

    View Slide

  90. Blocking Buffer
    class Buffer
    def initialize
    @latch = Latch.new
    @buffer = Queue.new
    end
    def await # wait for write
    @latch.await
    end
    def write(str)
    @latch.release
    @buffer << str
    end
    end
    `write` unblocks

    View Slide

  91. What can we do?

    View Slide

  92. Rails Internals

    View Slide

  93. Streaming ERB

    View Slide

  94. View Source
    # encoding: utf-8
    require 'erb'
    doc = ERB.new '<%= hello %> world'
    puts doc.src

    View Slide

  95. Source
    #coding:UTF-8
    _erbout = '';
    _erbout.concat(( hello ).to_s);
    _erbout.concat " world";
    _erbout.force_encoding(__ENCODING__)

    View Slide

  96. Control Output
    class MyERB < ERB
    def set_eoutvar(compiler, eoutvar = '_erbout')
    compiler.put_cmd = "#{eoutvar}.write"
    compiler.insert_cmd = "#{eoutvar}.write"
    compiler.pre_cmd = []
    compiler.post_cmd = []
    end
    end
    doc = MyERB.new '<%= hello %> world', nil, nil, '$stdout'
    puts doc.src

    View Slide

  97. Source
    #coding:UTF-8
    $stdout.write(( hello ).to_s);
    $stdout.write " world"

    View Slide

  98. $ ruby test.rb
    hello world
    $

    View Slide

  99. Choose streaming
    or buffering.

    View Slide

  100. Web Apps

    View Slide

  101. Infinite Streams

    View Slide

  102. Server Sent Events

    View Slide

  103. SSE Response
    HTTP/1.1 200 OK
    X-Frame-Options: SAMEORIGIN
    X-XSS-Protection: 1; mode=block
    X-Content-Type-Options: nosniff
    Content-Type: text/event-stream
    Transfer-Encoding: chunked
    event: ping
    data: {"ping":"2012-10-06T21:44:41-07:00"}
    event: reload
    data: {"changed":["/Users/aaron/git/lolwut/app/views/
    users/"]}

    View Slide

  104. SSE Response
    HTTP/1.1 200 OK
    X-Frame-Options: SAMEORIGIN
    X-XSS-Protection: 1; mode=block
    X-Content-Type-Options: nosniff
    Content-Type: text/event-stream
    Transfer-Encoding: chunked
    event: ping
    data: {"ping":"2012-10-06T21:44:41-07:00"}
    event: reload
    data: {"changed":["/Users/aaron/git/lolwut/app/views/
    users/"]}

    View Slide

  105. SSE Response
    HTTP/1.1 200 OK
    X-Frame-Options: SAMEORIGIN
    X-XSS-Protection: 1; mode=block
    X-Content-Type-Options: nosniff
    Content-Type: text/event-stream
    Transfer-Encoding: chunked
    event: ping
    data: {"ping":"2012-10-06T21:44:41-07:00"}
    event: reload
    data: {"changed":["/Users/aaron/git/lolwut/app/views/
    users/"]}

    View Slide

  106. SSE Response
    HTTP/1.1 200 OK
    X-Frame-Options: SAMEORIGIN
    X-XSS-Protection: 1; mode=block
    X-Content-Type-Options: nosniff
    Content-Type: text/event-stream
    Transfer-Encoding: chunked
    event: ping
    data: {"ping":"2012-10-06T21:44:41-07:00"}
    event: reload
    data: {"changed":["/Users/aaron/git/lolwut/app/views/
    users/"]}

    View Slide

  107. Client Side
    jQuery(document).ready(function() {
    setTimeout(function() {
    var source = new EventSource('/control');
    // if we get a reload command, reload the page
    source.addEventListener('reload', function(e) {
    window.location.reload();
    });
    }, 1);
    });

    View Slide

  108. Client Side
    jQuery(document).ready(function() {
    setTimeout(function() {
    var source = new EventSource('/control');
    // if we get a reload command, reload the page
    source.addEventListener('reload', function(e) {
    window.location.reload();
    });
    }, 1);
    });

    View Slide

  109. Client Side
    jQuery(document).ready(function() {
    setTimeout(function() {
    var source = new EventSource('/control');
    // if we get a reload command, reload the page
    source.addEventListener('reload', function(e) {
    window.location.reload();
    });
    }, 1);
    });

    View Slide

  110. Client Side
    jQuery(document).ready(function() {
    setTimeout(function() {
    var source = new EventSource('/control');
    // if we get a reload command, reload the page
    source.addEventListener('reload', function(e) {
    window.location.reload();
    });
    }, 1);
    });

    View Slide

  111. Real-Time Browser
    Communication

    View Slide

  112. View Slide

  113. Puma
    Browser
    FS-Events
    FS Events

    View Slide

  114. Puma
    Browser
    FS-Events
    FS Events

    View Slide

  115. Puma
    Browser
    Console
    DRB
    DB Events

    View Slide

  116. Puma
    Browser
    Console
    DRB
    DB Events
    Socket

    View Slide

  117. Real-Time Salami

    View Slide

  118. View Slide

  119. Data Broadcasting

    View Slide

  120. Thread Thread Thread
    Observer
    Browser
    Salami Browser
    Observer

    View Slide

  121. Thread Thread Thread
    Observer
    Browser
    Salami Browser
    Observer
    create index
    index

    View Slide

  122. Message Bus
    class Bus
    include Observable
    def publish data
    changed
    notify_observers data
    end
    def add_observer &block
    o = Class.new {
    define_method(:update) { |data| block.call data }
    }.new
    super(o)
    end
    end

    View Slide

  123. Subscriber
    BUS = Bus.new
    def index
    queue = Queue.new
    BUS.add_observer { |data| queue << data }
    # ..
    end

    View Slide

  124. Emit SSE
    def index
    queue = Queue.new
    observer = BUS.add_observer { |data| queue << data }
    begin
    while data = queue.pop
    begin
    io.write data, :event => 'measurement'
    rescue IOError
    queue.push nil
    io.close
    end
    end
    ensure
    BUS.delete_observer observer
    end
    end

    View Slide

  125. Publisher
    def create
    sig, data = params['_json']
    BUS.publish({ :now => Time.now,
    :data => JSON.load(data.unpack('m').first) })
    render :nothing => true
    end

    View Slide

  126. Feedback

    View Slide

  127. GChart + SSE
    var source = new EventSource('/measurements.json');
    var chart = document.getElementById('chart');
    source.addEventListener('measurement', function(e) {
    var payload = JSON.parse(e.data);
    var data = payload.data;
    if(chart && table) {
    var count = table.getNumberOfRows();
    table.addRow(['', data[0], data[1]]);
    if(count > 60) { table.removeRow(0); }
    gchart.draw(table, options(data.interface));
    }
    }, false);

    View Slide

  128. View Slide

  129. HACKER
    STUFF

    View Slide

  130. Ruby VM

    View Slide

  131. Stack Based

    View Slide

  132. View Slide

  133. Ghostscript
    GS>2
    GS<1>3
    GS<2>add
    GS<1>stack
    5
    GS<1>pop
    GS>
    []
    [2]
    [2, 3]
    [5]
    [5]
    []
    Instructions Stack

    View Slide

  134. In Ruby

    View Slide

  135. Compile
    is = RubyVM::InstructionSequence.new '2 + 3'

    View Slide

  136. Disassemble
    is = RubyVM::InstructionSequence.new '2 + 3'
    puts is.disasm

    View Slide

  137. Instructions
    0000 trace 1
    0002 putobject 2
    0004 putobject 3
    0006 opt_plus
    0008 leave

    View Slide

  138. Instructions
    0000 trace 1
    0002 putobject 2
    0004 putobject 3
    0006 opt_plus
    0008 leave
    Instruction names
    Parameters

    View Slide

  139. What does it mean?

    View Slide

  140. insns.def

    View Slide

  141. trace - trace (set_trace_func)
    putobject - push object on the stack
    opt_plus - optimized X + Y
    leave - return from this scope

    View Slide

  142. Slight Detour

    View Slide

  143. Ruby -> GS
    /trace { pop } def
    /putobject { } def
    /opt_plus { add } def
    /leave { } def

    View Slide

  144. Ruby on GS
    GS>1 trace
    GS>1 putobject
    GS<1>2 putobject
    GS<2>opt_plus
    GS<1>leave
    GS<1>stack
    3
    GS<1>

    View Slide

  145. Translation
    is = RubyVM::InstructionSequence.new '2 + 3'
    puts is.to_a.last.map { |l,i|
    [Hash === i ? nil : i, l].compact.join ' '
    }.join "\n"
    1 trace
    2 putobject
    3 putobject
    opt_plus
    leave
    Translated
    Instructions

    View Slide

  146. 2013: PrintRuby

    View Slide

  147. MASSIVELY
    Distributed

    View Slide

  148. MASSIVELY
    Distributed

    View Slide

  149. Take that
    Node.js!

    View Slide

  150. Slight Detour
    Massive Detour

    View Slide

  151. Actual
    Slight Detour

    View Slide

  152. Get Instructions
    RubyVM::InstructionSequence#to_a

    View Slide

  153. to_a
    irb> is = RubyVM::InstructionSequence.new '3 +
    2'
    =>
    irb> is.to_a
    => ["YARVInstructionSequence/SimpleDataFormat",
    2, 0, 1,
    {:arg_size=>0, :local_size=>1, :stack_max=>2},
    "", "", nil, 1, :top, [], 0,
    [], [[:trace, 1], [:putobject, 3], [:putobject,
    2], [:opt_plus, {:mid=>:
    +, :flag=>256, :orig_argc=>1, :blockptr=>nil}],
    [:leave]]]

    View Slide

  154. Eval Instructions
    RubyVM::InstructionSequence#eval

    View Slide

  155. eval
    irb> is =
    RubyVM::InstructionSequence.new '3 + 2'
    =>
    irb> is.eval
    => 5

    View Slide

  156. Load Instructions?
    Can’t do it.

    View Slide

  157. Or can we?

    View Slide

  158. View Slide

  159. View Slide

  160. View Slide

  161. handle = DL::Handle::DEFAULT
    address = handle['rb_iseq_load']
    func = Fiddle::Function.new(address,
    [DL::TYPE_VOIDP] * 3,
    DL::TYPE_VOIDP)
    RubyVM::InstructionSequence.class_eval do
    # This monkey patch allows us to load arbitrary byte code with
    # Ruby's VM
    define_singleton_method(:load) { |data, parent = nil, opt = nil|
    func.call(DL.dlwrap(data), parent, opt).to_value
    }
    end

    View Slide

  162. handle = DL::Handle::DEFAULT
    address = handle['rb_iseq_load']
    func = Fiddle::Function.new(address,
    [DL::TYPE_VOIDP] * 3,
    DL::TYPE_VOIDP)
    RubyVM::InstructionSequence.class_eval do
    # This monkey patch allows us to load arbitrary byte code with
    # Ruby's VM
    define_singleton_method(:load) { |data, parent = nil, opt = nil|
    func.call(DL.dlwrap(data), parent, opt).to_value
    }
    end

    View Slide

  163. is = RubyVM::InstructionSequence.new '3 + 5'
    is2 = RubyVM::InstructionSequence.load is.to_a
    p is2.eval # => 8
    Load Instructions

    View Slide

  164. Manipulate Insns
    is = RubyVM::InstructionSequence.new '3 + 5'
    myis = is.to_a
    myis.last.map! { |ins, val|
    if ins == :putobject
    [ins, 10]
    else
    [ins, val].compact
    end
    }
    is2 = RubyVM::InstructionSequence.load myis
    p is2.eval # => 20

    View Slide

  165. When your code is
    a little too readable.

    View Slide

  166. When “meta” isn’t
    meta enough.

    View Slide

  167. Take your app
    from lolscale to
    roflscale

    View Slide

  168. Works on every
    Ruby: Guaranteed

    View Slide

  169. Works on every
    Ruby: Guaranteed
    Seal of
    Approval

    View Slide

  170. He’s lying.

    View Slide

  171. Yes, you
    are.

    View Slide

  172. Listen, we’ve
    been talking, and
    we think you have
    a problem

    View Slide

  173. Anyway,

    View Slide

  174. Cool hacks, but
    what else?

    View Slide

  175. Micro-
    Optimizations

    View Slide

  176. Step 1:
    Benchmark

    View Slide

  177. def active_record
    user = User.find_by_login('tater')
    user.starred_items.count
    end
    require 'perftools'
    PerfTools::CpuProfiler.start("/tmp/ar")
    10000.times { active_record }
    PerfTools::CpuProfiler.stop

    View Slide

  178. ActiveRecord
    ConnectionAdapters
    Mysql2Adapter#execute
    0 (0.0%)
    of 107 (21.0%)
    Enumerable#to_a
    0 (0.0%)
    of 32 (6.3%)
    ActiveRecord
    ConnectionAdapters
    AbstractAdapter#log
    9 (1.8%)
    of 107 (21.0%)
    ActiveSupport
    Notifications
    Instrumenter#instrument
    0 (0.0%)
    of 98 (19.3%)
    98
    ActiveRecord
    ConnectionAdapters
    AbstractMysqlAdapter#execute
    0 (0.0%)
    of 107 (21.0%)
    107
    107
    Arel
    Visitors
    ToSql#accept
    0 (0.0%)
    of 104 (20.4%)
    Arel
    Visitors
    MySQL#visit_Arel_Nodes_SelectStatement
    1 (0.2%)
    of 104 (20.4%)
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_SelectStatement
    1 (0.2%)
    of 103 (20.2%)
    103
    Arel
    Visitors
    Visitor#accept
    0 (0.0%)
    of 104 (20.4%)
    104
    Arel
    Visitors
    Visitor#visit
    1 (0.2%)
    of 104 (20.4%)
    104
    104
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_JoinSource
    1 (0.2%)
    of 40 (7.9%)
    40
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_InnerJoin
    9 (1.8%)
    of 22 (4.3%)
    22
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_Equality
    8 (1.6%)
    of 18 (3.5%)
    18
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_On
    0 (0.0%)
    of 13 (2.6%)
    13
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_And
    0 (0.0%)
    of 11 (2.2%)
    11
    Arel
    Visitors
    ToSql#visit_Arel_Attributes_Attribute
    10 (2.0%)
    10
    Array#map
    3 (0.6%)
    of 92 (18.1%)
    91
    Array#join
    51 (10.0%)
    11
    Mysql2
    Client#query
    82 (16.1%)
    of 83 (16.3%)
    83
    ActiveSupport
    Notifications
    Fanout#start
    0 (0.0%)
    of 15 (2.9%)
    15 41
    Arel
    Visitors
    MySQL#visit_Arel_Nodes_SelectCore
    0 (0.0%)
    of 91 (17.9%)
    91
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_SelectCore
    16 (3.1%)
    of 91 (17.9%)
    91
    41
    14
    18
    22
    17
    Mysql2
    Result#each
    32 (6.3%)
    32
    Struct#hash
    4 (0.8%)
    of 21 (4.1%)
    13
    Arel
    Table#hash
    2 (0.4%)
    of 17 (3.3%)
    17
    10
    15
    ActiveSupport
    Notifications
    Fanout#listeners_for
    9 (1.8%)
    9
    13
    6
    5
    ARel
    mysql2

    View Slide

  179. Quick PSA:
    AR::Relation != ARel

    View Slide

  180. user.starred.foo.bar.count
    starred

    View Slide

  181. user.starred.foo.bar.count
    starred foo
    bar
    count
    SQL AST DB

    View Slide

  182. Build a tree to
    build a tree

    View Slide

  183. Yo Dawg Moment

    View Slide

  184. ActiveRecord
    ConnectionAdapters
    Mysql2Adapter#execute
    0 (0.0%)
    of 107 (21.0%)
    Enumerable#to_a
    0 (0.0%)
    of 32 (6.3%)
    ActiveRecord
    ConnectionAdapters
    AbstractAdapter#log
    9 (1.8%)
    of 107 (21.0%)
    ActiveSupport
    Notifications
    Instrumenter#instrument
    0 (0.0%)
    of 98 (19.3%)
    98
    ActiveRecord
    ConnectionAdapters
    AbstractMysqlAdapter#execute
    0 (0.0%)
    of 107 (21.0%)
    107
    107
    Arel
    Visitors
    ToSql#accept
    0 (0.0%)
    of 104 (20.4%)
    Arel
    Visitors
    MySQL#visit_Arel_Nodes_SelectStatement
    1 (0.2%)
    of 104 (20.4%)
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_SelectStatement
    1 (0.2%)
    of 103 (20.2%)
    103
    Arel
    Visitors
    Visitor#accept
    0 (0.0%)
    of 104 (20.4%)
    104
    Arel
    Visitors
    Visitor#visit
    1 (0.2%)
    of 104 (20.4%)
    104
    104
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_JoinSource
    1 (0.2%)
    of 40 (7.9%)
    40
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_InnerJoin
    9 (1.8%)
    of 22 (4.3%)
    22
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_Equality
    8 (1.6%)
    of 18 (3.5%)
    18
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_On
    0 (0.0%)
    of 13 (2.6%)
    13
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_And
    0 (0.0%)
    of 11 (2.2%)
    11
    Arel
    Visitors
    ToSql#visit_Arel_Attributes_Attribute
    10 (2.0%)
    10
    Array#map
    3 (0.6%)
    of 92 (18.1%)
    91
    Array#join
    51 (10.0%)
    11
    Mysql2
    Client#query
    82 (16.1%)
    of 83 (16.3%)
    83
    ActiveSupport
    Notifications
    Fanout#start
    0 (0.0%)
    of 15 (2.9%)
    15 41
    Arel
    Visitors
    MySQL#visit_Arel_Nodes_SelectCore
    0 (0.0%)
    of 91 (17.9%)
    91
    Arel
    Visitors
    ToSql#visit_Arel_Nodes_SelectCore
    16 (3.1%)
    of 91 (17.9%)
    91
    41
    14
    18
    22
    17
    Mysql2
    Result#each
    32 (6.3%)
    32
    Struct#hash
    4 (0.8%)
    of 21 (4.1%)
    13
    Arel
    Table#hash
    2 (0.4%)
    of 17 (3.3%)
    17
    10
    15
    ActiveSupport
    Notifications
    Fanout#listeners_for
    9 (1.8%)
    9
    13
    6
    5
    ARel
    mysql2

    View Slide

  185. Step 2:
    Look at the code

    View Slide

  186. Select Core
    def visit_Arel_Nodes_SelectCore o
    [
    "SELECT",
    ("FROM #{visit(o.source)} " if o.source),
    ].compact.join ' '
    end

    View Slide

  187. Select Core
    def visit_Arel_Nodes_SelectCore o
    [
    "SELECT",
    ("FROM #{visit(o.source)} " if o.source),
    ].compact.join ' '
    end

    View Slide

  188. Step 3:
    Read the insns

    View Slide

  189. “SELECT”
    irb> puts RubyVM::InstructionSequence.new('"SELECT"').disasm
    == disasm:
    @>==========
    0000 trace 1
    0002 putstring "SELECT"
    0004 leave
    => nil

    View Slide

  190. putstring
    VALUE
    rb_str_resurrect(VALUE str)
    {
    return str_replace(str_alloc(rb_cString), str);
    }

    View Slide

  191. Easy Proof
    irb> 10.times { puts "foo".object_id }
    70166440589860
    70166440589800
    70166440589740
    70166440589660
    70166440589580
    70166440589520
    70166440589420
    70166440589360
    70166440589260
    70166440589200
    => 10

    View Slide

  192. "FROM #{visit(o.source)} "
    irb> puts RubyVM::InstructionSequence.new('"FROM
    #{visit(o.source)} "').disasm
    == disasm:
    @>==========
    0000 trace 1
    0002 putobject "FROM "
    0004 putself
    0005 putself
    0006 send :o, 0, nil, 24,
    0012 send :source, 0, nil, 0,
    0018 send :visit, 1, nil, 8,
    0024 tostring
    0025 putstring " "
    0027 concatstrings 3
    0029 leave
    => nil

    View Slide

  193. "FROM #{visit(o.source)} "
    irb> puts RubyVM::InstructionSequence.new('"FROM
    #{visit(o.source)} "').disasm
    == disasm:
    @>==========
    0000 trace 1
    0002 putobject "FROM "
    0004 putself
    0005 putself
    0006 send :o, 0, nil, 24,
    0012 send :source, 0, nil, 0,
    0018 send :visit, 1, nil, 8,
    0024 tostring
    0025 putstring " "
    0027 concatstrings 3
    0029 leave
    => nil

    View Slide

  194. putobject
    /**
    @c put
    @e put some object.
    i.e. Fixnum, true, false, nil, and so on.
    @j ΦϒδΣΫτ val ΛελοΫʹϓογϡ͢Δɻ
    i.e. Fixnum, true, false, nil, and so on.
    */
    DEFINE_INSN
    putobject
    (VALUE val)
    ()
    (VALUE val)
    {
    /* */
    }

    View Slide

  195. putobject
    /**
    @c put
    @e put some object.
    i.e. Fixnum, true, false, nil, and so on.
    @j ΦϒδΣΫτ val ΛελοΫʹϓογϡ͢Δɻ
    i.e. Fixnum, true, false, nil, and so on.
    */
    DEFINE_INSN
    putobject
    (VALUE val)
    ()
    (VALUE val)
    {
    /* */
    }
    It does nothing.

    View Slide

  196. “foo #{x} bar #{y} baz”

    View Slide

  197. “foo #{x} bar #{y} baz”
    putobject

    View Slide

  198. “foo #{x} bar #{y} baz”
    putstring

    View Slide

  199. “foo #{x} bar #{y} baz”
    putstring

    View Slide

  200. “foo #{x} bar #{y} baz”
    concat

    View Slide

  201. “foo #{x} bar #{y} baz”
    Fixed
    in
    2.0

    View Slide

  202. “foo #{x} bar #{y} baz”
    putobject
    Fixed
    in
    2.0

    View Slide

  203. “foo #{x} bar #{y} baz”
    putobject
    Fixed
    in
    2.0

    View Slide

  204. “foo #{x} bar #{y} baz”
    putobject
    Fixed
    in
    2.0

    View Slide

  205. “foo #{x} bar #{y} baz”
    concat
    Fixed
    in
    2.0

    View Slide

  206. Step 4:
    Update the code

    View Slide

  207. Use Constants
    irb> SELECT = "SELECT"
    => "SELECT"
    irb> 5.times { p SELECT.object_id }
    70230907127200
    70230907127200
    70230907127200
    70230907127200
    70230907127200
    => 5

    View Slide

  208. Use String#<<
    FROM = "FROM "
    def visit_Arel_Nodes_SelectCore o
    select = "SELECT"
    if o.source
    select << FROM
    select << visit(o.source)
    end
    select
    end

    View Slide

  209. String Allocations
    FROM = "FROM "
    def visit_Arel_Nodes_SelectCore o
    select = "SELECT"
    if o.source
    select << FROM
    select << visit(o.source)
    end
    select
    end

    View Slide

  210. String Allocations
    FROM = "FROM "
    def visit_Arel_Nodes_SelectCore o
    select = "SELECT"
    if o.source
    select << FROM
    select << visit(o.source)
    end
    select
    end

    View Slide

  211. 18% reduction in
    GC invocations.
    56 -> 46 invocations

    View Slide

  212. 18% reduction in
    GC time.
    963ms => 786ms

    View Slide

  213. Please, please,

    View Slide

  214. please, please,

    View Slide

  215. please, please,

    View Slide

  216. optimize for
    readability first,

    View Slide

  217. then find your
    bottlenecks.

    View Slide

  218. DTrace
    Ruby 2.0

    View Slide

  219. Probe Format
    provider:module:function:name
    /predicate/
    {
    D Code
    }

    View Slide

  220. Ruby Probes
    ruby:::function-entry;
    ruby:::function-return;
    ruby:::require-entry;
    ruby:::require-return;
    ruby:::load-entry;
    ruby:::load-return;
    ruby:::raise;
    ruby:::object-create;
    ruby:::array-create;
    ruby:::hash-create;
    ruby:::string-create;
    ruby:::parse-begin;
    ruby:::parse-end;
    ruby:::insn;
    ruby:::insn-operand;
    ruby:::gc-mark-begin;
    ruby:::gc-mark-end;
    ruby:::gc-sweep-begin;
    ruby:::gc-sweep-end;

    View Slide

  221. Function Probes
    ruby:::function-entry;
    ruby:::function-return;
    ruby:::require-entry;
    ruby:::require-return;
    ruby:::load-entry;
    ruby:::load-return;
    ruby:::raise;

    View Slide

  222. Object Creation
    ruby:::object-create;
    ruby:::array-create;
    ruby:::hash-create;
    ruby:::string-create;

    View Slide

  223. GC Actions
    ruby:::gc-mark-begin;
    ruby:::gc-mark-end;
    ruby:::gc-sweep-begin;
    ruby:::gc-sweep-end;

    View Slide

  224. Ruby Internals
    ruby:::parse-begin;
    ruby:::parse-end;
    ruby:::insn;
    ruby:::insn-operand;

    View Slide

  225. Inspecting Rails
    Boot Time

    View Slide

  226. No incredible
    revelations

    View Slide

  227. No incredible
    revelations
    SPOILER

    View Slide

  228. Count Insns
    ruby$target:::insn
    {
    @[copyinstr(arg0)] = count();
    }

    View Slide

  229. Test Script
    ruby -Ilib:. -rconfig/environment -e 0

    View Slide

  230. Output
    putself 76307
    putobject 79394
    leave 141904
    opt_send_simple 204104
    getlocal 249011
    trace 421121
    $

    View Slide

  231. Modify Compile
    RubyVM::InstructionSequence.compile_option = {
    trace_instruction: false
    }

    View Slide

  232. Works on every
    Ruby: Guaranteed

    View Slide

  233. Works on every
    Ruby: Guaranteed
    Seal of
    Approval

    View Slide

  234. He’s lying
    again.

    View Slide

  235. Output
    branchunless 56244
    setlocal 56857
    branchif 60836
    dup 65032
    send 66905
    putself 76301
    putobject 79396
    leave 141896
    opt_send_simple 204095
    getlocal 249000
    $

    View Slide

  236. Is it faster?
    100 samples of loading config/environment.rb

    View Slide

  237. > mean(times$trace)
    [1] 1.570746
    > mean(times$notrace)
    [1] 1.545819
    Runtime (in s)

    View Slide

  238. > sd(times$notrace)
    [1] 0.05686799
    > sd(times$trace)
    [1] 0.05532489
    Standard Dev (in s)

    View Slide

  239. Answer: no.

    View Slide

  240. Favorite
    Instruction?

    View Slide

  241. Use a timer
    tick-5000hz
    {
    @[insn] = count();
    }
    ruby$target:::insn
    {
    insn = copyinstr(arg0);
    }

    View Slide

  242. Samples
    branchif 518
    putself 542
    getinstancevariable 550
    putobject 667
    leave 1355
    getconstant 1521
    invokesuper 1655
    getlocal 2009
    opt_send_simple 3008
    send 5958
    $

    View Slide

  243. trace trace 57
    getclassvariable 64
    opt_regexpmatch1 65
    toregexp 66
    setinlinecache 82
    jump 83
    newarray 99
    tostring 112
    concatstrings 115
    opt_regexpmatch2 120
    expandarray 133
    defined 179
    setinstancevariable 189
    putspecialobject 209
    opt_eq 233
    checkmatch 234
    putstring 234
    opt_aref 285
    putnil 315
    defineclass 336
    getinlinecache 402
    pop 433
    dup 464
    setlocal 471
    branchunless 491
    branchif 518
    putself 542
    getinstancevariable 550
    putobject 667
    leave 1355
    getconstant 1521
    invokesuper 1655
    getlocal 2009
    opt_send_simple 3008
    send 5958

    View Slide

  244. GC Time.

    View Slide

  245. Measure GC time
    ruby$target:::gc-mark-begin { self->mark = timestamp; }
    ruby$target:::gc-sweep-begin { self->sweep = timestamp; }
    ruby$target:::gc-mark-end
    {
    @mark_time = sum(timestamp - self->mark);
    }
    ruby$target:::gc-sweep-end
    {
    @sweep_time = sum(timestamp - self->sweep);
    }

    View Slide

  246. Track Total Time
    BEGIN { start = timestamp; }
    END {
    total = timestamp - start;
    printf("mark time (ns): ");
    printa("%@d\n", @mark_time);
    printf("sweep time (ns): ");
    printa("%@d\n", @sweep_time);
    printf("total time (ns): %d", total);
    }

    View Slide

  247. GC Time
    mark time (ns) 276526868
    sweep time (ns) 74943136
    program time (ns) 1464656199

    View Slide

  248. GC Time
    76%
    5%
    19%
    Mark Sweep Rest
    mark time (ns) 276526868
    sweep time (ns) 74943136
    program time (ns) 1464656199

    View Slide

  249. Compile Time.

    View Slide

  250. Parse and Compile
    ruby$target:::parse-begin
    {
    parse = timestamp;
    }
    ruby$target:::parse-end
    {
    @compile = sum(timestamp - parse);
    }

    View Slide

  251. Compile time
    compile time (ns) 255934383
    program time (ns) 1237971025
    79%
    21%
    Compile Rest

    View Slide

  252. Searching.

    View Slide

  253. D Probes
    ruby$target:::find-require-entry
    {
    req_search = timestamp;
    }
    ruby$target:::find-require-return
    {
    t = timestamp;
    printf("%d,%d,%s\n", t, t - req_search, copyinstr(arg0));
    }

    View Slide

  254. Statistics
    Total Files 1649
    Total Search Time 460096404
    Total Time 1499901879
    Mean Time 278846
    Min Time 13840
    Max Time 1392542
    Std Dev 192585
    Time in Nanoseconds
    30%

    View Slide

  255. View Slide

  256. Linear Fit
    Call:
    lm(formula = trunk_require$y ~ trunk_require$x)
    Coefficients:
    (Intercept) trunk_require$x
    134747.2 174.6

    View Slide

  257. Bug #7158

    View Slide

  258. Statistics
    Total Files 1649
    Total Search Time 182910579
    Total Time 1141907918
    Mean Time 110854
    Min Time 1905
    Max Time 926160
    Std Dev 134429
    Time in Nanoseconds
    16%

    View Slide

  259. Comparison
    0
    375
    750
    1125
    1500
    Program Time (ms) Search Time (ms)
    trunk Bug #7158

    View Slide

  260. View Slide

  261. Sorted Compare

    View Slide

  262. $ time ruby-trunk -Ilib:. -rconfig/environment -e 0
    real 0m1.479s
    user 0m1.280s
    sys 0m0.191s
    $ time ruby-req -Ilib:. -rconfig/environment -e 0
    real 0m1.145s
    user 0m0.972s
    sys 0m0.169s

    View Slide

  263. Combined!

    View Slide

  264. rest
    25%
    find file
    30%
    compile
    21%
    sweep
    5%
    mark
    19%
    mark
    sweep
    compile
    find file
    rest
    Combined Graph

    View Slide

  265. rest
    39%
    find file
    16%
    compile
    21%
    sweep
    5%
    mark
    19%
    mark
    sweep
    compile
    find file
    rest
    After #7158

    View Slide

  266. #7158 = ὑὑὑὑ

    View Slide

  267. View Slide

  268. Stay cool!!!

    View Slide

  269. Never change!!!

    View Slide

  270. Work!

    View Slide

  271. Eat!

    View Slide

  272. Hack!

    View Slide

  273. Try Ruby 2.0!

    View Slide

  274. View Slide

  275. THANK YOU

    View Slide

  276. Profile Info
    https://gist.github.com/3989310
    https://gist.github.com/3997732
    https://bugs.ruby-lang.org/issues/7158

    View Slide