Spelunking in Ruby

We've all heard, "With good tests, you don't need a debugger." But faced with unfamiliar or poorly covered code, tests can fall short. Debugging tools are indispensable for taking that next step, and the Ruby ecosystem provides many options to help.

This talk showcases a wide variety of techniques for digging into that daunting application or gem. Starting from the humble puts statement, we'll dive through the various platform-specific Ruby debuggers, eventually peeking into the murky depths of gdb and the Ruby VM itself.

Jam packed with shortcuts, techniques, and gotchas, you'll be plumbing the depths of your code in no time.

Transcript

1. Spelunking in Ruby Jason Clark @jasonrclark https://flic.kr/p/bB396H http://jasonrclark.com/debug
3. https://flic.kr/p/bB396H 3 Built-in Gems Tools
4. Built-in https://flic.kr/p/6983QC
5. ruby 5 puts "I <3 Ruby"
6. ruby 6 puts "JRC: Don't leave me!"
7. ruby 7 def weird_method value = faulty_calculation puts "Strange? #{value}" value end
8. ruby 8 def weird_method value = faulty_calculation puts "Strange? #{value}" if $bedug value end
9. ruby 9 def weird_method value = faulty_calculation $c ||= 0; $c += 1 puts "Strange? #{value}" if $c % 1_000 == 0 value end
10. ruby 10 def weird_method value = faulty_calculation if caller.grep(/mine.rb/).any? puts "Strange? #{value}" end value end
11. ruby 11 ["caller.rb:6:in `dork'", "caller.rb:2:in `bork'", "caller.rb:13:in `<main>'"] def bork dork end def dork mork end def mork p caller end bork
12. ruby 12 def bork dork end def dork mork end def mork puts caller.join "\n\t" end bork > ruby caller.rb caller.rb:6:in `dork' caller.rb:2:in `bork' caller.rb:13:in `<main>'
13. Errors 13 https://flic.kr/p/dPQBvr
14. ruby 14 > ruby deal_with_it.rb >
15. ruby 15 def deal_with_it raise "O_o" rescue # Nope end deal_with_it
16. ruby 16 > ruby -d deal_with_it.rb Exception `RuntimeError' at deal...rb:2 - O_o > Hat tip to @tenderlove!
17. ruby 17 def clean_up_after_yourself @counter += 1 flaky_method ensure @counter -= 1 end
18. ruby 18 def clean_up_after_yourself @counter += 1 flaky_method ensure p $! @counter -= 1 end
19. ruby 19 > ruby clean_up.rb <RuntimeError: Oh noes> clean_up.rb:4:in `flake': Oh noes (RuntimeError) from clean_up.rb:9:in `clean_up_after_yourself' from clean_up.rb:15:in `<main>'
20. ruby 20 Thread.new do raise "Boo" puts "Done" end loop do # ... end
21. ruby 21 Thread.abort_on_exception = true Thread.new do raise "Boo" puts "Done" end loop do # ... end
22. > ruby 22 > ruby thread.rb thread.rb:4:in `block in <main>': Boo ... >
23. Accessing Gems https://flic.kr/p/bBS5ir
24. > bundler 24 > EDITOR=vim bundle open newrelic_rpm
26. > rubygems 26 > gem --version 2.4.0 > gem open newrelic_rpm
27. > rubygems 27 > gem pristine newrelic_rpm Restoring gems to pristine condition... Restored newrelic_rpm-3.9.2.237.beta Restored newrelic_rpm-3.9.2.238.beta
28. Helpful Gems https://flic.kr/p/3fjxf
29. hometown 29 require 'hometown' Hometown.watch(::Thread) t = Thread.new do loop { } end p Hometown.for(t)
30. hometown 30 require 'hometown' Hometown.watch(::Thread) t = Thread.new do loop { } end p Hometown.for(t)
31. hometown 31 require 'hometown' Hometown.watch(::Thread) t = Thread.new do loop { } end p Hometown.for(t)
32. hometown 32 require 'hometown' Hometown.watch(::Thread) t = Thread.new do loop { } end p Hometown.for(t)
33. hometown 33 #<Hometown::Trace:0x007f8d730fa6b0 @traced_class=Thread, @backtrace=[ "hometown.rb:6:in `start_work'", "hometown.rb:11:in `<main>'"]>
34. pry 34 require 'pry' @tool = "crowbar" def crowbar bar_like = true binding.pry end crowbar
35. > pry 35 Frame number: 0/1 From: ./pry.rb @ line 7 Object#crowbar: 5: def crowbar 6: bar_like = true => 7: binding.pry 8: end [1] pry(main)>
36. > pry 36 [1] pry(main)> ls self.methods: inspect to_s instance variables: @tool locals: ... bar_like
37. > pry 37 [3] pry(main)> whereami Frame number: 0/1 From: ./pry.rb @ line 7 Object#crowbar: 5: def crowbar 6: bar_like = true => 7: binding.pry 8: end
39. > pry debugging 39 > gem install pry-byebug MRI 2.0+ > gem install pry-debugger MRI 1.9.2+ > gem install pry-nav Everyone Else!
40. > pry debugging 40 [1] pry(main)> From: ./pry-nav.rb @ line 17 : 15: binding.pry => 16: step1 17: step2 18: step3
41. > pry debugging 41 [1] pry(main)> next From: ./pry-nav.rb @ line 17 : 15: binding.pry 16: step1 => 17: step2 18: step3
42. > prompt 42 [1] pry(main)> step From: ./pry-nav.rb @ line 8 Object#step2: 7: def step2 => 8: puts "Stuff" 9: end [1] pry(main)> continue
43. pry-stack_explorer 43 require 'pry' def parent priority = 'sleep' child end def child priority = 'play' binding.pry end parent
44. > pry-stack_explorer 44 Frame number: 0/2 From: ./stacked.rb @ line 10 Object#child: 8: def child 9: priority = "play" => 10: binding.pry 11: end [1] pry(main)> priority => "play"
45. > pry-stack_explorer 45 [2] pry(main)> up Frame number: 1/2 Frame type: method From: ./stacked.rb @ line 5 Object#parent: 3: def parent 4: priority = "sleep" => 5: child 6: end [3] pry(main)> priority => "sleep"
46. > pry-stack_explorer 46 [4] pry(main)> show-stack Showing all accessible frames (3 in total): -- #0 child <Object#child()> #=> #1 [method] parent <Object#parent()> # #2 [main] <main> # [5] pry(main)>
47. > ~/.pryrc 47 Hat tip to https://github.com/pry/pry/issues/607! Pry::Commands.command /^$/, "repeat" do last = StringIO.new(Pry.history.to_a.last) _pry_.input = last end
48. Tools https://flic.kr/p/ng9aPM
49. > jruby 49
50. > jruby 50
51. > jruby 51
52. > jruby 52
53. rubinius 53 require 'rubinius/debugger' Rubinius::Debugger.start def my_message puts "Built-in debugging FTW" end print_message
54. > rubinius 54 | Breakpoint: Object#__script__ at rbx.rb:3 (16) | 3: Rubinius::Debugger.start debug> l | 1: require 'rubinius/debugger' | 2: | 3: Rubinius::Debugger.start | 4: | 5: def my_message | 6: puts "Built-in debugging FTW" | 7: end | 8:
55. > rubinius 55 debug> break Object.my_message * Unable to find method 'my_message' in Object | Defer this breakpoint to later? [y/n] y | Deferred breakpoint created.
56. > rubinius 56 debug> c | Resolved breakpoint for Object.my_message | Set breakpoint 2: rbx.rb:6 (+0) | Breakpoint: Object#my_message at rbx.rb:6 (0) | 6: puts "Built-in debugging FTW"
57. > rubinius 57 > ruby -Xdebug rbx.rb | Breakpoint: Rubinius::Loader#debugger at kernel/loader.rb:565 (50) | 565: Rubinius::Debugger.start
58. gdb 58 require 'thread' puts Process.pid m1 = Mutex.new m2 = Mutex.new Thread.new do loop do # ... end end
59. gdb 59 t = [] t << Thread.new do m1.lock; sleep 1; m2.lock end
60. gdb 60 t = [] t << Thread.new do m1.lock; sleep 1; m2.lock end t << Thread.new do m2.lock; sleep 1; m1.lock end
61. gdb 61 t = [] t << Thread.new do m1.lock; sleep 1; m2.lock end t << Thread.new do m2.lock; sleep 1; m1.lock end t { |ts| ts.join } puts "Done!"
62. gdb 62 t = [] t << Thread.new do m1.lock; sleep 1; m2.lock end t << Thread.new do m2.lock; sleep 1; m1.lock end t { |ts| ts.join } puts "Done!"
63. > gdb 63 > ruby deadlock.rb 2796
64. > gdb 64 > sudo gdb GNU gdb (Ubuntu/Linaro 7.4-2012.04-0ubuntu2.1) Copyright (C) 2012 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later... ... (gdb)
65. > gdb 65 (gdb) attach 2796 Attaching to process 2796 Reading symbols from /rbenv/.../bin/ruby...done. Reading symbols from /...libpthread.so.0 (no debugging symbols found)...done. [Thread debugging using libthread_db enabled] [New Thread 0xb6f82b40 (LWP 2814)] [New Thread 0xb7084b40 (LWP 2813)] [New Thread 0xb7186b40 (LWP 2812)] [New Thread 0xb7213b40 (LWP 2811)] Loaded symbols for /...libpthread.so.0 .... 0xb770c424 in __kernel_vsyscall () (gdb)
66. > gdb 66 (gdb) attach 2796 Attaching to process 2796 Reading symbols from /rbenv/.../bin/ruby...done. Reading symbols from /...libpthread.so.0 (no debugging symbols found)...done. [Thread debugging using libthread_db enabled] [New Thread 0xb6f82b40 (LWP 2814)] [New Thread 0xb7084b40 (LWP 2813)] [New Thread 0xb7186b40 (LWP 2812)] [New Thread 0xb7213b40 (LWP 2811)] Loaded symbols for /...libpthread.so.0 .... 0xb770c424 in __kernel_vsyscall () (gdb)
67. > gdb 67 (gdb) attach 2796 Attaching to process 2796 Reading symbols from /rbenv/.../bin/ruby...done. Reading symbols from /...libpthread.so.0 (no debugging symbols found)...done. [Thread debugging using libthread_db enabled] [New Thread 0xb6f82b40 (LWP 2814)] [New Thread 0xb7084b40 (LWP 2813)] [New Thread 0xb7186b40 (LWP 2812)] [New Thread 0xb7213b40 (LWP 2811)] Loaded symbols for /...libpthread.so.0 .... 0xb770c424 in __kernel_vsyscall () (gdb)
68. > gdb 68 (gdb) attach 2796 Attaching to process 2796 Reading symbols from /rbenv/.../bin/ruby...done. Reading symbols from /...libpthread.so.0 (no debugging symbols found)...done. [Thread debugging using libthread_db enabled] [New Thread 0xb6f82b40 (LWP 2814)] [New Thread 0xb7084b40 (LWP 2813)] [New Thread 0xb7186b40 (LWP 2812)] [New Thread 0xb7213b40 (LWP 2811)] Loaded symbols for /...libpthread.so.0 .... 0xb770c424 in __kernel_vsyscall () (gdb)
69. > gdb 69 (gdb) thread apply all backtrace Thread 5 (Thread 0xb7213b40 (LWP 2811)): #0 0xb770c424 in __kernel_vsyscall () #1 0xb75bcbd1 in select () from /lib/.../libc.so.6 #2 0x08162488 in thread_timer (p=0x8c7c83c) at thread_pthread.c:1155 #3 0xb76f0d4c in start_thread () from /lib/.../ libpthread.so.0 #4 0xb75c3bae in clone () from /lib/.../libc.so.6
70. > gdb 70 Thread 4 (Thread 0xb7186b40 (LWP 2812)): #0 0xb770c424 in __kernel_vsyscall () #1 0xb76f496b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0 #2 0x08168b8c in native_cond_wait (mutex=0x8dfbe28, cond=0x8dfbe40) at thread_pthread.c:304 #3 lock_func (timeout_ms=0, mutex=0x8dfbe28, th=0x8dfbe88) at thread.c:3515 #4 rb_mutex_lock (self=148863880) at thread.c:3575 #5 0x08168ff5 in rb_mutex_lock (self=148863880) at thread.c:3545 #6 0x0815c2b4 in vm_call_cfunc (me=0x8d0d6e0, blockptr=0x0, recv=<optimized out>, num=<optimized out>, #7 vm_call_method (th=0x8dfbe88, cfp=0xb7206f84, ....
71. > gdb 71 Thread 4 (Thread 0xb7186b40 (LWP 2812)): #0 0xb770c424 in __kernel_vsyscall () #1 0xb76f496b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0 #2 0x08168b8c in native_cond_wait (mutex=0x8dfbe28, cond=0x8dfbe40) at thread_pthread.c:304 #3 lock_func (timeout_ms=0, mutex=0x8dfbe28, th=0x8dfbe88) at thread.c:3515 #4 rb_mutex_lock (self=148863880) at thread.c:3575 #5 0x08168ff5 in rb_mutex_lock (self=148863880) at thread.c:3545 #6 0x0815c2b4 in vm_call_cfunc (me=0x8d0d6e0, blockptr=0x0, recv=<optimized out>, num=<optimized out>, #7 vm_call_method (th=0x8dfbe88, cfp=0xb7206f84, ....
72. > gdb 72 Thread 3 (Thread 0xb7084b40 (LWP 2813)): #0 0xb770c424 in __kernel_vsyscall () #1 0xb76f496b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0 #2 0x08168b8c in native_cond_wait (mutex=0x8dfbdc8, cond=0x8dfbde0) at thread_pthread.c:304 #3 lock_func (timeout_ms=0, mutex=0x8dfbdc8, th=0x8dfc180) at thread.c:3515 #4 rb_mutex_lock (self=148863900) at thread.c:3575 #5 0x08168ff5 in rb_mutex_lock (self=148863900) at thread.c:3545 #6 0x0815c2b4 in vm_call_cfunc (me=0x8d0d6e0, blockptr=0x0,recv=<optimized out>, num=<optimized out>, #7 vm_call_method (th=0x8dfc180, cfp=0xb7104f84,...
73. > gdb 73 Thread 3 (Thread 0xb7084b40 (LWP 2813)): #0 0xb770c424 in __kernel_vsyscall () #1 0xb76f496b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0 #2 0x08168b8c in native_cond_wait (mutex=0x8dfbdc8, cond=0x8dfbde0) at thread_pthread.c:304 #3 lock_func (timeout_ms=0, mutex=0x8dfbdc8, th=0x8dfc180) at thread.c:3515 #4 rb_mutex_lock (self=148863900) at thread.c:3575 #5 0x08168ff5 in rb_mutex_lock (self=148863900) at thread.c:3545 #6 0x0815c2b4 in vm_call_cfunc (me=0x8d0d6e0, blockptr=0x0,recv=<optimized out>, num=<optimized out>, #7 vm_call_method (th=0x8dfc180, cfp=0xb7104f84,...
74. > gdb 74 Thread 3 (Thread 0xb7084b40 (LWP 2813)): #0 0xb770c424 in __kernel_vsyscall () #1 0xb76f496b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0 #2 0x08168b8c in native_cond_wait (mutex=0x8dfbdc8, cond=0x8dfbde0) at thread_pthread.c:304 #3 lock_func (timeout_ms=0, mutex=0x8dfbdc8, th=0x8dfc180) at thread.c:3515 #4 rb_mutex_lock (self=148863900) at thread.c:3575 #5 0x08168ff5 in rb_mutex_lock (self=148863900) at thread.c:3545 #6 0x0815c2b4 in vm_call_cfunc (me=0x8d0d6e0, blockptr=0x0,recv=<optimized out>, num=<optimized out>, #7 vm_call_method (th=0x8dfc180, cfp=0xb7104f84,...
75. > ruby/thread.c /* * call-seq: * mutex.lock -> self * * ..... */ VALUE rb_mutex_lock(VALUE self) { rb_thread_t *th = GET_THREAD(); rb_mutex_t *mutex; GetMutexPtr(self, mutex); 75
76. > ruby/thread.c /* * call-seq: * mutex.lock -> self * * ..... */ VALUE rb_mutex_lock(VALUE self) { rb_thread_t *th = GET_THREAD(); rb_mutex_t *mutex; GetMutexPtr(self, mutex); 76 Mutex.lock
78. > gdb 78 (gdb) call (void)rb_backtrace() Elsewhere on STDOUT... from deadlock.rb:22:in `block in <main>' from deadlock.rb:22:in `loop'
79. > ~/.gdbinit 79 define redirect_stdout call (void)close(1) call (void)close(2) call (int)open($arg0, 2, 0) call (int)open($arg0, 2, 0) end
80. > gdb 80 (gdb) redirect_stdout("gdb.log") $1 = 1 $2 = 2
81. > gdb 81 (gdb) call (void)rb_backtrace() (gdb) call (void)fflush(0) > cat gdb.log ! from deadlock.rb:22:in `block in <main>' ! from deadlock.rb:22:in `loop'
82. > ~/.gdbinit 82 define ruby_eval call(rb_p(rb_eval_string_protect($arg0,(int*)0))) end Hat tip to http://robots.thoughtbot.com/using-gdb- to-inspect-a-running-ruby-process!
83. > strace 83 > ruby deadlock.rb 3621 > sudo strace -p 3621 -s 2048
84. > strace 84 futex(0x9963c28, FUTEX_WAKE_PRIVATE, 1) = 0 clock_gettime(CLOCK_MONOTONIC, {26169, 105071065}) = 0 time(NULL) = 1409262683 mmap2(NULL, 5284, PROT_READ|PROT_WRITE...) = 0xb700f000 mmap2(NULL, 5284, PROT_READ|PROT_WRITE...) = 0xb6f8e000 mprotect(0xb6f8e000, 4096, PROT_NONE) = 0 clone(child_stack=0xb700e464, flags=)... brk(0x9b19000) = 0x9b19000 clock_gettime(CLOCK_MONOTONIC, {26169, 112701666}) = 0 futex(0x9963860, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x996385c, futex(0x9963840, FUTEX_WAKE_PRIVATE, 1) = 1
85. > strace 85 futex(0x9963c28, FUTEX_WAKE_PRIVATE, 1) = 0 clock_gettime(CLOCK_MONOTONIC, {26169, 105071065}) = 0 time(NULL) = 1409262683 mmap2(NULL, 5284, PROT_READ|PROT_WRITE...) = 0xb700f000 mmap2(NULL, 5284, PROT_READ|PROT_WRITE...) = 0xb6f8e000 mprotect(0xb6f8e000, 4096, PROT_NONE) = 0 clone(child_stack=0xb700e464, flags=)... brk(0x9b19000) = 0x9b19000 clock_gettime(CLOCK_MONOTONIC, {26169, 112701666}) = 0 futex(0x9963860, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x996385c, futex(0x9963840, FUTEX_WAKE_PRIVATE, 1) = 1
86. > strace 86 > man futex FUTEX(2) Linux Programmer's Manual FUTEX(2) NAME futex - Fast Userspace Locking system call SYNOPSIS #include <linux/futex.h> #include <sys/time.h> int futex(int *uaddr, int op, int val, const struct timespec *timeout, int *uaddr2, int val3);
88. 88 strace
89. 89 dtruss
90. rbtrace 90 require 'rbtrace' puts Process.pid loop do sleep(0.1) print "." end
91. > rbtrace 91 > ruby loop_and_write.rb 7034
92. > rbtrace 92 > rbtrace -p 7034 --firehose *** attached to process 7034 Kernel#print IO#write <0.000017> Kernel#print <0.000040> Kernel#sleep <0.100162> Kernel#print IO#write <0.000018> Kernel#print <0.000033> ....
93. 93 --firehose
94. > rbtrace 94 > rbtrace -p <PID> --slow=<N> > rbtrace -p <PID> --methods "Kernel#sleep" > rbtrace -p <PID> --gc > rbtrace -p <PID> -c activerecord io
95. https://flic.kr/p/bB396H 95 Built-in Gems Tools
96. https://flic.kr/p/bB396H 96 Jason Clark @jasonrclark http://jasonrclark.com/debug