Spelunking in Ruby

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

View Slide

2

View Slide

3
Built-in
Gems
Tools

View Slide

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

View Slide

ruby
5
puts "I <3 Ruby"

View Slide

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

View Slide

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

View Slide

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

View Slide

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

View Slide

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

View Slide

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

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

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

View Slide

ruby
14
> ruby deal_with_it.rb
>

View Slide

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

View Slide

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

View Slide

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

View Slide

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

View Slide

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

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

View Slide

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

View Slide

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

View Slide

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

View Slide

> bundler
24
> EDITOR=vim bundle open newrelic_rpm

View Slide

View Slide

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

View Slide

> 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

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

View Slide

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

View Slide

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

View Slide

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

View Slide

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

View Slide

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

View Slide

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

View Slide

> 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

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

View Slide

> 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

> 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

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

View Slide

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

View Slide

> 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

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

View Slide

> 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
[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
[4] pry(main)> show-stack
Showing all accessible frames (3 in total):
--
#0 child
#=> #1 [method] parent
# #2 [main]
# [5] pry(main)>

View Slide

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

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

View Slide

> jruby
49

View Slide

> jruby
50

View Slide

> jruby
51

View Slide

> jruby
52

View Slide

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

View Slide

> 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

> 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

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

View Slide

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

View Slide

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

View Slide

gdb
60
t = []
t << Thread.new do
end
t << Thread.new do
end

View Slide

gdb
61
t = []
t << Thread.new do
end
t << Thread.new do
end
t { |ts| ts.join }
puts "Done!"

View Slide

gdb
62
t = []
t << Thread.new do
end
t << Thread.new do
end
t { |ts| ts.join }
puts "Done!"

View Slide

> gdb
63
> ruby deadlock.rb
2796

View Slide

> 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

> 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)]
Loaded symbols for /...libpthread.so.0
....
0xb770c424 in __kernel_vsyscall ()
(gdb)

View Slide

> gdb
66
(gdb) attach 2796
....
(gdb)

View Slide

> gdb
67
(gdb) attach 2796
....
(gdb)

View Slide

> gdb
68
(gdb) attach 2796
....
(gdb)

View Slide

> 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

> gdb
70
#1 0xb76f496b in [email protected]@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

> gdb
71
#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
thread.c:3545
blockptr=0x0, recv=, num=out>,
#7 vm_call_method (th=0x8dfbe88, cfp=0xb7206f84, ....

View Slide

> gdb
72
#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
thread.c:3545
blockptr=0x0,recv=, num=out>,
#7 vm_call_method (th=0x8dfc180, cfp=0xb7104f84,...

View Slide

> gdb
73
thread.c:3545

View Slide

> gdb
74
thread.c:3545

View Slide

> 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

> 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

> 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

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

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

View Slide

> 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

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

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

View Slide

> 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
futex(0x9963860, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x996385c,
futex(0x9963840, FUTEX_WAKE_PRIVATE, 1) = 1

View Slide

> strace
85
futex(0x9963c28, FUTEX_WAKE_PRIVATE, 1) = 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
futex(0x9963860, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x996385c,
futex(0x9963840, FUTEX_WAKE_PRIVATE, 1) = 1

View Slide

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

View Slide

89
dtruss

View Slide

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

View Slide

> rbtrace
91
> ruby loop_and_write.rb
7034

View Slide

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

View Slide

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

View Slide

95
Built-in
Gems
Tools

View Slide

96
Jason Clark
@jasonrclark
http://jasonrclark.com/debug

View Slide

Spelunking in Ruby

Spelunking in Ruby

Jason R Clark

More Decks by Jason R Clark

Other Decks in Technology

Featured

Transcript