MRI vs. Father Time - Speaker Deck

Slide 1

Slide 1 text

No content

Slide 2

Slide 2 text

Ruby VM Tooling Profiling Rails

Slide 3

Slide 3 text

Q&A

Slide 4

Slide 4 text

No content

Slide 5

Slide 5 text

No content

Slide 6

Slide 6 text

No content

Slide 7

Slide 7 text

No content

Slide 8

Slide 8 text

…

Slide 9

Slide 9 text

…

Slide 10

Slide 10 text

No content

Slide 11

Slide 11 text

• • • • • • • • •

Slide 12

Slide 12 text

No content

Slide 13

Slide 13 text

No content

Slide 14

Slide 14 text

• • • • • • • • •

Slide 15

Slide 15 text

• • • • • •

Slide 16

Slide 16 text

No content

Slide 17

Slide 17 text

• • • • • • • • •

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

No content

Slide 20

Slide 20 text

Terence Lee @hone02

Slide 21

Slide 21 text

Austin, TX

Slide 22

Slide 22 text

No content

Slide 23

Slide 23 text

No content

Slide 24

Slide 24 text

Tooling

Slide 25

Slide 25 text

Benchmark TracePoint ObjectSpace

Slide 26

Slide 26 text

Benchmark

Slide 27

Slide 27 text

No content

Slide 28

Slide 28 text

do you even fib()? def fib(n) if n < 2 1 else fib(n-1) + fib(n-2) end end

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

$ ruby manual.rb 6.902071125

Slide 31

Slide 31 text

benchmark require 'benchmark' require_relative 'fib' size = 35 Benchmark.bm do |x| x.report { fib(size) } end

Slide 32

Slide 32 text

$ ruby benchmark.rb user system total real 7.120000 0.000000 7.120000 ( 7.372350)

Slide 33

Slide 33 text

$ gem install benchmark- ips

Slide 34

Slide 34 text

benchmark/ips require 'benchmark/ips' require_relative 'fib' size = 35 Benchmark.ips do |x| x.time = 20 x.report { fib(35) } end

Slide 35

Slide 35 text

$ bundle exec ruby ips.rb Calculating ------------------------------------- 1.000 i/100ms ------------------------------------------------- 0.141 (± 0.0%) i/s - 3.000 in 21.216518s

Slide 36

Slide 36 text

Array#reject! regression

Slide 37

Slide 37 text

No content

Slide 38

Slide 38 text

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

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

No content

Slide 43

Slide 43 text

TracePoint

Slide 44

Slide 44 text

Kernel#set_func_trace

Slide 45

Slide 45 text

enable trace set_trace_func proc {|event, file, line, id, binding, klass| printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, klass }

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

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

Slide 49

Slide 49 text

Slide 50

Slide 50 text

Slide 51

Slide 51 text

Slide 52

Slide 52 text

Slide 53

Slide 53 text

Slide 54

Slide 54 text

Slide 55

Slide 55 text

Slide 56

Slide 56 text

events ● c-call ● c-return ● call ● return ● class ● end ● line ● raise

Slide 57

Slide 57 text

TracePoint

Slide 58

Slide 58 text

events ● b_call ● b_return ● thread_begin ● thread_end

Slide 59

Slide 59 text

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

Slide 60

Slide 60 text

Slide 61

Slide 61 text

Slide 62

Slide 62 text

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

Slide 63

Slide 63 text

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

Slide 64

Slide 64 text

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

Slide 65

Slide 65 text

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

Slide 66

Slide 66 text

1 classes used 1 methods used 1 methods dispatched

Slide 67

Slide 67 text

sinatra require 'sinatra' require 'rack/tracepoint' use Rack::Tracepoint::Middleware get "/" do `ruby -v` end run Sinatra::Application

Slide 68

Slide 68 text

43 classes used 155 methods used 548 methods dispatched

Slide 69

Slide 69 text

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

Slide 70

Slide 70 text

361 classes used 1193 methods used 8621 methods dispatched

Slide 71

Slide 71 text

{ "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 } }

Slide 72

Slide 72 text

{ "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, "##settings": 10, "Sinatra::Base#settings": 9, "Rack::Utils::HeaderHash#[]": 9, "##app_file": 8, "Rack::Utils::HeaderHash#[]=": 7, "Rack::Protection::Base#initialize": 6, "Rack::Protection::Base#default_options": 6, "##environment": 4, "##root": 4, "Sinatra::Base#filter!": 4, "Sinatra::Base#invoke": 3 ...

Slide 73

Slide 73 text

ObjectSpace

Slide 74

Slide 74 text

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

Slide 75

Slide 75 text

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

Slide 76

Slide 76 text

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

Slide 77

Slide 77 text

objspace.so

Slide 78

Slide 78 text

allocation tracer

Slide 79

Slide 79 text

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)

Slide 80

Slide 80 text

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)

Slide 81

Slide 81 text

Slide 82

Slide 82 text

Slide 83

Slide 83 text

objectspace.rb:8 bar Foo

Slide 84

Slide 84 text

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

Slide 85

Slide 85 text

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

Slide 86

Slide 86 text

memory_profiler.rb:28 Baz#foo 40 memory_profiler.rb:22 Foo#bar 40

Slide 87

Slide 87 text

$ gem install memory_profiler

Slide 88

Slide 88 text

Zachary Scott

Slide 89

Slide 89 text

San Francisco, CA Zachary Scott

Slide 90

Slide 90 text

No content

Slide 91

Slide 91 text

Zachary Scott

Slide 92

Slide 92 text

Zachary Scott Senior Archaeologist

Slide 93

Slide 93 text

LEGACY CODE

Slide 94

Slide 94 text

No content

Slide 95

Slide 95 text

No content

Slide 96

Slide 96 text

No content

Slide 97

Slide 97 text

No content

Slide 98

Slide 98 text

No content

Slide 99

Slide 99 text

No content

Slide 100

Slide 100 text

Profiling Rails

Slide 101

Slide 101 text

The Rails App Writing Benchmarks Analysis

Slide 102

Slide 102 text

The Rails App

Slide 103

Slide 103 text

The Rails App

Slide 104

Slide 104 text

Please help me come up with a better name ¯\_(ツ)_/¯

Slide 105

Slide 105 text

The Rails App

Slide 106

Slide 106 text

The Rails App

Slide 107

Slide 107 text

The Rails App

Slide 108

Slide 108 text

The Rails App

Slide 109

Slide 109 text

The Rails App

Slide 110

Slide 110 text

The Rails App

Slide 111

Slide 111 text

What’s Available

Slide 112

Slide 112 text

What’s Available

Slide 113

Slide 113 text

What’s Available Constants PATH_TO_HIT: End point to test TEST_COUNT: Number of times to run

Slide 114

Slide 114 text

No content

Slide 115

Slide 115 text

What’s Available

Slide 116

Slide 116 text

What’s Available Task :ips

Slide 117

Slide 117 text

What’s Available Task :ips

Slide 118

Slide 118 text

What’s Available Task :setup

Slide 119

Slide 119 text

What’s Available Task :rails_load

Slide 120

Slide 120 text

● Cut out what you’re not responsible for ○ Webserver, cache, etc ● Close to the real thing as possible ○ avoid mocks and VMs (travis)

Slide 121

Slide 121 text

What’s Available Task :test

Slide 122

Slide 122 text

What’s Available Task :gc

Slide 123

Slide 123 text

What’s Available Task :gc

Slide 124

Slide 124 text

What’s Available Task :gc

Slide 125

Slide 125 text

What’s Available Task :gc

Slide 126

Slide 126 text

What’s Available Task :mem

Slide 127

Slide 127 text

What’s Available Task :ips

Slide 128

Slide 128 text

What’s Available Task :ips

Slide 129

Slide 129 text

What’s Available

Slide 130

Slide 130 text

PATCH INCOMING What’s Available

Slide 131

Slide 131 text

Please ensure PATH and Verb PATCH INCOMING

Slide 132

Slide 132 text

Task :setup PATCH INCOMING

Slide 133

Slide 133 text

Writing Benchmarks

Slide 134

Slide 134 text

DANGER WILL ROBINSON

Slide 135

Slide 135 text

No content

Slide 136

Slide 136 text

Writing Benchmarks

Slide 137

Slide 137 text

No content

Slide 138

Slide 138 text

No content

Slide 139

Slide 139 text

No content

Slide 140

Slide 140 text

No content

Slide 141

Slide 141 text

No content

Slide 142

Slide 142 text

No content

Slide 143

Slide 143 text

Writing Benchmarks

Slide 144

Slide 144 text

Article.all

Slide 145

Slide 145 text

Writing Benchmarks

Slide 146

Slide 146 text

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

Slide 147

Slide 147 text

Benchmarking Templates

Slide 148

Slide 148 text

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

Slide 149

Slide 149 text

Inline the partial

Slide 150

Slide 150 text

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

Slide 151

Slide 151 text

NFI

Slide 152

Slide 152 text

Analysis

Slide 153

Slide 153 text

MICRO vs MACRO

Slide 154

Slide 154 text

Tradeoffs

Slide 155

Slide 155 text

Speed vs. Space Tradeoffs

Slide 156

Slide 156 text

Tradeoffs Speed vs. Space

Slide 157

Slide 157 text

Tradeoffs Speed vs. Space Time vs. Memory

Slide 158

Slide 158 text

What To Test???

Slide 159

Slide 159 text

What To Test??? ● How Fast is it?

Slide 160

Slide 160 text

What To Test??? ● How Fast is it? ● Where is Time spent?

Slide 161

Slide 161 text

Hotspots

Slide 162

Slide 162 text

Hotspots

Slide 163

Slide 163 text

Hotspots ● URL Recognition / Generation ● Model find and instantiation ● Template rendering