Fixing Performance and Memory Problems

Transcript

1. 1.

   None
2. 2.

   Fixing performance & Memory problems @fglc2 / dressipi

3. 3.

   Part 1: The follow events happen in real-time

4. 4.

   Realtime recommender

5. 5.

   Realtime recommender Batch Predictions

6. 6.

   Realtime recommender Batch Predictions Event Stream Recommender Realtime Predictions

7. 7.

   Realtime recommender Batch Predictions Event Stream Recommender Realtime Predictions Results

8. 8.

   We deployed to production

9. 9.

   None
10. 10.

    API Combine Serialize Batch Predictions Realtime Predictions

11. 11.

    None
12. 12.

    None
13. 13.

    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
14. 14.

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

    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
16. 16.

    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
17. 17.

    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
18. 18.

    None
19. 19.

    require 'ruby-prof'

20. 20.

    require 'ruby-prof' scores = load_example_data

21. 21.

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

    end
22. 22.

    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
23. 23.

    None
24. 24.

    None
25. 25.

    None
26. 26.

    None
27. 27.

    None
28. 28.

    None
29. 29.

    None
30. 30.

    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
31. 31.

    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
32. 32.

    None
33. 33.

    Slows down your code

34. 34.

    Can distort things

35. 35.

    Sampling profilers

36. 36.

    Sampling profilers • ruby-prof's overhead is because it is exact

37. 37.

    Sampling profilers • ruby-prof's overhead is because it is exact

    • Sampling profilers are approximate
38. 38.

    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
39. 39.

    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
40. 40.

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

41. 41.

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

42. 42.

    ================================== 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 <main> 433 (99.5%) 0 (0.0%) <main> 433 (99.5%) 0 (0.0%) <main>
43. 43.

    ================================== 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 <main> 433 (99.5%) 0 (0.0%) <main> 433 (99.5%) 0 (0.0%) <main>
44. 44.

    Overhead

45. 45.

    Overhead • Code on its own: 6.05 s

46. 46.

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

    ~ 27s
47. 47.

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

    ~ 27s • Stackprof (default settings): 6.09s
48. 48.

    Part 1 Summary

49. 49.

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

    detect problems
50. 50.

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

    detect problems • Refine with stackprof (if needed)
51. 51.

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

    detect problems • Refine with stackprof (if needed) • Reproduce the problem in a small benchmark
52. 52.

    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
53. 53.

    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!
54. 54.

    Part 2: Memory

55. 55.

    • Bitmap GC (1.9) • Generational GC (2.1) • Incremental

    GC (2.2) • Symbol GC (2.2) • Transient Heap (2.6) • Compacting GC ( 2.7 )
56. 56.

    You still have to worry about memory

57. 57.

    NoMemoryError: failed to allocate

58. 58.

    None
59. 59.

    0 100 200 300 400

60. 60.

    Memory leak

61. 61.

    Where do they come from

62. 62.

    Where do they come from • Leaks in native code

    (C extensions)
63. 63.

    Where do they come from • Leaks in native code

    (C extensions) • Ruby thinks you are still using it (long lived objects, caches, globals)
64. 64.

    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
65. 65.

    class LeakingMiddleware def initialize(app) @app = app end def call(env)

    ... end def cached_thing(id) @things ||= {} @things[id] ||= Thing.find id end end
66. 66.

    class LeakingMiddleware def initialize(app) @app = app end def call(env)

    ... end def cached_thing(id) @things ||= {} @things[id] ||= Thing.find id end end
67. 67.

    Leaks are scary because

68. 68.

    Leaks are scary because • Manifest as global problem

69. 69.

    Leaks are scary because • Manifest as global problem •

    Memory usage is complicated and noisy (caches, threads, lazy load)
70. 70.

    Leaks are scary because • Manifest as global problem •

    Memory usage is complicated and noisy (caches, threads, lazy load) • Easily hidden in a dependency
71. 71.

    Back to the problem

72. 72.

    At least a year

73. 73.

    At least a year • Slow or rare leak ~

    2 weeks to exhaust memory at 3M requests / day
74. 74.

    At least a year • Slow or rare leak ~

    2 weeks to exhaust memory at 3M requests / day • App usually restarted often enough (deploys, autoscaling)
75. 75.

    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
76. 76.

    None
77. 77.

    But seriously

78. 78.

    I couldn't reproduce the leak

79. 79.

    What could be happening?

80. 80.

    What could be happening? • Not picking the right endpoint

81. 81.

    What could be happening? • Not picking the right endpoint

    • Different usage patterns
82. 82.

    What could be happening? • Not picking the right endpoint

    • Different usage patterns • Environment differences
83. 83.

    Debugging in production

84. 84.

    rbtrace

85. 85.

    rbtrace • Count / trace method calls, GCs

86. 86.

    rbtrace • Count / trace method calls, GCs • Dump

    backtraces
87. 87.

    rbtrace • Count / trace method calls, GCs • Dump

    backtraces • Execute arbitrary ruby
88. 88.

    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 )
89. 89.

    Note that this feature introduces a huge performance decrease and

    huge memory consumption.
90. 90.

    The plan

91. 91.

    The plan • Only work on one instance

92. 92.

    The plan • Only work on one instance • Use

    rbtrace to dump heap from single rails process
93. 93.

    The plan • Only work on one instance • Use

    rbtrace to dump heap from single rails process • Analyse heap dump offline
94. 94.

    The plan • Only work on one instance • Use

    rbtrace to dump heap from single rails process • Analyse heap dump offline • Profit
95. 95.

    bundle exec rbtrace --pid $PID -e ' Thread.new { require

    'objspace' ObjectSpace.trace_object_allocations_start }' Start Tracing
96. 96.

    bundle exec rbtrace --pid $PID -e ' Thread.new { require

    'objspace' ObjectSpace.trace_object_allocations_start }' Start Tracing
97. 97.

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

98. 98.

    What's in a heap dump?

99. 99.

    None
100. 100.

     "address": "0x7ff5bbdfc3f8",

101. 101.

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

102. 102.

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


     "method": "allocate",
103. 103.

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


     "method": "allocate", "generation": 62,
104. 104.

     "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,
105. 105.

     "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"
 ],
106. 106.

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

     heapy

108. 108.

     heapy $ heapy read good_heap.dump

109. 109.

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

110. 110.

     heapy $ heapy read good_heap.dump Analyzing Heap
 ============== Generation: nil

     object count: 475742, mem: 0.0 kb
111. 111.

     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
112. 112.

     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
113. 113.

     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 ...
114. 114.

     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 ...
115. 115.

     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 ...
116. 116.

     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 ...
117. 117.

     $ heapy read heap.dump 1879

118. 118.

     $ 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
119. 119.

     $ 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
120. 120.

     $ 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}
121. 121.

     2 Questions

122. 122.

     2 Questions • Why so many of them?

123. 123.

     2 Questions • Why so many of them? • Why

     is the method name uncollectible?
124. 124.

     Ruby 2.2: Symbols can be garbage collected

125. 125.

     Ruby 2.2: Symbols can be garbage collected *Terms and conditions

     may apply Your statutory rights are not affected
126. 126.

     2 Kinds of Symbols

127. 127.

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

128. 128.

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

     • Immortal symbols: C-level references (rb_intern)
129. 129.

     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
130. 130.

     Action View template caching

131. 131.

     Action View template caching • Each template is compiled to

     a method with random name
132. 132.

     Action View template caching • Each template is compiled to

     a method with random name • Each entry in the view search path is a resolver
133. 133.

     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
134. 134.

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

135. 135.

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

136. 136.

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

137. 137.

     devise/app/views app/views View Paths

138. 138.

     devise/app/views app/views View Paths

139. 139.

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

140. 140.

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

141. 141.

     devise/app/views app/views View Paths

142. 142.

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

143. 143.

     New (empty) cache on each request!

144. 144.

     None
145. 145.

     None
146. 146.

     Part 2 Summary

147. 147.

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

148. 148.

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

     Understand what/how using memory with heap dumps
149. 149.

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

     Understand what/how using memory with heap dumps • Pay attention to your objects' lifecycles
150. 150.

     Thank you! @fglc2 / dressipi

151. 151.

     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/