Ruby interpreter provides event hooks, which can be used to trace execution of Ruby program. To setup an event hook, call set_trace_func(some_proc), to remove it, call set_trace_func(nil).
Tracers are probably the most useful debugging tool ever invented, far more useful than debuggers based on single-stepping and breakpoints.
Ruby traces 8 events:
line - file/line changedclass - module/class definition startedend - module/class definition endedcall - Ruby function was calledreturn - Ruby function returnedc-call - C function was calledc-return - C function returnedraise - exception was raised
Some events are not traced, like setting and getting variables (local, global, instance, or class).
set_trace_func proc { |event, file, line, id, binding, classname|
STDERR.printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}
@welcome = "Hello"
separator = ", "
$object = "world"
@@excl = "!"
puts(@welcome + separator + $object + @@excl)
$ ./example-1.rb
line ./example-1.rb:7 false
line ./example-1.rb:8 false
line ./example-1.rb:9 false
line ./example-1.rb:10 false
line ./example-1.rb:11 false
c-call ./example-1.rb:11 + String
c-return ./example-1.rb:11 + String
c-call ./example-1.rb:11 + String
c-return ./example-1.rb:11 + String
c-call ./example-1.rb:11 + String
c-return ./example-1.rb:11 + String
c-call ./example-1.rb:11 puts Kernel
c-call ./example-1.rb:11 write IO
c-return ./example-1.rb:11 write IO
c-call ./example-1.rb:11 write IO
c-return ./example-1.rb:11 write IO
c-return ./example-1.rb:11 puts Kernel
In the example
String#+ was run 3 times, and
IO#write 2 times - the second one most likely to write out newline character.
Many things in Ruby are magical and are not converted to method calls. One such thing is string interpolation with
"... #{ code } ... ", which is not converted to
String#+, or
Array#join, but handled specially by the interpreter.
set_trace_func proc { |event, file, line, id, binding, classname|
STDERR.printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}
@welcome = "Hello"
$object = "world"
puts("#{@welcome}, #{$object}\n")
$ ./example-2.rb
line ./example-2.rb:7 false
line ./example-2.rb:8 false
line ./example-2.rb:9 false
c-call ./example-2.rb:9 puts Kernel
c-call ./example-2.rb:9 write IO
c-return ./example-2.rb:9 write IO
c-return ./example-2.rb:9 puts Kernel
In the same way, creating classes is not converted to
Class#new, and adding methods is not converted to
Module#define_method. Fortunately if we need to capture such events Ruby provides specialized hooks - when a class is created its parent's
inherited method is called, and when a method is added, Ruby calls
method_added on its class.
set_trace_func proc { |event, file, line, id, binding, classname|
STDERR.printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}
class Geolocation
def initialize(lat, long)
@lat = lat
@long = long
end
def to_s
"<#{@lat}, #{@long}>"
end
end
$ ./example-3.rb
line ./example-3.rb:7 false
c-call ./example-3.rb:7 inherited Class
c-return ./example-3.rb:7 inherited Class
class ./example-3.rb:7 false
line ./example-3.rb:8 false
c-call ./example-3.rb:8 method_added Module
c-return ./example-3.rb:8 method_added Module
line ./example-3.rb:12 false
c-call ./example-3.rb:12 method_added Module
c-return ./example-3.rb:12 method_added Module
end ./example-3.rb:7 false
If we want to trace something useful it's probably time to change the format. If we're interested in tracing execution, file/line information is usually just noise,
return/
c-return/
end would be far better represented by indentation, and we're really interested in receiver (
self), not its class.
$indent = 0
set_trace_func proc { |event, file, line, id, binding, classname|
if event == "line"
# Ignore
elsif %w[return c-return end].include?(event)
$indent -= 2
else
if event == "class"
STDERR.printf "%*s%s %s\n", $indent, "", event, eval("self", binding)
else
STDERR.printf "%*s%s %s.%s\n", $indent, "", event, eval("self", binding), id
end
$indent += 2 if %w[call c-call class].include?(event)
end
}
class Geolocation
def initialize(lat, long)
@lat = lat
@long = long
end
def to_s
"<#{@lat}, #{@long}>"
end
end
a = Geolocation.new(51.12, 17.03)
puts a
p a
$ ./example-4.rb >/dev/null
c-call Object.inherited
class Geolocation
c-call Geolocation.method_added
c-call Geolocation.method_added
c-call Geolocation.new
call <, >.initialize
c-call main.puts
call <51.12, 17.03>.to_s
c-call 51.12.to_s
c-call 17.03.to_s
c-call #<IO:0xb7c80fc0>.write
c-call #<IO:0xb7c80fc0>.write
c-call main.p
c-call <51.12, 17.03>.inspect
c-call 17.03.inspect
c-call 17.03.to_s
c-call 51.12.inspect
c-call 51.12.to_s
c-call #<IO:0xb7c80fc0>.write
c-call #<IO:0xb7c80fc0>.write
There's still a minor quirk in the output, as
Geolocation#to_s is called by the tracer when
Geolocation#initialize starts, and before it can be meaningfully printed. In this case we simply got garbage
<, >, but some objects raise exceptions if printed before initialization.
require 'complex'
$indent = 0
set_trace_func proc { |event, file, line, id, binding, classname|
if event == "line"
# Ignore
elsif %w[return c-return end].include?(event)
$indent -= 2
else
obj = eval("self", binding)
if event == "class"
STDERR.printf "%*s%s %s\n", $indent, "", event, obj
else
obj = "<#{obj.class}##{obj.object_id}>" if id == :initialize
STDERR.printf "%*s%s %s.%s\n", $indent, "", event, obj, id
end
$indent += 2 if %w[call c-call class].include?(event)
end
}
a = Complex.new(11.0, -5.0)
b = Complex.new(2.0, 13.5)
c = a * b
$ ./example-5.rb
c-call Complex.new
call <Complex#-605829048>.initialize
c-call 11.0.kind_of?
c-call 11.0.kind_of?
c-call -5.0.kind_of?
c-call -5.0.kind_of?
c-call Complex.new
call <Complex#-605832038>.initialize
c-call 2.0.kind_of?
c-call 2.0.kind_of?
c-call 13.5.kind_of?
c-call 13.5.kind_of?
call 11.0-5.0i.*
c-call 2.0+13.5i.kind_of?
c-call 11.0.*
c-call -5.0.*
c-call 22.0.-
c-call 11.0.*
c-call -5.0.*
c-call 148.5.+
call 11.0-5.0i.Complex
c-call 138.5.==
call 89.5.real
call 138.5.imag
c-call 89.5.-
call 89.5.imag
call 138.5.real
c-call 0.+
c-call Complex.new
call <Complex#-605842188>.initialize
c-call 89.5.kind_of?
c-call 89.5.kind_of?
c-call 138.5.kind_of?
c-call 138.5.kind_of?
Many otherwise hard to find bugs become trivial with a custom tracer, grep, and some Ruby one-liners to massage the logs.
Smoke and mirrors
set_trace_func is useful not just for debugging, but also for all kinds of magic.
Binding.of_caller, which unfortunately doesn't work any more, was implemented with
set_trace_func.
magic/help uses
set_trace_func to provide convenient help access in
irb:
irb> help { STDERR.write }
--------------------------------------------------------------- IO#write
ios.write(string) => integer
------------------------------------------------------------------------
Writes the given string to _ios_. The stream must be opened for
writing. If the argument is not a string, it will be converted to a
string using +to_s+. Returns the number of bytes written.
count = $stdout.write( "This is a test\n" )
puts "That was #{count} bytes of data"
_produces:_
This is a test
That was 15 bytes of data
magic/help works by setting a
set_trace_func handler, executing the passed block, and then aborting execution by
throw after first interesting event. This means that calling
help { rm_rf "/" } should be perfectly safe.
One nasty case I found while developing
magic/help was inconsistent traces when functions are called with wrong number of arguments.
For functions implemented in C, even with explicit number of arguments specified, Ruby always issues
c-call before calling
ArgumentError.new. On the other hand for Ruby functions,
ArgumentError.new is issued, then
return from the function, but
call never happens.
To illustrate, tracing C function
STDERR.write gives:
c-call #<IO:0xb7c98fa8>.write
c-call ArgumentError.new
c-call #<ArgumentError: ArgumentError>.initialize
c-return #<ArgumentError: wrong number of arguments (0 for 1)>.initialize
c-return ArgumentError.new
c-call #<ArgumentError: wrong number of arguments (0 for 1)>.backtrace
c-return #<ArgumentError: wrong number of arguments (0 for 1)>.backtrace
c-call #<ArgumentError: wrong number of arguments (0 for 1)>.set_backtrace
c-return #<ArgumentError: wrong number of arguments (0 for 1)>.set_backtrace
raise #<IO:0xb7c98fa8>.write
c-return #<IO:0xb7c98fa8>.write
On the other hand tracing Ruby function
FileUtils.remove_entry gives:
# "call FileUtils.remove_entry" never happens !
c-call ArgumentError.new
c-call #<ArgumentError: ArgumentError>.initialize
c-return #<ArgumentError: wrong number of arguments (0 for 1)>.initialize
c-return ArgumentError.new
c-call #<ArgumentError: wrong number of arguments (0 for 1)>.backtrace
c-return #<ArgumentError: wrong number of arguments (0 for 1)>.backtrace
c-call #<ArgumentError: wrong number of arguments (0 for 1)>.set_backtrace
c-return #<ArgumentError: wrong number of arguments (0 for 1)>.set_backtrace
raise FileUtils.remove_entry
# "return FileUtils.remove_entry" does happen.
return FileUtils.remove_entry
In both cases checking number of arguments happens before the call.
IO#write in defined as 1-argument function:
rb_define_method(rb_cIO, "write", io_write, 1);
New versions of
magic/help handle this case too - if the first event is
c-call to
ArgumentError.new,
magic/help waits for the first
return event (if any) instead of instantly aborting execution of the passed block. Just
grab the new version and enjoy the magical help.
I ported Judy patch to Ruby 1.8.6. Speedups are comparable to ones in 1.8.5. On benchmarks from YARV (score is mean of 3 middle times from 5 runs):
