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

Spelunking in Ruby

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.

Jason R Clark

September 13, 2014
Tweet

More Decks by Jason R Clark

Other Decks in Technology

Transcript

  1. 2

  2. ruby 9 def weird_method value = faulty_calculation $c ||= 0;

    $c += 1 puts "Strange? #{value}" if $c % 1_000 == 0 value end
  3. 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>'
  4. 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>'
  5. > 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
  6. > 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)>
  7. > 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
  8. 38

  9. > pry debugging 39 > gem install pry-byebug MRI 2.0+

    > gem install pry-debugger MRI 1.9.2+ > gem install pry-nav Everyone Else!
  10. > pry debugging 40 [1] pry(main)> From: ./pry-nav.rb @ line

    17 : 15: binding.pry => 16: step1 17: step2 18: step3
  11. > pry debugging 41 [1] pry(main)> next From: ./pry-nav.rb @

    line 17 : 15: binding.pry 16: step1 => 17: step2 18: step3
  12. > 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
  13. pry-stack_explorer 43 require 'pry' def parent priority = 'sleep' child

    end def child priority = 'play' binding.pry end parent
  14. > 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"
  15. > 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"
  16. > 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)>
  17. > ~/.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
  18. > 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:
  19. > 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.
  20. > 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"
  21. > rubinius 57 > ruby -Xdebug rbx.rb | Breakpoint: Rubinius::Loader#debugger

    at kernel/loader.rb:565 (50) | 565: Rubinius::Debugger.start
  22. gdb 58 require 'thread' puts Process.pid m1 = Mutex.new m2

    = Mutex.new Thread.new do loop do # ... end end
  23. 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
  24. 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!"
  25. 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!"
  26. > 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)
  27. > 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)
  28. > 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)
  29. > 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)
  30. > 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)
  31. > 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
  32. > 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, ....
  33. > 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, ....
  34. > 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,...
  35. > 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,...
  36. > 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,...
  37. > 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
  38. > 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
  39. 77

  40. > gdb 78 (gdb) call (void)rb_backtrace() Elsewhere on STDOUT... from

    deadlock.rb:22:in `block in <main>' from deadlock.rb:22:in `loop'
  41. > ~/.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
  42. > 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'
  43. > ~/.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!
  44. > 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
  45. > 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
  46. > 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);
  47. 87

  48. > 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> ....
  49. > rbtrace 94 > rbtrace -p <PID> --slow=<N> > rbtrace

    -p <PID> --methods "Kernel#sleep" > rbtrace -p <PID> --gc > rbtrace -p <PID> -c activerecord io