Fixing Performance and Memory Problems

Fixing Performance and Memory Problems

From rubyconf 2019

81b61875e41eaa58887543635d556fca?s=128

Frederick Cheung

November 19, 2019
Tweet

Transcript

  1. 1.
  2. 9.
  3. 11.
  4. 12.
  5. 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
  6. 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 }
  7. 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
  8. 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
  9. 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
  10. 18.
  11. 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
  12. 23.
  13. 24.
  14. 25.
  15. 26.
  16. 27.
  17. 28.
  18. 29.
  19. 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
  20. 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
  21. 32.
  22. 37.
  23. 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
  24. 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
  25. 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>
  26. 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>
  27. 44.
  28. 47.

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

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

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

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

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

    detect problems • Refine with stackprof (if needed) • Reproduce the problem in a small benchmark
  31. 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
  32. 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!
  33. 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 )
  34. 58.
  35. 63.

    Where do they come from • Leaks in native code

    (C extensions) • Ruby thinks you are still using it (long lived objects, caches, globals)
  36. 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
  37. 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
  38. 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
  39. 69.

    Leaks are scary because • Manifest as global problem •

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

    Leaks are scary because • Manifest as global problem •

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

    At least a year • Slow or rare leak ~

    2 weeks to exhaust memory at 3M requests / day
  42. 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)
  43. 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
  44. 76.
  45. 82.

    What could be happening? • Not picking the right endpoint

    • Different usage patterns • Environment differences
  46. 84.
  47. 87.

    rbtrace • Count / trace method calls, GCs • Dump

    backtraces • Execute arbitrary ruby
  48. 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 )
  49. 90.
  50. 92.

    The plan • Only work on one instance • Use

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

    The plan • Only work on one instance • Use

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

    The plan • Only work on one instance • Use

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

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

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

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

    'objspace' ObjectSpace.trace_object_allocations_start }' Start Tracing
  55. 99.
  56. 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"
 ],
  57. 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
 },
  58. 107.
  59. 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
  60. 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
  61. 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 ...
  62. 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 ...
  63. 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 ...
  64. 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 ...
  65. 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
  66. 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
  67. 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}
  68. 123.

    2 Questions • Why so many of them? • Why

    is the method name uncollectible?
  69. 125.

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

    may apply Your statutory rights are not affected
  70. 128.

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

    • Immortal symbols: C-level references (rb_intern)
  71. 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
  72. 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
  73. 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
  74. 144.
  75. 145.
  76. 148.

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

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

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

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