Slide 1
Slide 1 text
No content
Slide 2
Slide 2 text
Fixing performance &
Memory problems
@fglc2
/ dressipi
Slide 3
Slide 3 text
Part 1: The follow events
happen in real-time
Slide 4
Slide 4 text
Realtime recommender
Slide 5
Slide 5 text
Realtime recommender
Batch Predictions
Slide 6
Slide 6 text
Realtime recommender
Batch Predictions
Event Stream Recommender Realtime Predictions
Slide 7
Slide 7 text
Realtime recommender
Batch Predictions
Event Stream Recommender Realtime Predictions
Results
Slide 8
Slide 8 text
We deployed to
production
Slide 9
Slide 9 text
No content
Slide 10
Slide 10 text
API
Combine Serialize
Batch Predictions
Realtime Predictions
Slide 11
Slide 11 text
No content
Slide 12
Slide 12 text
No content
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 }
.abs / 1000
end
end
Slide 14
Slide 14 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 15
Slide 15 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
Slide 16
Slide 16 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 17
Slide 17 text
Ruby-Prof is a profiler
• Records behaviour of your code
• Produces reports on where your code spends time
• Use to analyse problems not detect them
Slide 18
Slide 18 text
No content
Slide 19
Slide 19 text
require 'ruby-prof'
Slide 20
Slide 20 text
require 'ruby-prof'
scores = load_example_data
Slide 21
Slide 21 text
require 'ruby-prof'
scores = load_example_data
result = RubyProf.profile do
ScoreMap.new(scores).serialize
end
Slide 22
Slide 22 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 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
No content
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
@scores.values.max_by {|n| n.abs }
.abs / 1000
end
Slide 31
Slide 31 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 32
Slide 32 text
No content
Slide 33
Slide 33 text
Slows down your
code
Slide 34
Slide 34 text
Can distort things
Slide 35
Slide 35 text
Sampling profilers
Slide 36
Slide 36 text
Sampling profilers
• ruby-prof's overhead is because it is exact
Slide 37
Slide 37 text
Sampling profilers
• ruby-prof's overhead is because it is exact
• Sampling profilers are approximate
Slide 38
Slide 38 text
Sampling profilers
• ruby-prof's overhead is because it is exact
• Sampling profilers are approximate
• Sampling profilers monitor (sample) call stack periodically
and reports how often each method seen
Slide 39
Slide 39 text
Sampling profilers
• ruby-prof's overhead is because it is exact
• Sampling profilers are approximate
• Sampling profilers monitor (sample) call stack periodically
and reports how often each method seen
• Changing sampling frequency allows accuracy vs overhead
tradeoff
Slide 40
Slide 40 text
Stackprof
StackProf.run(mode: :cpu, out: 'stackprof.dump') do
ScoreMap.new(scores).serialize
end
Slide 41
Slide 41 text
Stackprof
StackProf.run(mode: :cpu, out: 'stackprof.dump') do
ScoreMap.new(scores).serialize
end
Slide 42
Slide 42 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 43
Slide 43 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 44
Slide 44 text
Overhead
Slide 45
Slide 45 text
Overhead
• Code on its own: 6.05 s
Slide 46
Slide 46 text
Overhead
• Code on its own: 6.05 s
• Rubyprof: ~ 27s
Slide 47
Slide 47 text
Overhead
• Code on its own: 6.05 s
• Rubyprof: ~ 27s
• Stackprof (default settings): 6.09s
Slide 48
Slide 48 text
Part 1 Summary
Slide 49
Slide 49 text
Part 1 Summary
• Use monitoring (or angry users) to detect problems
Slide 50
Slide 50 text
Part 1 Summary
• Use monitoring (or angry users) to detect problems
• Refine with stackprof (if needed)
Slide 51
Slide 51 text
Part 1 Summary
• Use monitoring (or angry users) to detect problems
• Refine with stackprof (if needed)
• Reproduce the problem in a small benchmark
Slide 52
Slide 52 text
Part 1 Summary
• Use monitoring (or angry users) to detect problems
• Refine with stackprof (if needed)
• Reproduce the problem in a small benchmark
• Use rubyprof to understand / fix the problem
Slide 53
Slide 53 text
Part 1 Summary
• Use monitoring (or angry users) to detect problems
• Refine with stackprof (if needed)
• Reproduce the problem in a small benchmark
• Use rubyprof to understand / fix the problem
• Profit!
Slide 54
Slide 54 text
Part 2: Memory
Slide 55
Slide 55 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 56
Slide 56 text
You still have to worry
about memory
Slide 57
Slide 57 text
NoMemoryError: failed to allocate
Slide 58
Slide 58 text
No content
Slide 59
Slide 59 text
0
100
200
300
400
Slide 60
Slide 60 text
Memory leak
Slide 61
Slide 61 text
Where do they come from
Slide 62
Slide 62 text
Where do they come from
• Leaks in native code (C extensions)
Slide 63
Slide 63 text
Where do they come from
• Leaks in native code (C extensions)
• Ruby thinks you are still using it (long lived objects, caches,
globals)
Slide 64
Slide 64 text
Where do they come from
• Leaks in native code (C extensions)
• Ruby thinks you are still using it (long lived objects, caches,
globals)
• Not understanding object lifecycles
Slide 65
Slide 65 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 66
Slide 66 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 67
Slide 67 text
Leaks are scary because
Slide 68
Slide 68 text
Leaks are scary because
• Manifest as global problem
Slide 69
Slide 69 text
Leaks are scary because
• Manifest as global problem
• Memory usage is complicated and noisy (caches, threads,
lazy load)
Slide 70
Slide 70 text
Leaks are scary because
• Manifest as global problem
• Memory usage is complicated and noisy (caches, threads,
lazy load)
• Easily hidden in a dependency
Slide 71
Slide 71 text
Back to the problem
Slide 72
Slide 72 text
At least a year
Slide 73
Slide 73 text
At least a year
• Slow or rare leak ~ 2 weeks to exhaust memory at 3M
requests / day
Slide 74
Slide 74 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 75
Slide 75 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 76
Slide 76 text
No content
Slide 77
Slide 77 text
But seriously
Slide 78
Slide 78 text
I couldn't reproduce
the leak
Slide 79
Slide 79 text
What could be happening?
Slide 80
Slide 80 text
What could be happening?
• Not picking the right endpoint
Slide 81
Slide 81 text
What could be happening?
• Not picking the right endpoint
• Different usage patterns
Slide 82
Slide 82 text
What could be happening?
• Not picking the right endpoint
• Different usage patterns
• Environment differences
Slide 83
Slide 83 text
Debugging in
production
Slide 84
Slide 84 text
rbtrace
Slide 85
Slide 85 text
rbtrace
• Count / trace method calls, GCs
Slide 86
Slide 86 text
rbtrace
• Count / trace method calls, GCs
• Dump backtraces
Slide 87
Slide 87 text
rbtrace
• Count / trace method calls, GCs
• Dump backtraces
• Execute arbitrary ruby
Slide 88
Slide 88 text
trace_object_allocations
• Part of Objectspace (in stdlib)
• Records details about each memory allocation (when/
where/what)
• Dump to a file for analysis ( heap dump )
Slide 89
Slide 89 text
Note that this feature introduces
a huge performance decrease and
huge memory consumption.
Slide 90
Slide 90 text
The plan
Slide 91
Slide 91 text
The plan
• Only work on one instance
Slide 92
Slide 92 text
The plan
• Only work on one instance
• Use rbtrace to dump heap from single rails process
Slide 93
Slide 93 text
The plan
• Only work on one instance
• Use rbtrace to dump heap from single rails process
• Analyse heap dump offline
Slide 94
Slide 94 text
The plan
• Only work on one instance
• Use rbtrace to dump heap from single rails process
• Analyse heap dump offline
• Profit
Slide 95
Slide 95 text
bundle exec rbtrace --pid $PID -e '
Thread.new {
require 'objspace'
ObjectSpace.trace_object_allocations_start
}'
Start Tracing
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
Dump
GC.start
io=File.open("/tmp/heap.dump", "w");
ObjectSpace.dump_all(output: io);
io.close
Slide 98
Slide 98 text
What's in a heap dump?
Slide 99
Slide 99 text
No content
Slide 100
Slide 100 text
"address": "0x7ff5bbdfc3f8",
Slide 101
Slide 101 text
"address": "0x7ff5bbdfc3f8",
"type": "OBJECT",
"class": "0x7ff5ba88b8e8",
Slide 102
Slide 102 text
"address": "0x7ff5bbdfc3f8",
"type": "OBJECT",
"class": "0x7ff5ba88b8e8",
"file": "...gems/mongoid-7.0.5/lib/mongoid/document.rb",
"line": 335,
"method": "allocate",
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",
"generation": 62,
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,
"ivars": 3,
"memsize": 40,
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,
"references": [
"0x7ff5bbe1c4f0"
],
Slide 106
Slide 106 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,
"references": [
"0x7ff5bbe1c4f0"
],
"flags": {
"wb_protected": true
},
Slide 107
Slide 107 text
heapy
Slide 108
Slide 108 text
heapy
$ heapy read good_heap.dump
Slide 109
Slide 109 text
heapy
$ heapy read good_heap.dump
Analyzing Heap
==============
Slide 110
Slide 110 text
heapy
$ heapy read good_heap.dump
Analyzing Heap
==============
Generation: nil object count: 475742, mem: 0.0 kb
Slide 111
Slide 111 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
Slide 112
Slide 112 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 113
Slide 113 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 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
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 116
Slide 116 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 117
Slide 117 text
$ heapy read heap.dump 1879
Slide 118
Slide 118 text
$ heapy read heap.dump 1879
allocated by memory (978) (in bytes)
==============================
858 .../lib/action_view/template.rb:296
120 .../lib/active_support/core_ext/module/remove_method.rb:4
Slide 119
Slide 119 text
$ heapy read heap.dump 1879
allocated by memory (978) (in bytes)
==============================
858 .../lib/action_view/template.rb:296
120 .../lib/active_support/core_ext/module/remove_method.rb:4
_app_views_mobile_layouts_widgets_html_haml__3857206368409431_70209738354
_app_views_mobile_widgets_outfits_html_haml___3715565700258114_70209720618
_app_views_mobile_layouts_widgets_html_haml__3857206368409431_70209688428
Slide 120
Slide 120 text
$ heapy read heap.dump 1879
allocated by memory (978) (in bytes)
==============================
858 .../lib/action_view/template.rb:296
120 .../lib/active_support/core_ext/module/remove_method.rb:4
_app_views_mobile_layouts_widgets_html_haml__3857206368409431_70209738354
_app_views_mobile_widgets_outfits_html_haml___3715565700258114_70209720618
_app_views_mobile_layouts_widgets_html_haml__3857206368409431_70209688428
"flags":{"wb_protected":true, "old":true, "uncollectible":true, "marked":true}
Slide 121
Slide 121 text
2 Questions
Slide 122
Slide 122 text
2 Questions
• Why so many of them?
Slide 123
Slide 123 text
2 Questions
• Why so many of them?
• Why is the method name uncollectible?
Slide 124
Slide 124 text
Ruby 2.2: Symbols can
be garbage collected
Slide 125
Slide 125 text
Ruby 2.2: Symbols can
be garbage collected
*Terms and conditions may apply
Your statutory rights are not affected
Slide 126
Slide 126 text
2 Kinds of Symbols
Slide 127
Slide 127 text
2 Kinds of Symbols
• Mortal symbols: created from foo.to_sym
Slide 128
Slide 128 text
2 Kinds of Symbols
• Mortal symbols: created from foo.to_sym
• Immortal symbols: C-level references (rb_intern)
Slide 129
Slide 129 text
2 Kinds of Symbols
• Mortal symbols: created from foo.to_sym
• Immortal symbols: C-level references (rb_intern)
Defining a method creates an immortal symbol
Slide 130
Slide 130 text
Action View template
caching
Slide 131
Slide 131 text
Action View template
caching
• Each template is compiled to a method with random name
Slide 132
Slide 132 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 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
• Resolvers return compiled template from cache or load from disk
Slide 134
Slide 134 text
before_action :set_view_path
def set_view_path
if mobile_site_requested?
prepend_view_path "app/views/mobile"
end
end
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
devise/app/views
app/views
View Paths
Slide 138
Slide 138 text
devise/app/views
app/views
View Paths
Slide 139
Slide 139 text
devise/app/views
app/views
View Paths
app/views/mobile
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
Slide 142
Slide 142 text
devise/app/views
app/views
View Paths
app/views/mobile
Slide 143
Slide 143 text
New (empty) cache
on each request!
Slide 144
Slide 144 text
No content
Slide 145
Slide 145 text
No content
Slide 146
Slide 146 text
Part 2 Summary
Slide 147
Slide 147 text
Part 2 Summary
• Don't be afraid of production!
Slide 148
Slide 148 text
Part 2 Summary
• Don't be afraid of production!
• Understand what/how using memory with heap dumps
Slide 149
Slide 149 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 150
Slide 150 text
Thank you!
@fglc2
/ dressipi
Slide 151
Slide 151 text
Further Reading
• https://samsaffron.com/archive/2015/03/31/debugging-memory-
leaks-in-ruby
• https://samsaffron.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/