Skip to content

TracePoint sees every call and return

Level: 301 · someone building a profiler, a coverage tool or a "who called this?" probe

One line: TracePoint.new(:call, :return) { |tp| … }.enable { … } reports every method the VM enters and leaves — name, class, return value, exception — without touching the traced code; Python's sys.settrace and sys.setprofile do the same job frame by frame, and both switch themselves off while the hook runs.

The VM raises an event at each interesting moment: :call and :return for Ruby methods, :c_call and :c_return for methods written in C, :line for each line executed, :raise for an exception, :b_call/:b_return for blocks, :class/:end for class bodies. A TracePoint subscribes to a list of them; inside the hook it exposes event, method_id, defined_class, self, parameters, return_value (only in a return event), raised_exception (only in :raise), binding, and the path and lineno that this page never prints. Rows 1–4 trace double(3) and show the nesting as a sequence: double is entered, add is entered, add returns 6, double returns 6. helper is called in the same block and is absent because it is defined on Object, and the hook keeps only events whose defined_class is ours. The block form of enable switches the trace off afterwards (row 5), and enable/disable return the previous state (row 13).

The rest of the rows are the details a real tool needs. One call of a two-line method is three events — :call, :line, :return (row 6). Array#size is C, so it fires :c_call, and its defined_class is Array (row 7). :raise reports the exception's class and the method it happened in, even though the exception is rescued a moment later (row 8). enable(target: method) narrows the trace to one method's instructions, so double calling add shows only add (row 9). A :return event carries the value and the method's parameters (row 10). A class method is defined on the class's singleton class, so a filter on defined_class == Calculator misses it; compare with Calculator.singleton_class and self is the class (row 11). Inside the hook tracing is suspended, so a hook that calls a traced method does not recurse (row 12). Enabling a trace has a cost — the JIT and the method caches treat a traced instruction sequence as changed — so real profilers narrow with target: and disable as soon as they can. (Not machine-checked here.)

Verified output of tracepoint_rb.rb — regenerated by tools/run_examples.py, never hand-typed.

 1. double(3) traced; helper is not ours                 [:call, :double, nil]
 2.                                                      [:call, :add, nil]
 3.                                                      [:return, :add, 6]
 4.                                                      [:return, :double, 6]
 5. tp.enabled? after the block form                     false
 6. events for one add(1, 2): call, line, return         [:call, :line, :return]
 7. [1, 2, 3].size is a C method                         [[:c_call, :size, Array], [:c_return, :size, Array]]
 8. :raise inside fail_hard                              [[:raise, ArgumentError, :fail_hard]]
 9. enable(target: add) while double(2) runs             [[:call, :add], [:return, :add]]
10. :return carries return_value and parameters          [[:add, 3, [[:req, :a], [:req, :b]]]]
11. Calculator.create: method_id, singleton_class?, self [[:create, true, Calculator]]
12. calls made inside the hook are not traced            [:add]
13. [tp.enable, tp.enabled?, tp.disable, tp.enabled?]    [false, true, true, false]

Reading the output

Rows 1–4 are one traced call, read top to bottom as a call stack growing and shrinking; the third element is return_value for a :return event and nil for a :call. Row 5 is false because the block form re-disables. Row 6: three events for one call. Row 7: the two C-method events, with Array as their class. Row 8: the exception's class and where it was raised. Row 9: target: filtering — double ran, only add was reported. Row 10: the value 3 and the two required parameters. Row 11: singleton_class? is true and self is Calculator. Row 12: a single :add although the hook itself called add again. Row 13: enable returned false (it was off), enabled? became true, disable returned true (it was on), and enabled? is false again.

Compared with Python

sys.settrace(fn) installs a global trace function that receives a 'call' event for every Python frame; if it returns a function, that becomes the local trace for the frame and receives its 'line', 'return' and 'exception' events. There is no class to filter on, so the twin keeps frames whose frame.f_code.co_name is in a set of our names — rows 1–4 are the same four events, and helper is dropped by the same kind of filter. Row 5 is the twin of enabled?: sys.gettrace() is None after settrace(None). One call of add is 'call', 'line', 'return' (row 6), exactly as in Ruby.

C functions are invisible to settrace; sys.setprofile sees them as 'c_call' and 'c_return' with the function object as the argument (row 7). An exception is an 'exception' event in the frame that raised it, followed by that frame's 'return' with None (row 8) — Ruby reports :raise and then a normal :return too, but this page's Ruby row asked only for :raise. Narrowing to one function is done by returning a local trace function only for add's frame (row 9). The 'return' event's argument is the return value, and the parameter names come from the code object, self included (row 10). A classmethod's frame has cls as its first local (row 11). Row 12 is the same re-entrancy rule: CPython disables tracing while the trace function runs. Python 3.12 added sys.monitoring (PEP 669), a cheaper per-tool event API on which sys.settrace is now implemented; its constants exist on both CI Pythons but its event stream is a different design, so it stays in prose here. (Not machine-checked here.)

Verified output of tracepoint_py.py — regenerated by tools/run_examples.py, never hand-typed.

 1. double(3) traced; helper is not ours                 ('call', 'double', None)
 2.                                                      ('call', 'add', None)
 3.                                                      ('return', 'add', 6)
 4.                                                      ('return', 'double', 6)
 5. sys.gettrace() is None after settrace(None)          True
 6. events for one add(1, 2): call, line, return         ['call', 'line', 'return']
 7. len([1, 2, 3]) is a C function (sys.setprofile)      [('c_call', 'len', 'builtin_function_or_method'), ('c_return', 'len', 'builtin_function_or_method')]
 8. 'exception' inside fail_hard, then its 'return'      [('exception', 'fail_hard', 'ValueError'), ('return', 'fail_hard', None)]
 9. local trace for add only while double(2) runs        [('call', 'add'), ('return', 'add')]
10. 'return' carries the value; co_varnames the parameters [('add', 3, ('self', 'a', 'b'))]
11. Calculator.create(): co_name, the cls local          [('create', 'Calculator')]
12. calls made inside the trace function are not traced  ['add']
13. [gettrace() is t after settrace(t), is None after]   [True, True]

Try it

  1. Write a call-count profiler: profile(klass) { … } enables a TracePoint for :call while the block runs, counts calls per method_id for that one class, and prints the tally sorted by name — no timings, so the output is identical on every run.
  2. Use :raise to log every exception raised inside a block, rescued or not, as [class, method] pairs; run a block that raises and rescues three different exception classes and print the log. Then subscribe to :rescue as well and pair each raise with the rescue that caught it.
Solution to 1

tracepoint_kata_rb.rb in full — pasted here by tools/run_examples.py from the file CI runs.

# Kata: a call-count profiler. Enable a TracePoint for :call while a block
# runs, count calls per method for one class of our own, and print the tally
# sorted by name -- no timings, so the output is the same on every run.

class Shape
  def initialize(sides) = @sides = sides
  def perimeter(side) = @sides * side
  def area(side) = side * side * factor
  def factor = @sides == 4 ? 1 : 0.5
end

def profile(klass)
  counts = Hash.new(0)
  tp = TracePoint.new(:call) { |t| counts[t.method_id] += 1 if t.defined_class == klass }
  tp.enable { yield }
  counts.sort.each { |name, n| puts format("%-10s called %d time%s", name, n, n == 1 ? "" : "s") }
end

profile(Shape) do
  square = Shape.new(4)
  triangle = Shape.new(3)
  square.perimeter(2)
  square.area(2)
  triangle.area(2)
  triangle.area(3)
end

Verified output of tracepoint_kata_rb.rb — regenerated by tools/run_examples.py, never hand-typed.

area       called 3 times
factor     called 3 times
initialize called 2 times
perimeter  called 1 time

See also