MRI vs. Father Time

Matz Ruby Implementation has grown into a fast and effective option for building dynamic applications. Thanks to the advancements such as YARV virtual machine and Incremental GC introduced in Ruby 2.2.

In this talk we will cover the Past, Present and Future of the MRI interpreter. We'll see how it performs under various conditions, such as static content generation and web services.

With the help of new and improved MRI tooling, you'll get to see the path to profiling your applications and enlightenment.

Join the author of MRI’s new Virtual Machine and Garbage Collector Koichi Sasada along with Terence Lee and Zachary Scott. As they dig through the internals of Matz Ruby Implementation.

Transcript

2. Ruby VM Tooling Profiling Rails
3. Q&A
8. …
9. …
11. • • • • • • • • •
14. • • • • • • • • •
15. • • • • • •
17. • • • • • • • • •
18. MRI Books • RHG: Ruby Hacking Guide https://ruby- hacking-guide.github.io/ • Explain about MRI 1.7 (too old) line by line • Originally written by Minero Aoki, in Japanese • Translated from Japanese to English • Ruby Under a Microscope http://patshaughnessy.net/ruby- under-a-microscope • Explain about MRI 2.0 from high-level • Written by Pat Shaughnessy, in English • Recently translated from English to Japanese
20. Terence Lee @hone02
21. Austin, TX
24. Tooling
25. Benchmark TracePoint ObjectSpace
26. Benchmark
28. do you even fib()? def fib(n) if n < 2 1 else fib(n-1) + fib(n-2) end end
29. manual require_relative 'fib' def benchmark beginning_time = Time.now yield end_time = Time.now end_time - beginning_time end size = 35 time = benchmark do fib(size) end puts time
30. $ ruby manual.rb 6.902071125
31. benchmark require 'benchmark' require_relative 'fib' size = 35 Benchmark.bm do |x| x.report { fib(size) } end
32. $ ruby benchmark.rb user system total real 7.120000 0.000000 7.120000 ( 7.372350)
33. $ gem install benchmark- ips
34. benchmark/ips require 'benchmark/ips' require_relative 'fib' size = 35 Benchmark.ips do |x| x.time = 20 x.report { fib(35) } end
35. $ bundle exec ruby ips.rb Calculating ------------------------------------- 1.000 i/100ms ------------------------------------------------- 0.141 (± 0.0%) i/s - 3.000 in 21.216518s
36. Array#reject! regression
38. Measure Twice Cut Once require 'benchmark/ips' Benchmark.ips do |x| 20.times do |i| a = [] i.times { |z| a = [nil]*z*10000 } x.report("Array#reject! * #{i}") { a.reject! { true } } end end
39. Ruby 2.2 Array#reject! * 0 8.236M (± 6.4%) i/s - 40.928M Array#reject! * 1 8.255M (± 5.9%) i/s - 41.049M Array#reject! * 2 8.298M (± 5.5%) i/s - 41.297M Array#reject! * 3 8.291M (± 5.7%) i/s - 41.243M Array#reject! * 4 8.244M (± 7.0%) i/s - 40.901M Array#reject! * 5 8.148M (± 8.0%) i/s - 40.375M Array#reject! * 6 8.247M (± 6.6%) i/s - 40.939M Array#reject! * 7 8.309M (± 5.3%) i/s - 41.319M Array#reject! * 8 8.313M (± 5.1%) i/s - 41.369M Array#reject! * 9 8.332M (± 4.0%) i/s - 41.522M Array#reject! * 10 8.331M (± 4.0%) i/s - 41.491M Array#reject! * 11 8.281M (± 5.6%) i/s - 41.106M Array#reject! * 12 8.162M (± 8.2%) i/s - 39.586M Array#reject! * 13 1.006M (±17.3%) i/s - 743.452k Array#reject! * 14 1.007M (±17.0%) i/s - 743.165k Array#reject! * 15 1.007M (±17.0%) i/s - 746.140k Array#reject! * 16 1.006M (±17.2%) i/s - 747.039k Array#reject! * 17 1.007M (±17.2%) i/s - 752.532k
40. Ruby 2.2 Array#reject! * 0 8.236M (± 6.4%) i/s - 40.928M Array#reject! * 1 8.255M (± 5.9%) i/s - 41.049M Array#reject! * 2 8.298M (± 5.5%) i/s - 41.297M Array#reject! * 3 8.291M (± 5.7%) i/s - 41.243M Array#reject! * 4 8.244M (± 7.0%) i/s - 40.901M Array#reject! * 5 8.148M (± 8.0%) i/s - 40.375M Array#reject! * 6 8.247M (± 6.6%) i/s - 40.939M Array#reject! * 7 8.309M (± 5.3%) i/s - 41.319M Array#reject! * 8 8.313M (± 5.1%) i/s - 41.369M Array#reject! * 9 8.332M (± 4.0%) i/s - 41.522M Array#reject! * 10 8.331M (± 4.0%) i/s - 41.491M Array#reject! * 11 8.281M (± 5.6%) i/s - 41.106M Array#reject! * 12 8.162M (± 8.2%) i/s - 39.586M Array#reject! * 13 1.006M (±17.3%) i/s - 743.452k Array#reject! * 14 1.007M (±17.0%) i/s - 743.165k Array#reject! * 15 1.007M (±17.0%) i/s - 746.140k Array#reject! * 16 1.006M (±17.2%) i/s - 747.039k Array#reject! * 17 1.007M (±17.2%) i/s - 752.532k
41. ruby-head Array#reject! * 0 7.285M (± 5.8%) i/s - 36.227M Array#reject! * 1 7.294M (± 6.5%) i/s - 36.274M Array#reject! * 2 7.378M (± 4.1%) i/s - 36.831M Array#reject! * 3 7.260M (± 7.8%) i/s - 35.974M Array#reject! * 4 7.385M (± 4.3%) i/s - 36.849M Array#reject! * 5 7.376M (± 5.5%) i/s - 36.735M Array#reject! * 6 7.145M (±10.2%) i/s - 35.136M Array#reject! * 7 6.974M (± 9.6%) i/s - 34.385M Array#reject! * 8 7.279M (± 5.7%) i/s - 36.259M Array#reject! * 9 7.333M (± 5.3%) i/s - 36.532M Array#reject! * 10 7.345M (± 5.5%) i/s - 36.554M Array#reject! * 11 7.328M (± 5.3%) i/s - 36.481M Array#reject! * 12 7.325M (± 3.2%) i/s - 36.579M Array#reject! * 13 7.319M (± 4.1%) i/s - 36.522M Array#reject! * 14 7.335M (± 5.5%) i/s - 36.527M Array#reject! * 15 7.338M (± 6.0%) i/s - 36.480M Array#reject! * 16 7.405M (± 5.2%) i/s - 36.901M Array#reject! * 17 7.151M (± 4.8%) i/s - 35.624M
43. TracePoint
44. Kernel#set_func_trace
45. enable trace set_trace_func proc {|event, file, line, id, binding, klass| printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, klass }
46. code to trace set_trace_func proc {|event, file, line, id, binding, klass| printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, klass } class Foo def bar "baz" end end Foo.new.bar
47. disable trace set_trace_func proc {|event, file, line, id, binding, klass| printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, klass } class Foo def bar "baz" end end Foo.new.bar set_trace_func(nil) Foo.new
48. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
49. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
50. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
51. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
52. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
53. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
54. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
55. c-return trace.rb:1 set_trace_func Kernel line trace.rb:5 c-call trace.rb:5 inherited Class c-return trace.rb:5 inherited Class class trace.rb:5 line trace.rb:6 c-call trace.rb:6 method_added Module c-return trace.rb:6 method_added Module end trace.rb:9 line trace.rb:11 c-call trace.rb:11 new Class c-call trace.rb:11 initialize BasicObject c-return trace.rb:11 initialize BasicObject c-return trace.rb:11 new Class call trace.rb:6 bar Foo line trace.rb:7 bar Foo return trace.rb:8 bar Foo line trace.rb:13 c-call trace.rb:13 set_trace_func Kernel
56. events • c-call • c-return • call • return • class • end • line • raise
57. TracePoint
58. events • b_call • b_return • thread_begin • thread_end
59. tracepoint = TracePoint.new do |tp| printf "%8s %s:%-2d %10s %8s\n", tp.event, tp.path, tp.lineno, tp.method_id, tp.defined_class end tracepoint.enable do class Foo def bar "baz" end end Foo.new.bar end Foo.new
60. tracepoint = TracePoint.new do |tp| printf "%8s %s:%-2d %10s %8s\n", tp.event, tp.path, tp.lineno, tp.method_id, tp.defined_class end tracepoint.enable do class Foo def bar "baz" end end Foo.new.bar end Foo.new
61. tracepoint = TracePoint.new do |tp| printf "%8s %s:%-2d %10s %8s\n", tp.event, tp.path, tp.lineno, tp.method_id, tp.defined_class end tracepoint.enable do class Foo def bar "baz" end end Foo.new.bar end Foo.new
62. b_call tracepoint.rb:5 line tracepoint.rb:6 c_call tracepoint.rb:6 inherited Class c_return tracepoint.rb:6 inherited Class class tracepoint.rb:6 line tracepoint.rb:7 c_call tracepoint.rb:7 method_added Module c_return tracepoint.rb:7 method_added Module end tracepoint.rb:10 line tracepoint.rb:12 c_call tracepoint.rb:12 new Class c_call tracepoint.rb:12 initialize BasicObject c_return tracepoint.rb:12 initialize BasicObject c_return tracepoint.rb:12 new Class call tracepoint.rb:7 bar Foo line tracepoint.rb:8 bar Foo return tracepoint.rb:9 bar Foo b_return tracepoint.rb:13
63. TracePoint Middleware def call(env) stats = {} response = nil trace = TracePoint.new(:call) do |tp| stats[tp.defined_class] ||= {} stats[tp.defined_class][tp.method_id] ||= 0 stats[tp.defined_class][tp.method_id] += 1 end trace.enable { response = @app.call(env) } ... end * https://gist.github.com/mattetti/5097206
64. TracePoint Middleware def call(env) ... puts env['PATH_INFO'] puts "#{stats.keys.size} classes used" puts "#{stats.map{|k,v| v.keys}.flatten.size} methods used" puts "#{stats.map{|k,v| v.values}.flatten.inject(0) {|sum, num| sum + num }} methods dispatched" File.open("tmp/#{env['PATH_INFO'].gsub('/', '_')}_req_stats. json", "w"){|f| f << stats.to_json } puts "" response end * https://gist.github.com/mattetti/5097206
65. rack require 'rack/tracepoint' class RubyVersion def self.version `ruby -v` end end use Rack::TracePoint::Middleware run Proc.new {|env| [200, {"Content-Type" => "text/plain"}, [RubyVersion.version] ] }
66. 1 classes used 1 methods used 1 methods dispatched
67. sinatra require 'sinatra' require 'rack/tracepoint' use Rack::Tracepoint::Middleware get "/" do `ruby -v` end run Sinatra::Application
68. 43 classes used 155 methods used 548 methods dispatched
69. rails # app/controllers/welcome_controller.rb class WelcomeController < ApplicationController def index @ruby_version = `ruby -v` end end # app/views/welcome/index.html.erb <%= @ruby_version %>
70. 361 classes used 1193 methods used 8621 methods dispatched
71. { "Sinatra::Base": { "initialize": 1, "call": 1, "call!": 1, "indifferent_params": 1, "indifferent_hash": 1, "settings": 9, "force_encoding": 1, "invoke": 3, "dispatch!": 1, "filter!": 4, "route!": 1, "process_route": 1, "route_eval": 1, "error_block!": 1 } }
72. { "ERB::Compiler::Buffer#push": 133, "ERB::Compiler#add_put_cmd": 66, "ERB::Compiler#content_dump": 66, "ERB::Compiler#add_insert_cmd": 34, "Rack::Builder#use": 13, "#<Class:Sinatra::Base>#settings": 10, "Sinatra::Base#settings": 9, "Rack::Utils::HeaderHash#[]": 9, "#<Class:Sinatra::Application>#app_file": 8, "Rack::Utils::HeaderHash#[]=": 7, "Rack::Protection::Base#initialize": 6, "Rack::Protection::Base#default_options": 6, "#<Class:Sinatra::Base>#environment": 4, "#<Class:Sinatra::Base>#root": 4, "Sinatra::Base#filter!": 4, "Sinatra::Base#invoke": 3 ...
73. ObjectSpace
74. ObjectSpace.count_objects { "TOTAL": 30161, "FREE": 677, "T_OBJECT": 70, "T_CLASS": 616, "T_MODULE": 37, "T_FLOAT": 7, "T_STRING": 10950, "T_REGEXP": 77, "T_ARRAY": 1629, "T_HASH": 63, "T_STRUCT": 9, "T_BIGNUM": 2, "T_FILE": 29, "T_DATA": 983, "T_MATCH": 26, ... }
75. ObjectSpace#each_object require 'json' types_count = Hash.new(0) ObjectSpace.each_object do |o| types_count[o.class] += 1 end puts types_count.to_a.sort {|a, b| b[1] <=> a[1] }.to_h.to_json
76. { "String": 8199, "RubyVM::InstructionSequence": 750, "Array": 511, "Class": 288, "Encoding": 100, "Regexp": 77, "Hash": 44, "Module": 37, "MatchData": 20, "File": 18, "Gem::Requirement": 15, "Gem::Version": 15, "Gem::StubSpecification": 11, "Proc": 10, "Range": 9, "Gem::StubSpecification::StubLine": 8, "Float": 7
77. objspace.so
78. allocation tracer
79. Object Introspection require 'objspace' os = ObjectSpace o = nil os.trace_object_allocations do class Foo def bar "baz" end end o = Foo.new.bar end printf "%s:%-2d %10s %8s\n", os.allocation_sourcefile(o), os. allocation_sourceline(o), os.allocation_method_id(o), os. allocation_class_path(o)
80. require 'objspace' os = ObjectSpace o = nil os.trace_object_allocations do class Foo def bar "baz" end end o = Foo.new.bar end printf "%s:%-2d %10s %8s\n", os.allocation_sourcefile(o), os. allocation_sourceline(o), os.allocation_method_id(o), os. allocation_class_path(o)
81. require 'objspace' os = ObjectSpace o = nil os.trace_object_allocations do class Foo def bar "baz" end end o = Foo.new.bar end printf "%s:%-2d %10s %8s\n", os.allocation_sourcefile(o), os. allocation_sourceline(o), os.allocation_method_id(o), os. allocation_class_path(o)
82. require 'objspace' os = ObjectSpace o = nil os.trace_object_allocations do class Foo def bar "baz" end end o = Foo.new.bar end printf "%s:%-2d %10s %8s\n", os.allocation_sourcefile(o), os. allocation_sourceline(o), os.allocation_method_id(o), os. allocation_class_path(o)
83. objectspace.rb:8 bar Foo
84. Object Size Counting require 'objspace' Metadata = Struct.new(:class, :sourcefile, :sourceline, : class_path, :method_id, :memsize) objects = [] result = {} def walk_objects(result) ObjectSpace.each_object do |o| result[o.object_id] = Metadata.new( ObjectSpace.allocation_class_path(o), ObjectSpace.allocation_sourcefile(o), ObjectSpace.allocation_sourceline(o), ObjectSpace.allocation_class_path(o), ObjectSpace.allocation_method_id(o), ObjectSpace.memsize_of(o) ) end end
85. Object Size Counting ObjectSpace.trace_object_allocations do a = Foo.new.bar b = Baz.new.foo walk_objects(result) end result.to_a.sort {|a,b| b[1].memsize <=> a[1].memsize }. to_h.each do |object_id, s| next if s.class_path.nil? printf "%s:%-2d %5s#%s %d\n", s.sourcefile, s.sourceline, s. class_path, s.method_id, s.memsize end
86. memory_profiler.rb:28 Baz#foo 40 memory_profiler.rb:22 Foo#bar 40
87. $ gem install memory_profiler
88. Zachary Scott
89. San Francisco, CA Zachary Scott
91. Zachary Scott
92. Zachary Scott Senior Archaeologist
93. LEGACY CODE
100. Profiling Rails
101. The Rails App Writing Benchmarks Analysis
102. The Rails App
103. The Rails App
104. Please help me come up with a better name ¯\_(ツ)_/¯
105. The Rails App
106. The Rails App
107. The Rails App
108. The Rails App
109. The Rails App
110. The Rails App
111. What’s Available
112. What’s Available
113. What’s Available Constants PATH_TO_HIT: End point to test TEST_COUNT: Number of times to run
115. What’s Available
116. What’s Available Task :ips
117. What’s Available Task :ips
118. What’s Available Task :setup
119. What’s Available Task :rails_load
120. • Cut out what you’re not responsible for ◦ Webserver, cache, etc • Close to the real thing as possible ◦ avoid mocks and VMs (travis)
121. What’s Available Task :test
122. What’s Available Task :gc
123. What’s Available Task :gc
124. What’s Available Task :gc
125. What’s Available Task :gc
126. What’s Available Task :mem
127. What’s Available Task :ips
128. What’s Available Task :ips
129. What’s Available
130. PATCH INCOMING What’s Available
131. Please ensure PATH and Verb PATCH INCOMING
132. Task :setup PATCH INCOMING
133. Writing Benchmarks
134. DANGER WILL ROBINSON
136. Writing Benchmarks
143. Writing Benchmarks
144. Article.all
145. Writing Benchmarks
146. Article.all $ be rake perf:article_all Calculating ------------------------------------- Article#all lazy 2.000 i/100ms Article#all eager 2.000 i/100ms ------------------------------------------------- Article#all lazy 24.136 (± 8.3%) i/s - 120.000 Article#all eager 24.029 (± 8.3%) i/s - 120.000
147. Benchmarking Templates
148. Benchmarking Templates "comments/_comment" x 10202 app/views/comments/_comment.html.erb:1 x 10000 actionview-4.2.0/lib/action_view/template/resolver.rb:328 x 100 actionview-4.2.0/lib/action_view/template/resolver.rb:18 x 100 actionview-4.2.0/lib/action_view/template.rb:296 x 2
149. Inline the partial
150. Benchmarking Templates $ be rake perf:partial_bench Calculating ------------------------------------- With partial rendering 2.000 i/100ms With inlined partial 2.000 i/100ms ------------------------------------------------- With partial rendering 22.232 (±13.5%) i/s - 110.000 With inlined partial 20.962 (±14.3%) i/s - 104.000
151. NFI
152. Analysis
153. MICRO vs MACRO
154. Tradeoffs
155. Speed vs. Space Tradeoffs
156. Tradeoffs Speed vs. Space
157. Tradeoffs Speed vs. Space Time vs. Memory
158. What To Test???
159. What To Test??? • How Fast is it?
160. What To Test??? • How Fast is it? • Where is Time spent?
161. Hotspots
162. Hotspots
163. Hotspots • URL Recognition / Generation • Model find and instantiation • Template rendering
164. Compare ALL THE THINGS • Commits • Patches • Releases Analysis
165. Compare
166. Further
167. railsperf.evilmartians.io
168. github.com/kirs/rails-perf
169. rubybench.org
170. rubybench.org
171. github.com/ruby-bench/ruby-bench-web
173. •
174. • • •
175. Thank you! Koichi Sasada Terence Lee Zachary Scott