Ruby has introduced the TracePoint API with the release of Ruby 2.0.
Earlier, there was a similar tool that let you track operations in any
Ruby program called
set_trace_func. However, using it was really slow
and ugly. This new TracePoint API aims to replace it.
What is “tracing”? Why is
set_trace_func slow? Why is
To understand how these two commands work, we need to understand how the compiler compiles a Ruby program and generates code that the VM then executes. The program that we will be using is:
Let’s have a look at the output of the compiler for the Ruby program mentioned above. To get the disassembled output, the command to run is:
The output of the command is:
Note that the disassembled output is just a human-readable output.
The lines starting with a number represent a single VM instruction each.
These instructions are implemented inside a file called
lines that start with
== disasm represent what are known as
These labels are useful in identifying which Ruby method call or
instruction the corresponding set of VM instructions pertain to. One
stack-frame in Ruby corresponds to the set of instructions between — and
including — a
leave. These two instructions are appended
to ends of the stackframe by the compiler, and they perform certain
trace instructions here and the number after that
instruction. This number is the decimal representation of a Ruby event.
Erm…event, you say?
Events and trace
Ruby emits an event every time the VM’s state changes. The full list of
events in Ruby (version
2.1.0-p0) consists of 25 events and are
defined inside of
ruby.h. However, the set of events that
corresponding to the example Ruby program above are a subset of the
1 2 3 4 5 6 7 8 9 10 11 12 /* traditional set_trace_func events */ #define RUBY_EVENT_NONE 0x0000 #define RUBY_EVENT_LINE 0x0001 #define RUBY_EVENT_CLASS 0x0002 #define RUBY_EVENT_END 0x0004 #define RUBY_EVENT_CALL 0x0008 #define RUBY_EVENT_RETURN 0x0010 #define RUBY_EVENT_C_CALL 0x0020 #define RUBY_EVENT_C_RETURN 0x0040 #define RUBY_EVENT_RAISE 0x0080 #define RUBY_EVENT_ALL 0x00ff
Each of the
RUBY_EVENT_* constants correspond to a hexadecimal number.
Using this list, we can understand what the
arguments in the disassembled output correspond to.
In the above example, there are a total of 8
trace instructions. Let’s
go through them one-by-one.
If you were thinking that the
trace instruction might be an
event emitting routine, it’s kind of the reverse in reality. When ever
the VM encounters a
trace event, all the event hooks that were defined
for that event get executed. Open up the file
insns.def and locate the
trace instruction definition. There’s just one call — well, ignoring
all the Dtrace-specific methods — which is,
trace instructions with an argument of
1 correspond to a
RUBY_EVENT_LINE event. This event is indicates that a new line of Ruby
code has been encountered. All event hooks registered for the event
RUBY_EVENT_LINE are executed when the VM
encounters this particular
You can see that, in each of the labels, there is a minimum number of
RUBY_EVENT_LINE event. An argument of 2 corresponds to the event
RUBY_EVENT_CLASS and an argument of 4 corresponds to the event
RUBY_EVENT_END. That means, inside the
class:A label, this is what
- Event signalling a class entry.
- Event signalling a new ruby line that has been encountered.
- Event signalling that the
endstatement for the class definition has been reached.
Finally, in the last label (
to_string), the trace arguments of 8 and
16 correspond to
leave VM instruction simply pops the stack frame and is essential
to start of execution of the next instruction. There will be
leave per instruction sequence but there can be multiple
trace instructions as we already saw in the example above.
The events emitted by the
trace instruction can be utilized by some
TracePoint API register event hooks that just call the
Proc that you
Here lies the reason why
set_trace_func is slow. As mentioned
trace instruction simply executes all the events that are
TracePoint API register event
hooks based on the configuration your provide to them. The usage of
these two libraries can be found on the Rubydoc website. The way you
use them differs slightly. In the case of
TracePoint, the event to
listen to is specified upfront — that said, if no event is specified,
the library adds a hook pertaining to all events — and in the
set_trace_func a proc is passed as an argument. This
argument gets called every time a Ruby event occurs. That’s
right, for every event, the argument gets called. In addition to
that, the binding information when the event is instantiated is
also computed and that slows down the tracing even more. In the case of
TracePoint though, you get access to a tracepoint object that can be
used to fetch the data that’s required and it won’t compute the extra
information unless it’s requested. This not only improves the API, it
also improves the performance of tracing.
trace instruction generation can be disabled by adding the
following lines to the program and
eval-ing the code under question.
For example, in the case of the program at the beginning, to disable
trace instruction, this does it:
The output of this program would be:
As you can see, this does not have the
There are a lot of tooling support features that are being added to
the latest Ruby. In fact, there are new TracePoint events added to Ruby
2.2.0 that were not present on 2.1.0. Tooling is a really important part
for the growth and stability of a language. TracePoint’s C-API
authors who write profilers like
ruby-prof to use a much
simpler API and support more internal events which are accessible only
via the C-API. And there has been a steady improvement on the quality
and performance of the profilers which is always a good thing.