Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Fixing Performance and Memory Problems (RubyWine)

Fixing Performance and Memory Problems (RubyWine)

Frederick Cheung

April 04, 2020
Tweet

More Decks by Frederick Cheung

Other Decks in Technology

Transcript

  1. 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
  2. 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 }
  3. 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
  4. 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
  5. 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
  6. 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
  7. 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
  8. 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
  9. Sampling profilers • Sampling profilers monitor (sample) call stack periodically

    and reports how often each method seen • Sampling frequency controls accuracy vs overhead tradeoff
  10. ================================== 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>
  11. ================================== 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>
  12. Overhead • Code on its own: 6.05 s • Rubyprof:

    ~ 27s • Stackprof (default settings): 6.09s
  13. Part 1 Summary • Use monitoring (or angry users) to

    detect problems • Refine with stackprof (if needed)
  14. Part 1 Summary • Use monitoring (or angry users) to

    detect problems • Refine with stackprof (if needed) • Reproduce the problem in a small benchmark
  15. 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
  16. 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!
  17. • Bitmap GC (1.9) • Generational GC (2.1) • Incremental

    GC (2.2) • Symbol GC (2.2) • Transient Heap (2.6) • Compacting GC ( 2.7 )
  18. Where do they come from • Leaks in native code

    (C extensions) • Ruby thinks you are still using it (long lived objects, caches, etc.)
  19. 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
  20. class LeakingMiddleware def initialize(app) @app = app end def call(env)

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

    ... end def cached_thing(id) @things ||= {} @things[id] ||= Thing.find id end end
  22. Leaks are scary because • Manifest as global problem •

    Memory usage is complicated and noisy (caches, threads, lazy load)
  23. 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)
  24. At least a year • Slow or rare leak ~

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

    2 weeks to exhaust memory at 3M requests / day • App usually restarted often enough (deploys, autoscaling)
  26. 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
  27. What could be happening? • Not picking the right endpoint

    • Different usage patterns • Environment differences
  28. rbtrace • Count / trace method calls, GCs • Dump

    backtraces • Execute arbitrary ruby
  29. 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 )
  30. The plan • Only work on one instance • Use

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

    rbtrace to dump heap from single rails process • Analyse heap dump offline
  32. bundle exec rbtrace --pid $PID -e ' Thread.new { require

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

    'objspace' ObjectSpace.trace_object_allocations_start }' Start Tracing
  34. "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"
 ],
  35. "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
 },
  36. 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
  37. 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
  38. 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 ...
  39. 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 ...
  40. 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 ...
  41. 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 ...
  42. $ 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
  43. $ 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
  44. $ 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 "flags":{"wb_protected":true, "old":true, "uncollectible":true }
  45. Ruby 2.2: Symbols can be garbage collected *Terms and conditions

    may apply Your statutory rights are not affected
  46. 2 Kinds of Symbols • Mortal symbols: created from foo.to_sym

    • Immortal symbols: C-level references (rb_intern)
  47. 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
  48. Action View template caching • Each template is compiled to

    a method with random name • Each entry in the view search path is a resolver
  49. 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
  50. Part 2 Summary • Don't be afraid of production! •

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

    Understand what/how using memory with heap dumps • Pay attention to your objects' lifecycles
  52. 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/