Fixing Performance and Memory Problems (RubyWine)

Slide 1

Slide 1 text

Fixing performance & Memory problems @fglc2 / dressipi

Slide 2

Slide 2 text

Part 1: The follow events happen in real-time

Slide 3

Slide 3 text

Realtime recommender

Slide 4

Slide 4 text

Realtime recommender Batch Predictions

Slide 5

Slide 5 text

Realtime recommender Batch Predictions Event Stream Recommender Realtime Predictions

Slide 6

Slide 6 text

Realtime recommender Batch Predictions Event Stream Recommender Realtime Predictions Results

Slide 7

Slide 7 text

We deployed to production

Slide 8

Slide 8 text

No content

Slide 9

Slide 9 text

API Combine Serialize Batch Predictions Realtime Predictions

Slide 10

Slide 10 text

No content

Slide 11

Slide 11 text

No content

Slide 12

Slide 12 text

class ScoreMap def serialize to_int_array.pack("l<*") end def to_int_array @scores.flat_map do |key, value| [ key, (value/(scale_factor + 1).to_i] end end def scale_factor @scores.values.max_by {|n| n.abs } .abs / 1000 end end

Slide 13

Slide 13 text

class ScoreMap def serialize to_int_array.pack("l<*") end def to_int_array @scores.flat_map do |key, value| [ key, (value/(scale_factor + 1)).to_i] end end def scale_factor @scores.values.max_by {|n| n.abs }

Slide 14

Slide 14 text

Slide 15

Slide 15 text

def to_int_array @scores.flat_map do |key, value| [ key, (value/(scale_factor + 1)).to_i] end end def scale_factor @scores.values.max_by {|n| n.abs } .abs / 1000 end end

Slide 16

Slide 16 text

Ruby-Prof is a proﬁler • Records behaviour of your code • Produces reports on where your code spends time • Use to analyse problems not detect them

Slide 17

Slide 17 text

No content

Slide 18

Slide 18 text

require 'ruby-prof'

Slide 19

Slide 19 text

require 'ruby-prof' scores = load_example_data

Slide 20

Slide 20 text

require 'ruby-prof' scores = load_example_data result = RubyProf.profile do ScoreMap.new(scores).serialize end

Slide 21

Slide 21 text

require 'ruby-prof' scores = load_example_data result = RubyProf.profile do ScoreMap.new(scores).serialize end printer = RubyProf::GraphHtmlPrinter.new(result) File.open('out.html', 'w') do |file| printer.print(file) end

Slide 22

Slide 22 text

No content

Slide 23

Slide 23 text

No content

Slide 24

Slide 24 text

No content

Slide 25

Slide 25 text

No content

Slide 26

Slide 26 text

No content

Slide 27

Slide 27 text

No content

Slide 28

Slide 28 text

No content

Slide 29

Slide 29 text

def to_int_array @scores.flat_map do |key, value| [ key, (value/(scale_factor + 1)).to_i] end end def scale_factor @scores.values.max_by {|n| n.abs } .abs / 1000 end

Slide 30

Slide 30 text

def to_int_array @scores.flat_map do |key, value| [ key, (value/(scale_factor + 1)).to_i] end end def scale_factor @scale_factor ||= @scores.values.max_by {|n| n.abs } .abs / 1000 end

Slide 31

Slide 31 text

No content

Slide 32

Slide 32 text

Slows down your code

Slide 33

Slide 33 text

Can distort things

Slide 34

Slide 34 text

ruby-prof is exact

Slide 35

Slide 35 text

Sampling proﬁlers

Slide 36

Slide 36 text

Sampling proﬁlers • Sampling proﬁlers monitor (sample) call stack periodically and reports how often each method seen

Slide 37

Slide 37 text

Sampling profilers • Sampling profilers monitor (sample) call stack periodically and reports how often each method seen • Sampling frequency controls accuracy vs overhead tradeoff

Slide 38

Slide 38 text

Stackprof StackProf.run(mode: :cpu, out: 'stackprof.dump') do ScoreMap.new(scores).serialize end

Slide 39

Slide 39 text

Stackprof StackProf.run(mode: :cpu, out: 'stackprof.dump') do ScoreMap.new(scores).serialize end

Slide 40

Slide 40 text

================================== Mode: cpu(1000) Samples: 435 (0.00% miss rate) GC: 2 (0.46%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 433 (99.5%) 433 (99.5%) ScoreMap#scale_factor 2 (0.5%) 2 (0.5%) (garbage collection) 433 (99.5%) 0 (0.0%) ScoreMap#to_int_array 433 (99.5%) 0 (0.0%) ScoreMap#serialize 433 (99.5%) 0 (0.0%) block in 433 (99.5%) 0 (0.0%) 433 (99.5%) 0 (0.0%)

Slide 41

Slide 41 text

Slide 42

Slide 42 text

Overhead

Slide 43

Slide 43 text

Overhead • Code on its own: 6.05 s

Slide 44

Slide 44 text

Overhead • Code on its own: 6.05 s • Rubyprof: ~ 27s

Slide 45

Slide 45 text

Overhead • Code on its own: 6.05 s • Rubyprof: ~ 27s • Stackprof (default settings): 6.09s

Slide 46

Slide 46 text

Part 1 Summary

Slide 47

Slide 47 text

Part 1 Summary • Use monitoring (or angry users) to detect problems

Slide 48

Slide 48 text

Part 1 Summary • Use monitoring (or angry users) to detect problems • Reﬁne with stackprof (if needed)

Slide 49

Slide 49 text

Part 1 Summary • Use monitoring (or angry users) to detect problems • Reﬁne with stackprof (if needed) • Reproduce the problem in a small benchmark

Slide 50

Slide 50 text

Part 1 Summary • Use monitoring (or angry users) to detect problems • Reﬁne with stackprof (if needed) • Reproduce the problem in a small benchmark • Use rubyprof to understand / ﬁx the problem

Slide 51

Slide 51 text

Slide 52

Slide 52 text

Part 2: Memory

Slide 53

Slide 53 text

• Bitmap GC (1.9) • Generational GC (2.1) • Incremental GC (2.2) • Symbol GC (2.2) • Transient Heap (2.6) • Compacting GC ( 2.7 )

Slide 54

Slide 54 text

You still have to worry about memory

Slide 55

Slide 55 text

NoMemoryError: failed to allocate

Slide 56

Slide 56 text

No content

Slide 57

Slide 57 text

0 100 200 300 400

Slide 58

Slide 58 text

Memory leak

Slide 59

Slide 59 text

Where do they come from

Slide 60

Slide 60 text

Where do they come from • Leaks in native code (C extensions)

Slide 61

Slide 61 text

Where do they come from • Leaks in native code (C extensions) • Ruby thinks you are still using it (long lived objects, caches, etc.)

Slide 62

Slide 62 text

Where do they come from • Leaks in native code (C extensions) • Ruby thinks you are still using it (long lived objects, caches, etc.) • Not understanding object lifecycles

Slide 63

Slide 63 text

class LeakingMiddleware def initialize(app) @app = app end def call(env) ... end def cached_thing(id) @things ||= {} @things[id] ||= Thing.find id end end

Slide 64

Slide 64 text

class LeakingMiddleware def initialize(app) @app = app end def call(env) ... end def cached_thing(id) @things ||= {} @things[id] ||= Thing.find id end end

Slide 65

Slide 65 text

Leaks are scary because

Slide 66

Slide 66 text

Leaks are scary because • Manifest as global problem

Slide 67

Slide 67 text

Leaks are scary because • Manifest as global problem • Memory usage is complicated and noisy (caches, threads, lazy load)

Slide 68

Slide 68 text

Leaks are scary because • Manifest as global problem • Memory usage is complicated and noisy (caches, threads, lazy load) • Easily hidden in a dependency (see bundler-leak)

Slide 69

Slide 69 text

Back to the problem

Slide 70

Slide 70 text

At least a year

Slide 71

Slide 71 text

At least a year • Slow or rare leak ~ 2 weeks to exhaust memory at 3M requests / day

Slide 72

Slide 72 text

At least a year • Slow or rare leak ~ 2 weeks to exhaust memory at 3M requests / day • App usually restarted often enough (deploys, autoscaling)

Slide 73

Slide 73 text

At least a year • Slow or rare leak ~ 2 weeks to exhaust memory at 3M requests / day • App usually restarted often enough (deploys, autoscaling) • Failed instances automatically detected as unhealthy and replaced

Slide 74

Slide 74 text

No content

Slide 75

Slide 75 text

But seriously

Slide 76

Slide 76 text

I couldn't reproduce the leak

Slide 77

Slide 77 text

What could be happening?

Slide 78

Slide 78 text

What could be happening? • Not picking the right endpoint

Slide 79

Slide 79 text

What could be happening? • Not picking the right endpoint • Diﬀerent usage patterns

Slide 80

Slide 80 text

What could be happening? • Not picking the right endpoint • Diﬀerent usage patterns • Environment diﬀerences

Slide 81

Slide 81 text

Debugging in production

Slide 82

Slide 82 text

rbtrace

Slide 83

Slide 83 text

rbtrace • Count / trace method calls, GCs

Slide 84

Slide 84 text

rbtrace • Count / trace method calls, GCs • Dump backtraces

Slide 85

Slide 85 text

rbtrace • Count / trace method calls, GCs • Dump backtraces • Execute arbitrary ruby

Slide 86

Slide 86 text

trace_object_allocations

Slide 87

Slide 87 text

trace_object_allocations • Part of Objectspace (in stdlib)

Slide 88

Slide 88 text

trace_object_allocations • Part of Objectspace (in stdlib) • Records details about each memory allocation (when/ where/what)

Slide 89

Slide 89 text

trace_object_allocations • Part of Objectspace (in stdlib) • Records details about each memory allocation (when/ where/what) • Dump to a ﬁle for analysis ( heap dump )

Slide 90

Slide 90 text

Note that this feature introduces a huge performance decrease and huge memory consumption.

Slide 91

Slide 91 text

The plan

Slide 92

Slide 92 text

The plan • Only work on one instance

Slide 93

Slide 93 text

The plan • Only work on one instance • Use rbtrace to dump heap from single rails process

Slide 94

Slide 94 text

The plan • Only work on one instance • Use rbtrace to dump heap from single rails process • Analyse heap dump oﬄine

Slide 95

Slide 95 text

I had to google this!

Slide 96

Slide 96 text

bundle exec rbtrace --pid $PID -e ' Thread.new { require 'objspace' ObjectSpace.trace_object_allocations_start }' Start Tracing

Slide 97

Slide 97 text

bundle exec rbtrace --pid $PID -e ' Thread.new { require 'objspace' ObjectSpace.trace_object_allocations_start }' Start Tracing

Slide 98

Slide 98 text

Dump GC.start io=File.open("/tmp/heap.dump", "w"); ObjectSpace.dump_all(output: io); io.close

Slide 99

Slide 99 text

What's in a heap dump?

Slide 100

Slide 100 text

No content

Slide 101

Slide 101 text

"address": "0x7ff5bbdfc3f8",

Slide 102

Slide 102 text

"address": "0x7ff5bbdfc3f8", "type": "OBJECT",  "class": "0x7ff5ba88b8e8",

Slide 103

Slide 103 text

"address": "0x7ff5bbdfc3f8", "type": "OBJECT",  "class": "0x7ff5ba88b8e8", "file": "...gems/mongoid-7.0.5/lib/mongoid/document.rb",  "line": 335,  "method": "allocate",

Slide 104

Slide 104 text

"address": "0x7ff5bbdfc3f8", "type": "OBJECT",  "class": "0x7ff5ba88b8e8", "file": "...gems/mongoid-7.0.5/lib/mongoid/document.rb",  "line": 335,  "method": "allocate", "generation": 62,

Slide 105

Slide 105 text

"address": "0x7ff5bbdfc3f8", "type": "OBJECT",  "class": "0x7ff5ba88b8e8", "file": "...gems/mongoid-7.0.5/lib/mongoid/document.rb",  "line": 335,  "method": "allocate", "generation": 62, "ivars": 3,  "memsize": 40,

Slide 106

Slide 106 text

Slide 107

Slide 107 text

Slide 108

Slide 108 text

heapy

Slide 109

Slide 109 text

heapy $ heapy read good_heap.dump

Slide 110

Slide 110 text

heapy $ heapy read good_heap.dump Analyzing Heap  ==============

Slide 111

Slide 111 text

heapy $ heapy read good_heap.dump Analyzing Heap  ============== Generation: nil object count: 475742, mem: 0.0 kb

Slide 112

Slide 112 text

Slide 113

Slide 113 text

heapy $ heapy read good_heap.dump Analyzing Heap  ============== Generation: nil object count: 475742, mem: 0.0 kb Generation: 61 object count: 5334, mem: 1782.5 kb  Generation: 62 object count: 918, mem: 1324.8 kb  Generation: 63 object count: 4, mem: 0.3 kb Generation: 2222 object count: 1, mem: 0.0 kb  Generation: 2223 object count: 420, mem: 44.6 kb  Generation: 2224 object count: 635, mem: 42.8 kb

Slide 114

Slide 114 text

Analyzing Heap ============== Generation: nil object count: 498011, mem: 0.0 kb Generation: 61 object count: 834, mem: 82.2 kb Generation: 62 object count: 36, mem: 3.9 kb Generation: 63 object count: 9, mem: 0.8 kb Generation: 64 object count: 3, mem: 0.4 kb Generation: 65 object count: 23, mem: 1.8 kb Generation: 66 object count: 16, mem: 1.4 kb Generation: 67 object count: 12, mem: 1.2 kb ...

Slide 115

Slide 115 text

Slide 116

Slide 116 text

Generation: 218 object count: 11, mem: 1.2 kb Generation: 219 object count: 10, mem: 1.1 kb Generation: 220 object count: 12, mem: 1.2 kb Generation: 221 object count: 12, mem: 1.2 kb Generation: 222 object count: 13, mem: 9.2 kb Generation: 223 object count: 10, mem: 1.0 kb Generation: 224 object count: 12, mem: 1.2 kb Generation: 225 object count: 12, mem: 1.2 kb Generation: 226 object count: 9, mem: 0.9 kb Generation: 227 object count: 11, mem: 1.2 kb ...

Slide 117

Slide 117 text

Generation: 1874 object count: 8, mem: 0.9 kb Generation: 1875 object count: 8, mem: 1.0 kb Generation: 1876 object count: 10, mem: 1.0 kb Generation: 1877 object count: 6, mem: 0.7 kb Generation: 1878 object count: 8, mem: 1.0 kb Generation: 1879 object count: 10, mem: 1.0 kb Generation: 1880 object count: 6, mem: 0.7 kb Generation: 1881 object count: 8, mem: 1.0 kb Generation: 1882 object count: 9, mem: 0.8 kb Generation: 1883 object count: 6, mem: 0.7 kb ...

Slide 118

Slide 118 text

$ heapy read heap.dump 1879

Slide 119

Slide 119 text

$ heapy read heap.dump 1879 allocated by memory (978) (in bytes)  ==============================  858 .../action_view/template.rb:296  120 .../active_support/core_ext/module/remove_method.rb:4

Slide 120

Slide 120 text

$ heapy read heap.dump 1879 allocated by memory (978) (in bytes)  ==============================  858 .../action_view/template.rb:296  120 .../active_support/core_ext/module/remove_method.rb:4 _app_views_mobile_layouts_widgets_html_haml__3857206368_702097383 _app_views_mobile_widgets_outfits_html_haml__3715565700_702097206 _app_views_mobile_layouts_widgets_html_haml__3857206368_702096884

Slide 121

Slide 121 text

Slide 122

Slide 122 text

2 Questions

Slide 123

Slide 123 text

2 Questions • Why is the method name uncollectible?

Slide 124

Slide 124 text

2 Questions • Why is the method name uncollectible? • Why so many of them?

Slide 125

Slide 125 text

Ruby 2.2: Symbols can be garbage collected

Slide 126

Slide 126 text

Ruby 2.2: Symbols can be garbage collected *Terms and conditions may apply Your statutory rights are not aﬀected

Slide 127

Slide 127 text

2 Kinds of Symbols

Slide 128

Slide 128 text

2 Kinds of Symbols • Mortal symbols: created from foo.to_sym

Slide 129

Slide 129 text

2 Kinds of Symbols • Mortal symbols: created from foo.to_sym • Immortal symbols: C-level references (rb_intern)

Slide 130

Slide 130 text

2 Kinds of Symbols • Mortal symbols: created from foo.to_sym • Immortal symbols: C-level references (rb_intern) Deﬁning a method creates an immortal symbol

Slide 131

Slide 131 text

Action View template caching

Slide 132

Slide 132 text

Action View template caching • Each template is compiled to a method with random name

Slide 133

Slide 133 text

Action View template caching • Each template is compiled to a method with random name • Each entry in the view search path is a resolver

Slide 134

Slide 134 text

Action View template caching • Each template is compiled to a method with random name • Each entry in the view search path is a resolver • Resolvers return compiled template from cache or load from disk

Slide 135

Slide 135 text

before_action :set_view_path def set_view_path if mobile_site_requested? prepend_view_path "app/views/mobile" end end

Slide 136

Slide 136 text

before_action :set_view_path def set_view_path if mobile_site_requested? prepend_view_path "app/views/mobile" end end

Slide 137

Slide 137 text

before_action :set_view_path def set_view_path if mobile_site_requested? prepend_view_path "app/views/mobile" end end

Slide 138

Slide 138 text

devise/app/views app/views View Paths

Slide 139

Slide 139 text

devise/app/views app/views View Paths

Slide 140

Slide 140 text

devise/app/views app/views View Paths app/views/mobile

Slide 141

Slide 141 text

devise/app/views app/views View Paths app/views/mobile

Slide 142

Slide 142 text

devise/app/views app/views View Paths

Slide 143

Slide 143 text

devise/app/views app/views View Paths app/views/mobile

Slide 144

Slide 144 text

New (empty) cache on each request!

Slide 145

Slide 145 text

Each request leaks a symbol

Slide 146

Slide 146 text

No content

Slide 147

Slide 147 text

No content

Slide 148

Slide 148 text

Part 2 Summary

Slide 149

Slide 149 text

Part 2 Summary • Don't be afraid of production!

Slide 150

Slide 150 text

Part 2 Summary • Don't be afraid of production! • Understand what/how using memory with heap dumps

Slide 151

Slide 151 text

Part 2 Summary • Don't be afraid of production! • Understand what/how using memory with heap dumps • Pay attention to your objects' lifecycles

Slide 152

Slide 152 text

Thank you! @fglc2 / dressipi

Slide 153

Slide 153 text

Further Reading • https://samsaﬀron.com/archive/2015/03/31/debugging-memory- leaks-in-ruby • https://samsaﬀron.com/archive/2019/10/08/debugging-unmanaged- and-hidden-memory-leaks-in-ruby • https://blog.codeship.com/tracking-object-allocations-in-ruby/ • https://blog.codeship.com/debugging-a-memory-leak-on-heroku/ • https://www.slideshare.net/authorNari/symbol-gc • https://github.com/schneems/derailed_benchmarks • https://www.schneems.com/2019/11/07/why-does-my-apps- memory-usage-grow-asymptotically-over-time/