Spelunking in Ruby - Speaker Deck

Slide 1

Slide 1 text

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

Slide 2

Slide 2 text

Slide 3

Slide 3 text

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

Slide 4

Slide 4 text

Built-in https://ﬂic.kr/p/6983QC

Slide 5

Slide 5 text

ruby 5 puts "I <3 Ruby"

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

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

Slide 10

Slide 10 text

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

Slide 11

Slide 11 text

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

Slide 12

Slide 12 text

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

Slide 13

Slide 13 text

Errors 13 https://ﬂic.kr/p/dPQBvr

Slide 14

Slide 14 text

ruby 14 > ruby deal_with_it.rb >

Slide 15

Slide 15 text

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

Slide 16

Slide 16 text

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

Slide 17

Slide 17 text

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

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

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

Slide 20

Slide 20 text

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

Slide 21

Slide 21 text

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

Slide 22

Slide 22 text

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

Slide 23

Slide 23 text

Accessing Gems https://ﬂic.kr/p/bBS5ir

Slide 24

Slide 24 text

> bundler 24 > EDITOR=vim bundle open newrelic_rpm

Slide 25

Slide 25 text

No content

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

> 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

Slide 28

Slide 28 text

Helpful Gems https://ﬂic.kr/p/3fjxf

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

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

Slide 31

Slide 31 text

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

Slide 32

Slide 32 text

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

Slide 33

Slide 33 text

hometown 33 #'"]>

Slide 34

Slide 34 text

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

Slide 35

Slide 35 text

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

Slide 36

Slide 36 text

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

Slide 37

Slide 37 text

> 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

Slide 38

Slide 38 text

Slide 39

Slide 39 text

> pry debugging 39 > gem install pry-byebug MRI 2.0+ > gem install pry-debugger MRI 1.9.2+ > gem install pry-nav Everyone Else!

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

> 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

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

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

Slide 45

Slide 45 text

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

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

Tools https://ﬂic.kr/p/ng9aPM

Slide 49

Slide 49 text

> jruby 49

Slide 50

Slide 50 text

> jruby 50

Slide 51

Slide 51 text

> jruby 51

Slide 52

Slide 52 text

> jruby 52

Slide 53

Slide 53 text

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

Slide 54

Slide 54 text

Slide 55

Slide 55 text

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

Slide 56

Slide 56 text

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

Slide 57

Slide 57 text

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

Slide 58

Slide 58 text

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

Slide 59

Slide 59 text

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

Slide 60

Slide 60 text

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

Slide 61

Slide 61 text

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

Slide 62

Slide 62 text

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

Slide 63

Slide 63 text

> gdb 63 > ruby deadlock.rb 2796

Slide 64

Slide 64 text

Slide 65

Slide 65 text

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

Slide 66

Slide 66 text

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

Slide 67

Slide 67 text

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

Slide 68

Slide 68 text

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

Slide 69

Slide 69 text

> 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

Slide 70

Slide 70 text

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

Slide 71

Slide 71 text

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

Slide 72

Slide 72 text

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

Slide 73

Slide 73 text

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

Slide 74

Slide 74 text

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

Slide 75

Slide 75 text

> 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

Slide 76

Slide 76 text

> 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

Slide 77

Slide 77 text

Slide 78

Slide 78 text

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

Slide 79

Slide 79 text

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

Slide 80

Slide 80 text

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

Slide 81

Slide 81 text

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

Slide 82

Slide 82 text

> ~/.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!

Slide 83

Slide 83 text

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

Slide 84

Slide 84 text

> 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

Slide 85

Slide 85 text

> 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

Slide 86

Slide 86 text

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

Slide 87

Slide 87 text

Slide 88

Slide 88 text

88 strace

Slide 89

Slide 89 text

89 dtruss

Slide 90

Slide 90 text

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

Slide 91

Slide 91 text

> rbtrace 91 > ruby loop_and_write.rb 7034

Slide 92

Slide 92 text

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

Slide 93

Slide 93 text

93 --firehose

Slide 94

Slide 94 text

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

Slide 95

Slide 95 text

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

Slide 96

Slide 96 text

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