/ Tags: RUBY 3 / Categories: RUBY

TracePoint in Practice — Instrument Your Code Without Reaching for a Gem

Something in a Rails boot sequence is defining a method you can’t find. A query is being issued from a code path you can’t identify. An exception is swallowed six layers down and you’d like to know where it was raised, not where it was rescued. These are all the same problem — you need visibility into the runtime rather than the source — and Ruby has had the tool for it in the standard library since 2.0.

What TracePoint Does


TracePoint lets you register a callback that fires on specific VM events: a method being called, a line being executed, a class being defined, an exception being raised. No gem, no monkey patching, no changes to the code you’re inspecting.

Example:

trace = TracePoint.new(:call) do |tp|
  puts "#{tp.defined_class}##{tp.method_id} at #{tp.path}:#{tp.lineno}"
end

trace.enable
# ... code you want to observe
trace.disable

Or scoped to a block, which is almost always what you want:

TracePoint.new(:call) { |tp| puts tp.method_id }.enable do
  Order.find(42).total
end

The block form disables the trace automatically, including on exception. Leaving a trace enabled by accident will make the process crawl.

The Events Worth Knowing


Event Fires when
:call A Ruby method is called
:return A Ruby method returns
:c_call / :c_return A C-implemented method is called / returns
:line A new source line is about to execute
:class / :end A class or module definition opens / closes
:raise An exception is raised
:b_call / :b_return A block is entered / left
:thread_begin / :thread_end A thread starts / finishes

:line is the most expensive by a wide margin — it fires for essentially every statement in the program. Use it only inside a tightly scoped block.

Inside the handler, the TracePoint object exposes context:

tp.event          # => :call
tp.path           # => "/app/models/order.rb"
tp.lineno         # => 47
tp.method_id      # => :total
tp.defined_class  # => Order
tp.self           # => the receiver
tp.binding        # => the binding at that point
tp.return_value   # => only valid on :return / :c_return
tp.raised_exception # => only valid on :raise

tp.binding is the powerful one — it gives you local variables at that point in execution, which is how you build a poor man’s debugger.

Finding Where a Method Gets Defined


The problem that sends most people to TracePoint in the first place. A method exists at runtime and grep finds nothing, because a gem generated it.

Example:

def trace_method_definition(target_method)
  TracePoint.new(:c_call, :call) do |tp|
    next unless %i[define_method attr_accessor attr_reader method_missing].include?(tp.method_id)

    caller_location = caller_locations(1, 5)
    puts "#{tp.method_id} invoked from:"
    caller_location.each { |loc| puts "  #{loc}" }
  end
end

A more direct approach for a known method name:

Example:

TracePoint.new(:call) do |tp|
  next unless tp.method_id == :total_with_tax

  puts "Defined at: #{tp.path}:#{tp.lineno} in #{tp.defined_class}"
  tp.disable
end.enable

Order.new.total_with_tax

Between this and Order.instance_method(:total_with_tax).source_location, one of them will tell you. source_location is cheaper — try it first; fall back to TracePoint when it returns nil, which is the signal that the method was built at runtime.

Catching Every Raise, Including Swallowed Ones


An exception rescued and turned into nil three frames down leaves no trace in your logs. :raise fires at the raise site, before any rescue runs.

Example:

tracer = TracePoint.new(:raise) do |tp|
  ex = tp.raised_exception
  next if ex.is_a?(StopIteration)   # normal control flow in Enumerators

  warn "RAISED #{ex.class}: #{ex.message}"
  warn "  at #{tp.path}:#{tp.lineno}"
end

tracer.enable do
  begin
    JSON.parse("not json")
  rescue JSON::ParserError
    nil   # swallowed — but we saw it
  end
end

Filter aggressively. Rails raises internally as part of normal operation — ActiveRecord::RecordNotFound inside find_by, StopIteration in enumerators — so an unfiltered :raise trace during a request produces hundreds of lines of noise.

Building a Call-Count Profiler in Fifteen Lines


Example:

class CallCounter
  def initialize(path_filter:)
    @counts = Hash.new(0)
    @filter = path_filter
    @trace = TracePoint.new(:call) do |tp|
      next unless tp.path.include?(@filter)
      @counts["#{tp.defined_class}##{tp.method_id}"] += 1
    end
  end

  def measure
    @trace.enable { yield }
    @counts.sort_by { |_, count| -count }.first(20).to_h
  end
end

Example:

CallCounter.new(path_filter: "/app/").measure do
  InvoiceBuilder.new(account).build
end
# => { "LineItem#taxable?" => 4820, "Order#total" => 1204, ... }

Four thousand calls to taxable? for one invoice is the kind of finding that doesn’t show up in a wall-clock profiler, because each call is fast. Call counts and time-based sampling answer different questions and both are worth having.

Timing Method Execution


Example:

timings = Hash.new { |h, k| h[k] = [] }
starts = {}

call_trace = TracePoint.new(:call) do |tp|
  next unless tp.path.include?("/app/services/")
  starts[[tp.defined_class, tp.method_id]] = Process.clock_gettime(Process::CLOCK_MONOTONIC)
end

return_trace = TracePoint.new(:return) do |tp|
  key = [tp.defined_class, tp.method_id]
  started = starts.delete(key) or next
  timings[key] << Process.clock_gettime(Process::CLOCK_MONOTONIC) - started
end

call_trace.enable
return_trace.enable
InvoiceBuilder.new(account).build
call_trace.disable
return_trace.disable

timings.map { |k, v| [k.join("#"), v.sum.round(4), v.size] }
       .sort_by { |_, total, _| -total }
       .first(10)

Note that recursion breaks the simple hash approach — a recursive method overwrites its own start time. Use a stack per key if you need to handle it.

Pro-Tip: Never leave a TracePoint enabled in production, and be specific about why: an enabled :call trace disables the VM’s method cache optimizations globally, not just for the code you’re watching. The slowdown is typically 2–10× for :call and can exceed 100× for :line, and it applies to the entire process including threads you didn’t intend to observe. Use enable with a block so it’s guaranteed to unwind, filter on tp.path as the very first line of the handler so the common case exits fast, and if you genuinely need production tracing, use enable(target:) to scope the trace to a single method object rather than the whole VM. TracePoint.new(:call) { ... }.enable(target: Order.instance_method(:total)) costs almost nothing because the VM only instruments that one method.

Targeted Tracing


Ruby 2.6 added target: and target_line:, which turn TracePoint from a debugging-only tool into something you can occasionally use in anger.

Example:

trace = TracePoint.new(:call) do |tp|
  Rails.logger.info("Order#total called from #{caller_locations(1, 3).join(' | ')}")
end

trace.enable(target: Order.instance_method(:total))

Only that method is instrumented. The rest of the VM runs at full speed. This is the right way to answer “who is calling this?” in a staging environment under real traffic.

What to Use Instead, and When


TracePoint is a scalpel for questions you can’t answer any other way. For most profiling, purpose-built tools are better:

  • stackprof — sampling profiler, negligible overhead, tells you where wall time goes
  • memory_profiler — allocations by call site
  • ActiveSupport::Notifications — Rails already instruments queries, renders, and jobs; subscribe rather than trace
  • Method#source_location / #owner — for “where is this defined,” try these first

Reach for TracePoint when the question is about runtime structure — what was defined, what was raised, who called what — rather than about time or memory.

Conclusion


TracePoint gives you a view of the running VM that no amount of source reading provides, and it’s already installed. The events that earn their keep in practice are :raise for finding swallowed exceptions, :call with a path filter for call-count profiling, and :call with target: for tracking down a specific caller under real traffic. Always use the block form, always filter on the first line of the handler, and treat an unscoped trace as a development-only tool — the method cache invalidation is a global cost, not a local one.

FAQs


Q1: Does TracePoint work with C-implemented methods?
Yes, via the :c_call and :c_return events. Note that tp.binding is unavailable for those — there’s no Ruby frame to bind to.

Q2: Can I have multiple TracePoints active at once?
Yes, and they all fire independently. Each one adds overhead, so combine events into a single TracePoint.new(:call, :return) where possible rather than creating two.

Q3: Why does my trace fire for gem code I didn’t write?
Because it’s global by default. Filter on tp.path as the first statement in the handler, or use enable(target:) to scope it to specific methods.

Q4: Is TracePoint thread-safe?
The trace itself fires on all threads, and your handler runs on whichever thread triggered it. If you accumulate into a shared hash, you need synchronization — or key by Thread.current.object_id and merge afterwards.

Q5: How is this different from set_trace_func?
set_trace_func is the older, slower predecessor that fires for every event with no filtering and passes positional arguments instead of an object. TracePoint supersedes it entirely; there’s no reason to use the old API in new code.

cdrrazan

Rajan Bhattarai

Full Stack Software Developer! 💻 🏡 Grad. Student, MCS. 🎓 Class of '23. GitKraken Ambassador 🇳🇵 2021/22. Works with Ruby / Rails. Photography when no coding. Also tweets a lot at TW / @cdrrazan!

Read More