$30 off During Our Annual Pro Sale. View Details »

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. Spelunking
    in Ruby
    Jason Clark
    @jasonrclark
    https://flic.kr/p/bB396H
    http://jasonrclark.com/debug

    View Slide

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