Exploring TracePoint in Ruby — Part Two — Events
Now that we have a brief overview of the basics of TracePoint, let’s take a look at all of the events we can monitor and what we might do with them.
This article is rated at a difficulty of 3 out of 5, and requires some prerequisite knowledge in Ruby:
<< Previous | Next >>
The Helpers
We’ll be using a few helper methods from last time, extract_arguments
and extract_locals
:
def extract_arguments(trace)
param_names = trace.parameters.map(&:last)
param_names.map { |n| [n, trace.binding.eval(n.to_s)] }.to_h
enddef extract_locals(trace)
local_names = trace.binding.local_variables
local_names.map { |n|
[n, trace.binding.local_variable_get(n)]
}.to_h
end
This will allow us to see a bit more context for each event by allowing us to see the current local variables and current arguments in the context of the event.
If you happen to be using Pry, extracting locals may be incredibly noisy. To avoid this, use this version of the method instead:
def extract_locals(trace)
local_names = trace.binding.local_variables.reject { |v|
v.to_s[0] == '_'
}local_names.map { |n|
value = trace.binding.local_variable_get(n)
[n, value.is_a?(TracePoint) ? :trace_point : value]
}.to_h
end
It will get rid of Pry variables starting with underscores, and avoid capturing the tracepoint we just defined.
I’ll be refreshing my REPL after each event section to keep the output clear, and the above functions are defined in my ~/.pryrc
so they’re present when I start up Pry.
The Events
TracePoint allows us to monitor specific events in Ruby’s execution lifecycle. To start with, what are those events? The official documentation is available, but let’s define them in our own words for the sake of this tutorial.
We’ll look at each in turn later in the article, but a short list is a good place to start:
line
: Each literal line of code in the program.class
: Aclass
ormodule
is defined.end
: Aclass
ormodule
definition ends.call
: The invocation of a Ruby method.c_call
: The invocation of a function defined in C, likeputs
and other core methods.return
: The return of a Ruby method.c_return
: The return of a function defined in C, much likec_call
above.raise
: An exception occurrence.b_call
: When a block function is called.b_return
: The return of a block function.thread_begin
: When a thread starts.thread_end
: When a thread ends, or rather joins.fiber_switch
: When a fiber switches.
With that out of the way, shall we begin?
Line Event
:line
This event triggers on every line of a Ruby program, so be careful with it or you’re going to have quite the noisy trace!
We can start by defining a TracePoint
that responds to a line event:
line_event = TracePoint.new(:line) do |t|
p [t.lineno, t.method_id, extract_locals(t)]
end
Using the fact that an instance of a TracePoint can call enable with a block for scoped execution, we can give that a try:
line_event.enable do
a = 1
a + 2
end[26, :__pry__, {:a => nil, :line_event => :trace_point}]
[27, :__pry__, {:a => 1, :line_event => :trace_point}]
=> 3
Now note that your line numbers are probably going to be different than mine depending on when and where you execute this code.
Watching for a Variable
What might be interesting here is that a
isn’t able to be extracted until the line event directly after it was assigned. Using this we might even be able to set watchers using TracePoint
on a specific value either being present or being set:
a_is_5_trace = TracePoint.new(:line) do |t|
local_variables = extract_locals(t)next false unless local_variables[:a] == 5puts <<~MESSAGE
Here's the context when 'a' became 5 on line #{t.lineno}:#{local_variables}
MESSAGE
enda_is_5_trace.enable do
b = 3
c = 4
a = 5
d = 6
endHere's the context when 'a' became 5 on line 29:
{:b=>3, :c=>4, :a=>5, :d=>nil, :a_is_5_trace=>:trace_point}
=> 6
This can be really handy for finding when a particularly naughty code branch is setting variables it’s not supposed to know about, especially when used in conjunction with some of the other TracePoint
instance methods we learned about in the last article.
Note: TracePoint
parameters
are not accessible in:line
events. You can only get locals. On occasion you’ll see errors about a certain type of method not being supported for a certain event.At the moment these are not documented well, but will be in the future.
Now there are several interesting things one could do by watching for variable changes, but that’s outside the scope of this article. Let me know if you’re interested in an extended part with some extra fun!
Class Event
:class
This event triggers on the creation of a class.
Let’s start by creating a TracePoint to watch for one:
class_tracer = TracePoint.new(:class) do |t|
puts <<~MESSAGE
Class or Module '#{t.self}' was defined at
`#{t.path}:#{t.lineno}`
MESSAGE
end
Say we wanted to know where a class got defined, we can use the above trace to get a pretty good idea:
class_tracer.enable do
class FooBar
def a; end
endmodule BazBat
def b; end
end
endClass or Module 'FooBar' was defined at
`(pry):6`
Class or Module 'BazBat' was defined at
`(pry):7`
Personally I find this mildly confusing that TracePoint#self
happens to contain the class or module name instead of TracePoint#defined_class
which instead returns nil
.
This can be handy for when you want to find out where a particular class or module was defined without having to hunt through source code to get it.
Class End Event
:end
This event triggers on the creation of a class.
Let’s start by creating a TracePoint:
class_tracer = TracePoint.new(:end) do |t|
puts <<~MESSAGE
Class or Module '#{t.self}' was ended at
`#{t.path}:#{t.lineno}`
MESSAGE
end
and call it like so:
class_tracer.enable do
class FooBar
def a; end
endmodule BazBat
def b; end
end
endClass or Module 'FooBar' was ended at
`(pry):6`
Class or Module 'BazBat' was ended at
`(pry):7`
Admittedly I can’t think of a use for this event at the moment, but would be interested to find out from others what they’ve found.
Call Event
:call
Call events trigger on any method call, and are one of the most useful events to monitor. The have access to arguments and a whole slew of other interesting data we can use for debugging.
Let’s say we wanted to watch for calls of a method called testing
:
def testing(a, b, c)
d = 5
a + b + c + d
endtesting_call_trace = TracePoint.new(:call) do |t|
# We only want to monitor our testing method
next unless t.method_id == :testingp args: extract_arguments(t), locals: extract_locals(t)
end
and call it like so:
testing_call_trace.enable do
testing(1, 2, 3)
end{:args=>{:a=>1, :b=>2, :c=>3}, :locals=>{:a=>1, :b=>2, :c=>3, :d=>nil}}
Being able to get ahold of arguments is really useful, so much so that one could potentially do very bad things with it. For now though, consider what one might be able to do by getting the arguments of this function:
def deep_defaults(a: {b: [:c, :d]})
a + b + c + d
end
It’ll crash (for now), but that could be interesting…
It should be noted the directly above is a really black magic experiment, the author would simply like you to enjoy a similar rabbit hole
C Call Event
:c_call
The first, and fairest question here is what’s the difference between this and a :call
event? :c_call
is an event that’s in a C-extension or base Ruby code, like puts
. Let’s try and capture a puts
with :call
to see this in action:
puts_call_trace = TracePoint.new(:call) do |t|
if t.method_id == :puts
p [t.lineno, t.method_id, extract_locals(t)]
end
endputs_call_trace.enable do
puts "OHAI!"
endOHAI!
=> nil
So we didn’t see our event register, but if we instead use :c_call
:
puts_c_call_trace = TracePoint.new(:c_call) do |t|
if t.method_id == :puts
p [t.lineno, t.method_id, extract_locals(t)]
end
endputs_c_call_trace.enable do
puts "OHAI!"
end[49, :puts, {:puts_c_call_trace=>:trace_point, :puts_call_trace=>:trace_point, :e=>nil}]
[49, :puts, {:puts_c_call_trace=>:trace_point, :puts_call_trace=>:trace_point, :e=>nil}]
OHAI!
=> nil
Now if you wanted to just get both, it’s of benefit to know that TracePoint.new
takes multiple arguments:
TracePoint.new(:call, :c_call)
So if you’re trying to capture multiple event types you can specify them just like that. You can also give no arguments and have it send every event.
It should be noted that arguments can’t be fetched from :c_call
events.
Return Event
:return
Return events come in a lot of handy when we want to see exactly where a specific value was returned. Much like its counterpart :c_return
, it only gets part of the picture, so you’ll frequently see both put into a TracePoint
declaration.
It comes with an especially handy TracePoint
method called return_value
that’s not accessible in non-return events.
Let’s take a look at a way to catch nil
returns:
def nil_on_odd(n)
d = 10
n.odd? ? nil : n + d
endnil_return_trace = TracePoint.new(:return) do |t|
next unless t.return_value == nilp({
locals: extract_locals(t),
args: extract_arguments(t),
ret_val: t.return_value
})
endnil_return_trace.enable do
nil_on_odd(2)
nil_on_odd(3)
end{:locals=>{:n=>3, :d=>10}, :args=>{:n=>3}, :ret_val=>nil}
=> nil
We can get our local values and arguments too while we’re at it, and perhaps even the method_id
too if we needed it. Return events are particularly useful when you want to see the full context of a method at the point a value is returned.
C Return Event
:c_return
Much like its sibling event, :c_call
, :c_return
will only activate on the return event of a c method returning. As such we won’t get too much into it, except to say that your life will be substantially easier by specifying both the return event types when creating a new TracePoint
:
trace_returns = TracePoint.new(:return, :c_return) { ... }
Raise Event
:raise
A :raise
event is one triggered on an exception, and will allow us to see the full context around an exception happening. This includes stuffing a binding.pry
or binding.irb
in there too. You could probably even emulate parts of pry-rescue
with it.
Let’s take a look at a quick example using that:
def raise_on_odd(n)
d = 20
raise 'a ruckus' if n.odd?
n + d
endexception_trace = TracePoint.new(:raise) do |t|
p locals: extract_locals(t), exception: t.raised_exception
endexception_trace.enable do
raise_on_odd(2)
raise_on_odd(3)
end{:locals=>{:n=>3, :d=>20}, :exception=>#<RuntimeError: a ruckus>}
RuntimeError: a ruckus
from (pry):81:in `raise_on_odd'
It should be noted that arguments are not available in this context, so we would have to rely on locals to see what might be going on in this area.
Block Call Event
:b_call
A :b_call
event will trigger whenever a block is called. Now what precisely qualifies as a block? Let’s take a look:
def maps(list, &fn)
list.reduce([]) { |a, v| a << yield(v) }
endblock_trace = TracePoint.new(:b_call) do |t|
p({
line: t.lineno,
method_name: t.method_id,
locals: extract_locals(t),
args: extract_arguments(t)
})
endblock_trace.enable do
maps([1,2,3], &:even?)
end{
line: 12,
method_name: :__pry__,
locals: { block_trace: :trace_point },
args: {},
}{
line: 2,
method_name: :maps,
locals: {
a: [],
v: 1,
list: [1, 2, 3],
fn: #<Proc:X(&:even?)>
},
args: { a: [], v: 1 },
}{
line: 2,
method_name: :maps,
locals: {
a: [false],
v: 2,
list: [1, 2, 3],
fn: #<Proc:X(&:even?)>
},
args: { a: [false], v: 2 },
}{
line: 2,
method_name: :maps,
locals: {
a: [false, true],
v: 3,
list: [1, 2, 3],
fn: #<Proc:X(&:even?)>
},
args: { a: [false, true], v: 3 },
}
Remember that reduce
call up above in our maps
function? That counts as a block too, meaning we just got a nice little look into each step of map
implemented in reduce while we were at it!
It’s imperative to remember that when TracePoint
captures something, it really does mean everything, which is why we try and limit its scope with early returns and using the block form of enable
.
Block Return Event
:b_return
Like its counterpart return events, :b_return
captures the return event of a block. Let’s take a look back at our map example, except this time we’ll make it into flat_map
instead just for the novelty of it. We’ll also be using cleaned up pp
output instead as this output is getting a bit hairy otherwise:
def flat_maps(list, &fn)
list.reduce([]) { |a, v| a.push *yield(v) }
endblock_trace = TracePoint.new(:b_return) do |t|
pp({
line: t.lineno,
method_name: t.method_id,
locals: extract_locals(t),
args: extract_arguments(t),
ret_value: t.return_value
})
endblock_trace.enable do
flat_maps([1,2]) { |v| [v - 1, v + 1] }
end{
line: 14,
method_name: :__pry__,
locals: {v: 1, block_trace: :trace_point},
args: {v: 1},
ret_value: [0, 2]
}{
line: 2,
method_name: :flat_maps,
locals: {
a: [0, 2],
v: 1,
list: [1, 2],
fn: #<Proc:0x00007fe70425f510@(pry):14>
},
args: {a: [0, 2], v: 1},
ret_value: [0, 2]
}{
line: 14,
method_name: :__pry__,
locals: {v: 2, block_trace: :trace_point},
args: {v: 2},
ret_value: [1, 3]
}{
line: 2,
method_name: :flat_maps,
locals: {
a: [0, 2, 1, 3],
v: 2,
list: [1, 2],
fn: #<Proc:0x00007fe70425f510@(pry):14>
},
args: {a: [0, 2, 1, 3], v: 2},
ret_value: [0, 2, 1, 3]
}{
line: 15,
method_name: :__pry__,
locals: {block_trace: :trace_point},
args: {},
ret_value: [0, 2, 1, 3]
}=> [0, 2, 1, 3]
This is especially useful if you have a particularly hairy function block you need to debug step by step to see what it’s doing, especially if it’s a larger reduce function you want to see inside of.
Thread Begin and End Event
:thread_begin
/ :thread_end
These events trigger on the beginning and ending of a thread. As I don’t do an incredible amount with threads this won’t be a very detailed section. They don’t appear to have access to a local binding or most of the other things we’ve seen in above sections except for basic location information.
We’ll save this section for later, as I have a feeling it’ll require a good amount of research on my part to figure out. Suggestions and ideas welcome!
Fiber Switch Event
:fiber_switch
As with threads, we’ll save this for a later section about parallel tracing.
Wrapping Up
TracePoint can be a dense subject, so we’re going to break this up into a few articles to make it easier to follow. Part Two was meant to cover each event TracePoint can watch. The next parts are:
Part Three — Aphyr’s Black Magic
Covering an old classic Ruby post abusing set_trace_func
to do bad things to Ruby. We’re going to modernize some of it to play with some of the more out there features of TracePoint
.
Part Four — Advent of TraceSpy
TracePoint is powerful, but it can be hard to use. Trace Spy is a gem that was written to make it a bit easier to use in the wild with a fluent interface based on Pattern Matching from Qo.
We’ll explore writing fluent wrappers, documentation, and making meta-tools to help us do our jobs as developers more effectively.
Part Five — Giving TraceSpy some Color
Now that we have a fluent wrapper to use, how about some pretty output to make debugging even easier? Let’s take a look into providing utilities to see our local contexts more clearly and make debugging even easier!
We’re going to be going through some deeper parts of Ruby in these next few series in 2019, so buckle up because we’re going to have some fun.
<< Previous | Next >>