A Tool Belt of a Seasond Bug Hunter

Let me take you on a journey. This true story begins with a performance issue in a Ruby on Rails application, and ends deep inside internals of MRI, surrounded by barren landscape of C’s curly braces. Using tools I knew before, learning new utilities, failing to get a conclusive answer, and learning from all that, marked my passage from a software developer to a seasoned bug hunter. This talk will spare you the frustration of such a trip, and give you the raw insight.

Transcript

1. A Tool Belt of a Seasoned Bug Hunter Damir Zekić
3. (["foo")
4. Baaaad bugs Not so bad bugs
5. Silent bugs Loud bugs
6. 2016: a debugging odyssey
8. Chapter 1: Reproduce A Tool Belt of a Seasoned Bug Hunter
 Damir Zekić • @sidonath
9. 10 RUN TESTS 20 MODIFY CODE 30 GOTO 10
10. Chapter 1: Reproduce SUCCESS
11. Chapter 2: What introduced it? A Tool Belt of a Seasoned Bug Hunter
 Damir Zekić • @sidonath
12. $ git bisect
13. 13 37 c0 ff ee c0 de a0 bug is present here "bad" no bug 7 commits ago "good"
14. 13 37 c0 ff ee c0 de a0 bug is present here "bad" no bug 7 commits ago "good"
15. 13 37 c0 ff ee c0 de a0 bug is present here "bad" no bug 7 commits ago "good"
16. 13 37 c0 ff ee c0 de a0 bug is present here "bad" no bug 7 commits ago "good"
17. 13 37 c0 ff ee c0 de a0 bug is present here "bad" no bug 7 commits ago "good"
18. 13 37 c0 ff ee c0 de a0 bug is present here "bad" no bug 7 commits ago "good"
19. 13 37 c0 ff ee c0 de a0 bug is present here "bad" no bug 7 commits ago "good"
20. 13 37 c0 ff ee c0 de a0 cli-ff-hanger
21. But… which commit was "good"?!
22. 13 37 c0 ff ee c0 de a0 … a long time ago
23. ☕
24. "
25. Install gems
26. "
27. Reset the database
28. "
29. Missing dependency
30. Every commit must be stable
31. ••••••
33. Monolith: Business Action Framework
34. Chapter 2: What introduced it? UNSURE
35. Chapter 3: Is it a memory leak? A Tool Belt of a Seasoned Bug Hunter
 Damir Zekić • @sidonath
36. Time Memory
37. Time Memory No memory leak
38. Time Memory
39. Time Memory Memory leak
40. Problem: Ruby is very slow to release memory back to OS
41. Time Memory
42. Time Memory Memory bloat
43. What is actually in memory?
44. require 'objspace' ObjectSpace.trace_object_allocations_start class Foo def bar puts "Hello, world!" end end
 foo = Foo.new foo.bar File.open("/tmp/heap.dump", 'w') do |file| ObjectSpace.dump_all(output: file) end
45. {"address":"0x7f9fa7076ea0", "type":"STRING", "class":"0x7f9fa70cfe10", "embedded":true, "bytesize":13, "value":"Hello, world!", "encoding":"UTF-8", "file":"hello_world.rb", "line":5, "method":"bar", "generation":11, "memsize":40, "flags":{"wb_protected":true}}
46. {"address":"0x7f9fa7076ea0", "type":"STRING", "class":"0x7f9fa70cfe10", "embedded":true, "bytesize":13, "value":"Hello, world!", "encoding":"UTF-8", "file":"hello_world.rb", "line":5, "method":"bar", "generation":11, "memsize":40, "flags":{"wb_protected":true}}
47. $ wc -l /tmp/heap.dump 20290 /tmp/heap.dump
48. $ gem install heapy
49. Generation: nil object count: 20275, mem: 0.0 kb Generation: 11 object count: 15, mem: 1.8 kb
50. Analyzing Heap (Generation: 17) ------------------------------- allocated by memory (44061517) (in bytes) ============================== 39908512 …/ruby-2.2.3/lib/ruby/2.2.0/timeout.rb:79 1284993 …/ruby-2.2.3/lib/ruby/2.2.0/openssl/buffering.rb:182 201068 …/bundle/ruby/2.2.0/gems/json-1.8.3/lib/json/common.rb:223 189272 …/bundle/ruby/2.2.0/gems/newrelic_rpm-3.13.2.302/lib/… 172531 …/ruby-2.2.3/lib/ruby/2.2.0/net/http/header.rb:172 92200 …/bundle/ruby/2.2.0/gems/activesupport-4.2.3/lib/…
51. Class DSL objects survive longest
52. #
53. Chapter 3: Is it a memory leak?
54. Chapter 4: Let's trace a call stack A Tool Belt of a Seasoned Bug Hunter
 Damir Zekić • @sidonath
55. def main say_hello say_bye end def say_hello name = read_name msg = greeting(name) puts msg end def say_bye puts "Bye" end
56. say_hello read_name main def main say_hello say_bye end def say_hello name = read_name msg = greeting(name) puts msg end def say_bye puts "Bye" end
57. say_hello read_name greeting main def main say_hello say_bye end def say_hello name = read_name msg = greeting(name) puts msg end def say_bye puts "Bye" end
58. say_hello read_name greeting main say_bye def main say_hello say_bye end def say_hello name = read_name msg = greeting(name) puts msg end def say_bye puts "Bye" end
59. say_hello read_name greeting main say_bye def main say_hello say_bye end def say_hello name = read_name msg = greeting(name) puts msg end def say_bye puts "Bye" end
60. $ gem install flamegraph
66. Dig into Rails!
67. actionpack/ lib/ action_dispatch/ routing/ route_set.rb
68. def clear! @path_helpers.each do |helper| @path_helpers_module.send :undef_method, helper end @url_helpers.each do |helper| @url_helpers_module.send :undef_method, helper end @routes.clear @path_helpers.clear @url_helpers.clear end
69. def clear! @path_helpers.each do |helper| @path_helpers_module.send :undef_method, helper end @url_helpers.each do |helper| @url_helpers_module.send :undef_method, helper end @routes.clear @path_helpers.clear @url_helpers.clear end
70. Sessio CommentsController ArticlesController UrlHelpers #articles_url #article_url #new_article_url … PathHelpers
 #articles_path #article_path #new_article_path …
71. def clear! @path_helpers.each do |helper| @path_helpers_module.send :undef_method, helper end @url_helpers.each do |helper| @url_helpers_module.send :undef_method, helper end @routes.clear @path_helpers.clear @url_helpers.clear end
72. Is removing a method from a module slow?
73. Time (s) 0 1.75 3.5 5.25 7 Number of classes that include the module 1000 2000 3000 4000 5000 6000 7000 8000 9000 10000 Expected Constant Expected Linear Actual
74. Dig into Ruby!
75. vm_method.c
76. void rb_undef(VALUE klass, ID id) { const rb_method_entry_t *me; if (NIL_P(klass)) { rb_raise(rb_eTypeError, "no class to undef method"); } rb_frozen_class_p(klass); if (id == object_id || id == id__send__ || id == idInitialize) { rb_warn("undefining `%s' may cause serious problems", rb_id2name(id)); } me = search_method(klass, id, 0); if (me && me->def->type == VM_METHOD_TYPE_REFINED) { me = rb_resolve_refined_method(Qnil, me); } if (UNDEFINED_METHOD_ENTRY_P(me) || UNDEFINED_REFINED_METHOD_P(me->def)) { rb_method_name_error(klass, rb_id2str(id)); } rb_add_method(klass, id, VM_METHOD_TYPE_UNDEF, 0, METHOD_VISI_PUBLIC); CALL_METHOD_HOOK(klass, undefined, id); }
77. const rb_method_entry_t *me; me = search_method(klass, id, 0); if (me && me->def->type == VM_METHOD_TYPE_REFINED) { me = rb_resolve_refined_method(Qnil, me); } if (UNDEFINED_METHOD_ENTRY_P(me) || UNDEFINED_REFINED_METHOD_P(me->def)) { rb_method_name_error(klass, rb_id2str(id)); } rb_add_method(klass, id, VM_METHOD_TYPE_UNDEF, 0, METHOD_VISI_PUBLIC); CALL_METHOD_HOOK(klass, undefined, id);
78. const rb_method_entry_t *me; me = search_method(klass, id, 0); if (me && me->def->type == VM_METHOD_TYPE_REFINED) { me = rb_resolve_refined_method(Qnil, me); } if (UNDEFINED_METHOD_ENTRY_P(me) || UNDEFINED_REFINED_METHOD_P(me->def)) { rb_method_name_error(klass, rb_id2str(id)); } rb_add_method(klass, id, VM_METHOD_TYPE_UNDEF, 0, METHOD_VISI_PUBLIC); CALL_METHOD_HOOK(klass, undefined, id);
79. Is adding a method to a module slow?
80. Chapter 4: Let's trace a call stack SUCCESS
81. Chapter 5: Complete the puzzle A Tool Belt of a Seasoned Bug Hunter
 Damir Zekić • @sidonath
82. $ git bisect
83. $ gem install heapy
84. $ gem install flamegraph
85. We're leaking controllers
86. Our app was eagerly generating anonymous controllers every time our routes would get reloaded
87. Chapter 5: Complete the puzzle SUCCESS
88. Chapter 6: Fixing it! A Tool Belt of a Seasoned Bug Hunter
 Damir Zekić • @sidonath
89. Make it lazy!
90. Chapter 6: Fixing it! SUCCESS
91. Chapter 7: The Lesson A Tool Belt of a Seasoned Bug Hunter
 Damir Zekić • @sidonath
92. Your framework is a part of your app!
93. A Toolbelt of a Seasoned Bug Hunter Damir Zekić • @sidonath