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

Spelunking in Ruby

92e7389893670a1920a4fd98aec0d246?s=47 Jason R Clark
September 13, 2014

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.

92e7389893670a1920a4fd98aec0d246?s=128

Jason R Clark

September 13, 2014
Tweet

Transcript

  1. Spelunking in Ruby Jason Clark @jasonrclark https://flic.kr/p/bB396H http://jasonrclark.com/debug

  2. 2

  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

  25. None
  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
  38. 38

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

  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);
  87. 87

  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