Real Time Salami

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

Transcript

1. Ingredients ❤ Pork ❤ Salt, nitrate, nitrite ❤ Dextose, Sugar ❤ White Pepper, Black Pepper ❤ Garlic, Fennel ❤ Chianti
2. Aaron Patterson @tenderlove
3. Aaron Patterson @tenderlove NO TIME
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.
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
6. WWFMD
7. WWFMD NO TIME
9. ALWAYS IME
10. Gorbachev Puff-Puff Thunderhorse
17. @gorbypuff
20. FOOD STUFF WORK STUFF HACKER STUFF
21. FOOD STUFF
22. Meat Curing Fermented Sausages
23. Botulism
24. Great Robot Uprising of 1863
25. PSA: Use Metric no, seriously
26. Hardware
27. Wine Fridge
28. Temp Controller 20ºF - 80ºF
29. Ionizing Humidifier
30. Humidity Controller
31. Fans
32. Grinding
33. Stuffing
34. Ingredients
35. Meat (80%) Pork Shoulder
36. Fat (20%) Pork back fat
37. Sugar (0.5%) Dextrose (glucose) and Sucrose
38. Salt (3%) NaCL + Nitrate + Nitrite
39. Pink Salt (Cure #2)
40. Nitrates release Nitrites
41. Nitrites prevent Botulism
42. Nitrites change the meat color.
43. 0hrs 24hrs
44. Bacteria (0.012%) Bactoferm T-SPX (Pediococcus pentosaceus & Staphylococcus xylosus) 30 DAYS
45. Bactoferm F-RM-52 (Lactobacillus sakei & Staphylococcus carnosus) 7 DAYS
46. Spices
47. Curing Environment
48. Windspeed
49. Temperature 50 55 60 65 70 Day 1 Day 2 Day 3 Day 4 Day 5 Day 6 Day 7 Temperature (F)
50. Wine Fridge 55ºF - 65ºF
51. Hack Your Fridge
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
53. Humidity Controller
54. Humidity Controller
55. Humidity Feed
56. Addiction
57. Safety
58. Salt
59. Nitrite Prevents Botulism
60. 22 mg / kg lethal dose
61. Pink Salt for safety
62. Acid
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)
64. pH Meter
65. Water ~45% weight loss (30% minimum)
66. Salt Nitrite Acid Water Activity Short Medium Long
67. Molds
68. WORK STUFF
69. Streaming Fermented Sausages
70. Template Rendering Today
71. Templates Results are Buffered
72. Clients are blocked while Rails works
73. The entire page must fit in memory
74. We can do I/O and CPU in parallel.
75. So why buffer?
76. ActionController::Live
77. Example class BrowserController < ApplicationController include ActionController::Live def index 100.times do response.stream.write "hello!\n" end response.stream.close end end
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
79. response.stream acts like an I/O object
80. Everything Is a File
81. How does it work?
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
83. Rack API def call(env) return [200, {‘X-Whatever’ => ‘<3’}, [‘hello world’]] end
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
85. Threaded action def call(env) res = Response.new controller.response = res Thread.new { controller.index } [res.status, res.headers, res.stream] end
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
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
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
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
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
91. What can we do?
92. Rails Internals
93. Streaming ERB
94. View Source # encoding: utf-8 require 'erb' doc = ERB.new '<%= hello %> world' puts doc.src
95. Source #coding:UTF-8 _erbout = ''; _erbout.concat(( hello ).to_s); _erbout.concat " world"; _erbout.force_encoding(__ENCODING__)
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
97. Source #coding:UTF-8 $stdout.write(( hello ).to_s); $stdout.write " world"
98. $ ruby test.rb hello world $
99. Choose streaming or buffering.
100. Web Apps
101. Infinite Streams
102. Server Sent Events
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/"]}
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/"]}
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/"]}
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/"]}
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); });
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); });
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); });
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); });
111. Real-Time Browser Communication
113. Puma Browser FS-Events FS Events
114. Puma Browser FS-Events FS Events
115. Puma Browser Console DRB DB Events
116. Puma Browser Console DRB DB Events Socket
117. Real-Time Salami
119. Data Broadcasting
120. Thread Thread Thread Observer Browser Salami Browser Observer
121. Thread Thread Thread Observer Browser Salami Browser Observer create index index
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
123. Subscriber BUS = Bus.new def index queue = Queue.new BUS.add_observer { |data| queue << data } # .. end
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
125. Publisher def create sig, data = params['_json'] BUS.publish({ :now => Time.now, :data => JSON.load(data.unpack('m').first) }) render :nothing => true end
126. Feedback
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);
129. HACKER STUFF
130. Ruby VM
131. Stack Based
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
134. In Ruby
135. Compile is = RubyVM::InstructionSequence.new '2 + 3'
136. Disassemble is = RubyVM::InstructionSequence.new '2 + 3' puts is.disasm
137. Instructions 0000 trace 1 0002 putobject 2 0004 putobject 3 0006 opt_plus <callinfo!mid:+, argc:1, ARGS_SKIP> 0008 leave
138. Instructions 0000 trace 1 0002 putobject 2 0004 putobject 3 0006 opt_plus <callinfo!mid:+, argc:1, ARGS_SKIP> 0008 leave Instruction names Parameters
139. What does it mean?
140. insns.def
141. trace - trace (set_trace_func) putobject - push object on the stack opt_plus - optimized X + Y leave - return from this scope
142. Slight Detour
143. Ruby -> GS /trace { pop } def /putobject { } def /opt_plus { add } def /leave { } def
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>
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
146. 2013: PrintRuby
147. MASSIVELY Distributed
148. MASSIVELY Distributed
149. Take that Node.js!
150. Slight Detour Massive Detour
151. Actual Slight Detour
152. Get Instructions RubyVM::InstructionSequence#to_a
153. to_a irb> is = RubyVM::InstructionSequence.new '3 + 2' => <RubyVM::InstructionSequence> irb> is.to_a => ["YARVInstructionSequence/SimpleDataFormat", 2, 0, 1, {:arg_size=>0, :local_size=>1, :stack_max=>2}, "<compiled>", "<compiled>", nil, 1, :top, [], 0, [], [[:trace, 1], [:putobject, 3], [:putobject, 2], [:opt_plus, {:mid=>: +, :flag=>256, :orig_argc=>1, :blockptr=>nil}], [:leave]]]
154. Eval Instructions RubyVM::InstructionSequence#eval
155. eval irb> is = RubyVM::InstructionSequence.new '3 + 2' => <RubyVM::InstructionSequence> irb> is.eval => 5
156. Load Instructions? Can’t do it.
157. Or can we?
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
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
163. is = RubyVM::InstructionSequence.new '3 + 5' is2 = RubyVM::InstructionSequence.load is.to_a p is2.eval # => 8 Load Instructions
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
165. When your code is a little too readable.
166. When “meta” isn’t meta enough.
167. Take your app from lolscale to roflscale
168. Works on every Ruby: Guaranteed
169. Works on every Ruby: Guaranteed Seal of Approval
170. He’s lying.
171. Yes, you are.
172. Listen, we’ve been talking, and we think you have a problem
173. Anyway,
174. Cool hacks, but what else?
175. Micro- Optimizations
176. Step 1: Benchmark
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
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
179. Quick PSA: AR::Relation != ARel
180. user.starred.foo.bar.count starred
181. user.starred.foo.bar.count starred foo bar count SQL AST DB
182. Build a tree to build a tree
183. Yo Dawg Moment
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
185. Step 2: Look at the code
186. Select Core def visit_Arel_Nodes_SelectCore o [ "SELECT", ("FROM #{visit(o.source)} " if o.source), ].compact.join ' ' end
187. Select Core def visit_Arel_Nodes_SelectCore o [ "SELECT", ("FROM #{visit(o.source)} " if o.source), ].compact.join ' ' end
188. Step 3: Read the insns
189. “SELECT” irb> puts RubyVM::InstructionSequence.new('"SELECT"').disasm == disasm: <RubyVM::InstructionSequence:<compiled>@<compiled>>========== 0000 trace 1 0002 putstring "SELECT" 0004 leave => nil
190. putstring VALUE rb_str_resurrect(VALUE str) { return str_replace(str_alloc(rb_cString), str); }
191. Easy Proof irb> 10.times { puts "foo".object_id } 70166440589860 70166440589800 70166440589740 70166440589660 70166440589580 70166440589520 70166440589420 70166440589360 70166440589260 70166440589200 => 10
192. "FROM #{visit(o.source)} " irb> puts RubyVM::InstructionSequence.new('"FROM #{visit(o.source)} "').disasm == disasm: <RubyVM::InstructionSequence:<compiled>@<compiled>>========== 0000 trace 1 0002 putobject "FROM " 0004 putself 0005 putself 0006 send :o, 0, nil, 24, <ic:0> 0012 send :source, 0, nil, 0, <ic:1> 0018 send :visit, 1, nil, 8, <ic:2> 0024 tostring 0025 putstring " " 0027 concatstrings 3 0029 leave => nil
193. "FROM #{visit(o.source)} " irb> puts RubyVM::InstructionSequence.new('"FROM #{visit(o.source)} "').disasm == disasm: <RubyVM::InstructionSequence:<compiled>@<compiled>>========== 0000 trace 1 0002 putobject "FROM " 0004 putself 0005 putself 0006 send :o, 0, nil, 24, <ic:0> 0012 send :source, 0, nil, 0, <ic:1> 0018 send :visit, 1, nil, 8, <ic:2> 0024 tostring 0025 putstring " " 0027 concatstrings 3 0029 leave => nil
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) { /* */ }
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.
196. “foo #{x} bar #{y} baz”
197. “foo #{x} bar #{y} baz” putobject
198. “foo #{x} bar #{y} baz” putstring
199. “foo #{x} bar #{y} baz” putstring
200. “foo #{x} bar #{y} baz” concat
201. “foo #{x} bar #{y} baz” Fixed in 2.0
202. “foo #{x} bar #{y} baz” putobject Fixed in 2.0
203. “foo #{x} bar #{y} baz” putobject Fixed in 2.0
204. “foo #{x} bar #{y} baz” putobject Fixed in 2.0
205. “foo #{x} bar #{y} baz” concat Fixed in 2.0
206. Step 4: Update the code
207. Use Constants irb> SELECT = "SELECT" => "SELECT" irb> 5.times { p SELECT.object_id } 70230907127200 70230907127200 70230907127200 70230907127200 70230907127200 => 5
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
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
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
211. 18% reduction in GC invocations. 56 -> 46 invocations
212. 18% reduction in GC time. 963ms => 786ms
213. Please, please,
214. please, please,
215. please, please,
216. optimize for readability first,
217. then find your bottlenecks.
218. DTrace Ruby 2.0
219. Probe Format provider:module:function:name /predicate/ { D Code }
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;
221. Function Probes ruby:::function-entry; ruby:::function-return; ruby:::require-entry; ruby:::require-return; ruby:::load-entry; ruby:::load-return; ruby:::raise;
222. Object Creation ruby:::object-create; ruby:::array-create; ruby:::hash-create; ruby:::string-create;
223. GC Actions ruby:::gc-mark-begin; ruby:::gc-mark-end; ruby:::gc-sweep-begin; ruby:::gc-sweep-end;
224. Ruby Internals ruby:::parse-begin; ruby:::parse-end; ruby:::insn; ruby:::insn-operand;
225. Inspecting Rails Boot Time
226. No incredible revelations
227. No incredible revelations SPOILER
228. Count Insns ruby$target:::insn { @[copyinstr(arg0)] = count(); }
229. Test Script ruby -Ilib:. -rconfig/environment -e 0
230. Output putself 76307 putobject 79394 leave 141904 opt_send_simple 204104 getlocal 249011 trace 421121 $
231. Modify Compile RubyVM::InstructionSequence.compile_option = { trace_instruction: false }
232. Works on every Ruby: Guaranteed
233. Works on every Ruby: Guaranteed Seal of Approval
234. He’s lying again.
235. Output branchunless 56244 setlocal 56857 branchif 60836 dup 65032 send 66905 putself 76301 putobject 79396 leave 141896 opt_send_simple 204095 getlocal 249000 $
236. Is it faster? 100 samples of loading config/environment.rb
237. > mean(times$trace) [1] 1.570746 > mean(times$notrace) [1] 1.545819 Runtime (in s)
238. > sd(times$notrace) [1] 0.05686799 > sd(times$trace) [1] 0.05532489 Standard Dev (in s)
239. Answer: no.
240. Favorite Instruction?
241. Use a timer tick-5000hz { @[insn] = count(); } ruby$target:::insn { insn = copyinstr(arg0); }
242. Samples branchif 518 putself 542 getinstancevariable 550 putobject 667 leave 1355 getconstant 1521 invokesuper 1655 getlocal 2009 opt_send_simple 3008 send 5958 $
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
244. GC Time.
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); }
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); }
247. GC Time mark time (ns) 276526868 sweep time (ns) 74943136 program time (ns) 1464656199
248. GC Time 76% 5% 19% Mark Sweep Rest mark time (ns) 276526868 sweep time (ns) 74943136 program time (ns) 1464656199
249. Compile Time.
250. Parse and Compile ruby$target:::parse-begin { parse = timestamp; } ruby$target:::parse-end { @compile = sum(timestamp - parse); }
251. Compile time compile time (ns) 255934383 program time (ns) 1237971025 79% 21% Compile Rest
252. Searching.
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)); }
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%
256. Linear Fit Call: lm(formula = trunk_require$y ~ trunk_require$x) Coefficients: (Intercept) trunk_require$x 134747.2 174.6
257. Bug #7158
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%
259. Comparison 0 375 750 1125 1500 Program Time (ms) Search Time (ms) trunk Bug #7158
261. Sorted Compare
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
263. Combined!
264. rest 25% find file 30% compile 21% sweep 5% mark 19% mark sweep compile find file rest Combined Graph
265. rest 39% find file 16% compile 21% sweep 5% mark 19% mark sweep compile find file rest After #7158
266. #7158 = ὑὑὑὑ
268. Stay cool!!!
269. Never change!!!
270. Work!
271. Eat!
272. Hack!
273. Try Ruby 2.0!
275. THANK YOU
276. Profile Info https://gist.github.com/3989310 https://gist.github.com/3997732 https://bugs.ruby-lang.org/issues/7158