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
   

   View Slide

2. View Slide

3. https://flic.kr/p/bB396H
   3
   Built-in
   Gems
   Tools
   

   View Slide

4. Built-in
   https://flic.kr/p/6983QC
   

   View Slide

5. ruby
   5
   puts "I <3 Ruby"
   

   View Slide

6. ruby
   6
   puts "JRC: Don't leave me!"
   

   View Slide

7. ruby
   7
   def weird_method
   value = faulty_calculation
   puts "Strange? #{value}"
   value
   end
   

   View Slide

8. ruby
   8
   def weird_method
   value = faulty_calculation
   puts "Strange? #{value}" if $bedug
   value
   end
   

   View Slide

9. ruby
   9
   def weird_method
   value = faulty_calculation
   $c ||= 0; $c += 1
   puts "Strange? #{value}" if $c % 1_000 == 0
   value
   end
   

   View Slide

10. ruby
    10
    def weird_method
    value = faulty_calculation
    if caller.grep(/mine.rb/).any?
    puts "Strange? #{value}"
    end
    value
    end
    

    View Slide

11. ruby
    11
    ["caller.rb:6:in `dork'",
    "caller.rb:2:in `bork'",
    "caller.rb:13:in `'"]
    def bork
    dork
    end
    def dork
    mork
    end
    def mork
    p caller
    end
    bork
    

    View Slide

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 `'
    

    View Slide

13. Errors
    13 https://flic.kr/p/dPQBvr
    

    View Slide

14. ruby
    14
    > ruby deal_with_it.rb
    >
    

    View Slide

15. ruby
    15
    def deal_with_it
    raise "O_o"
    rescue
    # Nope
    end
    deal_with_it
    

    View Slide

16. ruby
    16
    > ruby -d deal_with_it.rb
    Exception `RuntimeError' at deal...rb:2 - O_o
    >
    Hat tip to @tenderlove!
    

    View Slide

17. ruby
    17
    def clean_up_after_yourself
    @counter += 1
    flaky_method
    ensure
    @counter -= 1
    end
    

    View Slide

18. ruby
    18
    def clean_up_after_yourself
    @counter += 1
    flaky_method
    ensure
    p $!
    @counter -= 1
    end
    

    View Slide

19. ruby
    19
    > ruby clean_up.rb
    
    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 `'
    

    View Slide

20. ruby
    20
    Thread.new do
    raise "Boo"
    puts "Done"
    end
    loop do
    # ...
    end
    

    View Slide

21. ruby
    21
    Thread.abort_on_exception = true
    Thread.new do
    raise "Boo"
    puts "Done"
    end
    loop do
    # ...
    end
    

    View Slide

22. > ruby
    22
    > ruby thread.rb
    thread.rb:4:in `block in ': Boo ...
    >
    

    View Slide

23. Accessing
    Gems
    https://flic.kr/p/bBS5ir
    

    View Slide

24. > bundler
    24
    > EDITOR=vim bundle open newrelic_rpm
    

    View Slide

25. View Slide

26. > rubygems
    26
    > gem --version
    2.4.0
    > gem open newrelic_rpm
    

    View Slide

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
    

    View Slide

28. Helpful
    Gems
    https://flic.kr/p/3fjxf
    

    View Slide

29. hometown
    29
    require 'hometown'
    Hometown.watch(::Thread)
    t = Thread.new do
    loop { }
    end
    p Hometown.for(t)
    

    View Slide

30. hometown
    30
    require 'hometown'
    Hometown.watch(::Thread)
    t = Thread.new do
    loop { }
    end
    p Hometown.for(t)
    

    View Slide

31. hometown
    31
    require 'hometown'
    Hometown.watch(::Thread)
    t = Thread.new do
    loop { }
    end
    p Hometown.for(t)
    

    View Slide

32. hometown
    32
    require 'hometown'
    Hometown.watch(::Thread)
    t = Thread.new do
    loop { }
    end
    p Hometown.for(t)
    

    View Slide

33. hometown
    33
    #@traced_class=Thread,
    @backtrace=[
    "hometown.rb:6:in `start_work'",
    "hometown.rb:11:in `'"]>
    

    View Slide

34. pry
    34
    require 'pry'
    @tool = "crowbar"
    def crowbar
    bar_like = true
    binding.pry
    end
    crowbar
    

    View Slide

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)>
    

    View Slide

36. > pry
    36
    [1] pry(main)> ls
    self.methods: inspect to_s
    instance variables: @tool
    locals: ... bar_like
    

    View Slide

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
    

    View Slide

38. View Slide

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!
    

    View Slide

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

    View Slide

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

    View Slide

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
    

    View Slide

43. pry-stack_explorer
    43
    require 'pry'
    def parent
    priority = 'sleep'
    child
    end
    def child
    priority = 'play'
    binding.pry
    end
    parent
    

    View Slide

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"
    

    View Slide

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"
    

    View Slide

46. > pry-stack_explorer
    46
    [4] pry(main)> show-stack
    Showing all accessible frames (3 in total):
    --
    #0 child
    #=> #1 [method] parent
    # #2 [main]
    # [5] pry(main)>
    

    View Slide

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
    

    View Slide

48. Tools
    https://flic.kr/p/ng9aPM
    

    View Slide

49. > jruby
    49
    

    View Slide

50. > jruby
    50
    

    View Slide

51. > jruby
    51
    

    View Slide

52. > jruby
    52
    

    View Slide

53. rubinius
    53
    require 'rubinius/debugger'
    Rubinius::Debugger.start
    def my_message
    puts "Built-in debugging FTW"
    end
    print_message
    

    View Slide

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:
    

    View Slide

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.
    

    View Slide

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"
    

    View Slide

57. > rubinius
    57
    > ruby -Xdebug rbx.rb
    | Breakpoint: Rubinius::Loader#debugger at
    kernel/loader.rb:565 (50)
    | 565: Rubinius::Debugger.start
    

    View Slide

58. gdb
    58
    require 'thread'
    puts Process.pid
    m1 = Mutex.new
    m2 = Mutex.new
    Thread.new do
    loop do
    # ...
    end
    end
    

    View Slide

59. gdb
    59
    t = []
    t << Thread.new do
    m1.lock; sleep 1; m2.lock
    end
    

    View Slide

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
    

    View Slide

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!"
    

    View Slide

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!"
    

    View Slide

63. > gdb
    63
    > ruby deadlock.rb
    2796
    

    View Slide

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)
    

    View Slide

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)
    

    View Slide

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)
    

    View Slide

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)
    

    View Slide

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)
    

    View Slide

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
    

    View Slide

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=, num=out>,
    #7 vm_call_method (th=0x8dfbe88, cfp=0xb7206f84, ....
    

    View Slide

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=, num=out>,
    #7 vm_call_method (th=0x8dfbe88, cfp=0xb7206f84, ....
    

    View Slide

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=, num=out>,
    #7 vm_call_method (th=0x8dfc180, cfp=0xb7104f84,...
    

    View Slide

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=, num=out>,
    #7 vm_call_method (th=0x8dfc180, cfp=0xb7104f84,...
    

    View Slide

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=, num=out>,
    #7 vm_call_method (th=0x8dfc180, cfp=0xb7104f84,...
    

    View Slide

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
    

    View Slide

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
    

    View Slide

77. View Slide

78. > gdb
    78
    (gdb) call (void)rb_backtrace()
    Elsewhere on STDOUT...
    from deadlock.rb:22:in `block in '
    from deadlock.rb:22:in `loop'
    

    View Slide

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
    

    View Slide

80. > gdb
    80
    (gdb) redirect_stdout("gdb.log")
    $1 = 1
    $2 = 2
    

    View Slide

81. > gdb
    81
    (gdb) call (void)rb_backtrace()
    (gdb) call (void)fflush(0)
    > cat gdb.log
    ! from deadlock.rb:22:in `block in '
    ! from deadlock.rb:22:in `loop'
    

    View Slide

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!
    

    View Slide

83. > strace
    83
    > ruby deadlock.rb
    3621
    > sudo strace -p 3621 -s 2048
    

    View Slide

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
    

    View Slide

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
    

    View Slide

86. > strace
    86
    > man futex
    FUTEX(2) Linux Programmer's Manual FUTEX(2)
    NAME
    futex - Fast Userspace Locking system call
    SYNOPSIS
    #include
    #include
    int futex(int *uaddr, int op, int val,
    const struct timespec *timeout,
    int *uaddr2, int val3);
    

    View Slide

87. View Slide

88. 88
    strace
    

    View Slide

89. 89
    dtruss
    

    View Slide

90. rbtrace
    90
    require 'rbtrace'
    puts Process.pid
    loop do
    sleep(0.1)
    print "."
    end
    

    View Slide

91. > rbtrace
    91
    > ruby loop_and_write.rb
    7034
    

    View Slide

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

    View Slide

93. 93
    --firehose
    

    View Slide

94. > rbtrace
    94
    > rbtrace -p --slow=
    > rbtrace -p --methods "Kernel#sleep"
    > rbtrace -p --gc
    > rbtrace -p -c activerecord io
    

    View Slide

95. https://flic.kr/p/bB396H
    95
    Built-in
    Gems
    Tools
    

    View Slide

96. https://flic.kr/p/bB396H
    96
    Jason Clark
    @jasonrclark
    http://jasonrclark.com/debug
    

    View Slide