CrackedRuby logo

CrackedRuby

Event Tracing

Comprehensive guide to Ruby's event tracing mechanisms including TracePoint API, trace hooks, and debugging techniques.

Metaprogramming TracePoint API
5.10.1

Overview

Ruby provides event tracing capabilities through the TracePoint API and related tracing mechanisms. These tools allow developers to monitor program execution by intercepting specific events like method calls, returns, line execution, and exception handling. The primary interface is the TracePoint class, which creates trace objects that respond to various execution events.

TracePoint objects attach to Ruby's internal tracing hooks and execute callback blocks when specified events occur. Ruby supports multiple event types including :call, :return, :line, :class, :end, :c_call, :c_return, :b_call, :b_return, :thread_begin, :thread_end, :raise, and :rescue. Each event provides access to execution context through methods like #method_id, #path, #lineno, and #binding.

# Basic TracePoint creation
trace = TracePoint.new(:call) do |tp|
  puts "Method called: #{tp.method_id} in #{tp.path}:#{tp.lineno}"
end

trace.enable
some_method_call
trace.disable

The tracing system integrates with Ruby's execution engine at a low level, providing visibility into program flow without requiring code modification. TracePoint objects can be enabled globally or for specific code blocks, making them suitable for debugging, profiling, and dynamic analysis.

# Multiple event types
trace = TracePoint.new(:call, :return, :line) do |tp|
  case tp.event
  when :call
    puts "#{tp.method_id}"
  when :return  
    puts "#{tp.method_id} returns #{tp.return_value}"
  when :line
    puts "  #{tp.path}:#{tp.lineno}"
  end
end

Ruby also provides the older set_trace_func method and Kernel#trace_var for variable tracing, though TracePoint represents the modern approach. The tracing system supports multiple active trace objects simultaneously, with each receiving events according to their configured event types.

Basic Usage

TracePoint objects are created by calling TracePoint.new with one or more event symbols and a callback block. The block receives the TracePoint object as a parameter, providing access to event details through various methods.

# Method call tracing
tracer = TracePoint.new(:call) do |tp|
  puts "Called #{tp.method_id} in #{tp.defined_class}"
end

tracer.enable
Math.sqrt(16)  # Triggers the trace
String.new("hello").upcase  # Triggers the trace  
tracer.disable

Event types determine which execution points trigger the callback. The :call event fires when Ruby methods are invoked, while :c_call triggers for C extension methods. Line-level tracing with :line executes the callback for each line of Ruby code.

# Line-by-line execution tracing
line_tracer = TracePoint.new(:line) do |tp|
  puts "#{File.basename(tp.path)}:#{tp.lineno} - #{tp.binding.local_variables}"
end

line_tracer.enable do
  x = 10
  y = x * 2
  puts y
end
# Automatically disables after block

The TracePoint object provides context methods that return different values depending on the event type. Method-related events populate #method_id and #defined_class, while all events provide #path and #lineno for source location.

# Exception tracing
exception_tracer = TracePoint.new(:raise) do |tp|
  puts "Exception: #{tp.raised_exception.class} - #{tp.raised_exception.message}"
  puts "  at #{tp.path}:#{tp.lineno} in #{tp.method_id}"
end

exception_tracer.enable
begin
  1 / 0
rescue ZeroDivisionError
  puts "Caught division by zero"
end
exception_tracer.disable

Block-scoped enabling ensures traces are automatically disabled when execution leaves the block, preventing memory leaks and performance degradation. This pattern is recommended for temporary tracing during specific operations.

# Class definition tracing
class_tracer = TracePoint.new(:class, :end) do |tp|
  case tp.event
  when :class
    puts "Defining class: #{tp.self}"
  when :end
    puts "Class definition complete: #{tp.self}"
  end
end

class_tracer.enable do
  class ExampleClass
    def example_method
      "hello"
    end
  end
end

Advanced Usage

Advanced tracing scenarios involve filtering events, accessing execution context, and combining multiple trace strategies. TracePoint objects can inspect the binding at trace points, allowing access to local variables, instance variables, and the call stack.

# Method profiling with return value inspection
class MethodProfiler
  def initialize
    @call_stack = []
    @call_counts = Hash.new(0)
  end

  def start_profiling
    @tracer = TracePoint.new(:call, :return) do |tp|
      method_key = "#{tp.defined_class}##{tp.method_id}"
      
      case tp.event
      when :call
        @call_stack.push({
          method: method_key,
          start_time: Time.now,
          args: extract_arguments(tp.binding)
        })
        @call_counts[method_key] += 1
      when :return
        if call_info = @call_stack.pop
          duration = Time.now - call_info[:start_time]
          puts "#{call_info[:method]} (#{duration.round(4)}s) -> #{tp.return_value.inspect}"
        end
      end
    end
    
    @tracer.enable
  end

  def stop_profiling
    @tracer&.disable
    puts "\nCall counts:"
    @call_counts.each { |method, count| puts "  #{method}: #{count}" }
  end

  private

  def extract_arguments(binding)
    binding.local_variables.map { |var| [var, binding.local_variable_get(var)] }.to_h
  end
end

Conditional tracing allows filtering events based on runtime conditions. This reduces overhead by limiting trace execution to relevant code paths or specific conditions.

# Conditional tracing based on call location
filtered_tracer = TracePoint.new(:call) do |tp|
  # Only trace methods called from specific files
  caller_location = caller_locations(1, 1).first
  next unless caller_location.path.include?('application')
  
  # Only trace methods with specific naming patterns
  next unless tp.method_id.to_s.match?(/^(create|update|delete)_/)
  
  puts "Database operation: #{tp.method_id} in #{tp.defined_class}"
  puts "  Arguments: #{tp.binding.local_variables.map { |v| 
    "#{v}=#{tp.binding.local_variable_get(v).inspect}" 
  }.join(', ')}"
end

TracePoint objects support method chaining and can be combined with other metaprogramming techniques. The #self method returns the current object context, while #binding provides full access to the execution environment.

# Dynamic method instrumentation
module MethodInstrumentation
  def self.instrument_class(klass, pattern: /.*/)
    instrumented_methods = []
    
    tracer = TracePoint.new(:call) do |tp|
      next unless tp.defined_class == klass
      next unless tp.method_id.to_s.match?(pattern)
      
      method_name = tp.method_id
      unless instrumented_methods.include?(method_name)
        instrumented_methods << method_name
        
        # Access to instance variables through binding
        instance_vars = tp.self.instance_variables.map do |var|
          "#{var}=#{tp.self.instance_variable_get(var).inspect}"
        end.join(', ')
        
        puts "First call to #{klass}##{method_name}"
        puts "  Instance state: #{instance_vars}" unless instance_vars.empty?
      end
    end
    
    tracer.enable
    tracer
  end
end

Multiple TracePoint objects can operate simultaneously, each responding to different event types or conditions. This enables complex monitoring scenarios where different aspects of program execution require separate handling.

# Multi-layered tracing system
class ExecutionMonitor
  def initialize
    @active_traces = []
  end

  def monitor_database_calls
    db_tracer = TracePoint.new(:call) do |tp|
      if tp.defined_class.to_s.match?(/ActiveRecord|Sequel|Database/)
        puts "DB: #{tp.defined_class}##{tp.method_id}"
      end
    end
    
    @active_traces << db_tracer
    db_tracer.enable
  end

  def monitor_exceptions
    error_tracer = TracePoint.new(:raise) do |tp|
      exception = tp.raised_exception
      puts "ERROR: #{exception.class}: #{exception.message}"
      puts "  Location: #{tp.path}:#{tp.lineno}"
      puts "  Method: #{tp.method_id}" if tp.method_id
    end
    
    @active_traces << error_tracer
    error_tracer.enable
  end

  def disable_all
    @active_traces.each(&:disable)
    @active_traces.clear
  end
end

Error Handling & Debugging

Event tracing encounters specific error conditions that require careful handling. TracePoint callbacks can raise exceptions, potentially disrupting program execution or creating infinite recursion scenarios.

# Safe tracer with exception handling
class SafeTracer
  def initialize(events, &block)
    @tracer = TracePoint.new(*events) do |tp|
      begin
        block.call(tp)
      rescue StandardError => e
        # Log trace errors without disrupting program flow
        STDERR.puts "Trace error: #{e.class}: #{e.message}"
        STDERR.puts "  at #{tp.path}:#{tp.lineno}"
        # Disable tracer to prevent cascading errors
        @tracer.disable
      end
    end
  end

  def enable(*args, &block)
    @tracer.enable(*args, &block)
  rescue StandardError => e
    STDERR.puts "Failed to enable tracer: #{e.message}"
    false
  end

  def disable
    @tracer&.disable
  rescue StandardError => e
    STDERR.puts "Failed to disable tracer: #{e.message}"
    false
  end
end

Recursive tracing scenarios occur when trace callbacks trigger additional traceable events. This commonly happens when trace code calls methods that generate their own trace events, leading to stack overflow or infinite loops.

# Recursion detection and prevention
class RecursionSafeTracer
  def initialize
    @tracing_depth = 0
    @max_depth = 10
  end

  def create_tracer(events)
    TracePoint.new(*events) do |tp|
      # Prevent recursive tracing
      next if @tracing_depth > 0
      
      @tracing_depth += 1
      begin
        # Guard against deep recursion
        if @tracing_depth > @max_depth
          puts "Trace depth limit reached, disabling tracer"
          tp.disable
          next
        end
        
        # Safe trace logic here
        handle_trace_event(tp)
      ensure
        @tracing_depth -= 1
      end
    end
  end

  private

  def handle_trace_event(tp)
    # Avoid calling methods that might generate trace events
    output = String.new
    output << "Event: #{tp.event}"
    output << " Method: #{tp.method_id}" if tp.respond_to?(:method_id) && tp.method_id
    puts output
  end
end

Debugging trace behavior requires understanding event timing and context availability. Some TracePoint methods are only valid for specific event types, and accessing them incorrectly raises NoMethodError.

# Robust event handling with type checking
def debug_trace_event(tp)
  event_info = {
    event: tp.event,
    path: tp.path,
    lineno: tp.lineno
  }

  # Safely access event-specific information
  case tp.event
  when :call, :c_call, :return, :c_return
    if tp.respond_to?(:method_id)
      event_info[:method] = tp.method_id
      event_info[:class] = tp.defined_class if tp.respond_to?(:defined_class)
    end
  when :return, :c_return
    if tp.respond_to?(:return_value)
      event_info[:return_value] = tp.return_value.inspect
    end
  when :raise
    if tp.respond_to?(:raised_exception)
      event_info[:exception] = {
        class: tp.raised_exception.class,
        message: tp.raised_exception.message
      }
    end
  end

  # Safely access binding information
  if tp.respond_to?(:binding) && tp.binding
    begin
      event_info[:local_vars] = tp.binding.local_variables.length
    rescue StandardError
      event_info[:binding_error] = "Could not access binding"
    end
  end

  event_info
end

TracePoint objects must be explicitly disabled to prevent memory leaks and performance degradation. Failing to disable traces in long-running applications leads to accumulating overhead and potential memory exhaustion.

# Automatic cleanup with finalizers
class ManagedTracer
  def initialize(events, &block)
    @tracer = TracePoint.new(*events, &block)
    @enabled = false
    
    # Ensure cleanup on garbage collection
    ObjectSpace.define_finalizer(self, self.class.create_finalizer(@tracer))
  end

  def self.create_finalizer(tracer)
    proc { tracer.disable if tracer }
  end

  def enable
    return false if @enabled
    
    @tracer.enable
    @enabled = true
    
    # Register for cleanup on exit
    at_exit { disable }
    
    true
  end

  def disable
    return false unless @enabled
    
    @tracer.disable
    @enabled = false
    true
  end

  def enabled?
    @enabled
  end
end

Performance & Memory

Event tracing imposes significant performance overhead, particularly for high-frequency events like :line tracing. Each trace callback execution adds method call overhead and potential memory allocation, making careful event selection critical for production use.

# Performance comparison of different trace strategies
require 'benchmark'

def performance_test
  iterations = 100_000
  
  # Baseline performance without tracing
  baseline_time = Benchmark.realtime do
    iterations.times { |i| calculate_fibonacci(10) }
  end
  
  # Method call tracing overhead
  call_trace_time = Benchmark.realtime do
    tracer = TracePoint.new(:call) { |tp| }  # Empty callback
    tracer.enable
    iterations.times { |i| calculate_fibonacci(10) }
    tracer.disable
  end
  
  # Line tracing overhead  
  line_trace_time = Benchmark.realtime do
    tracer = TracePoint.new(:line) { |tp| }  # Empty callback
    tracer.enable
    iterations.times { |i| calculate_fibonacci(10) }
    tracer.disable
  end
  
  puts "Baseline: #{baseline_time.round(4)}s"
  puts "Call tracing: #{call_trace_time.round(4)}s (#{(call_trace_time / baseline_time).round(2)}x slower)"
  puts "Line tracing: #{line_trace_time.round(4)}s (#{(line_trace_time / baseline_time).round(2)}x slower)"
end

def calculate_fibonacci(n)
  return n if n < 2
  calculate_fibonacci(n - 1) + calculate_fibonacci(n - 2)
end

Memory consumption increases with trace complexity and callback logic. TracePoint objects retain references to binding objects and local variables, potentially preventing garbage collection of large data structures.

# Memory-conscious tracing implementation
class MemoryEfficientTracer
  def initialize(events)
    @event_counts = Hash.new(0)
    @sample_interval = 100
    @sample_counter = 0
    
    @tracer = TracePoint.new(*events) do |tp|
      @event_counts[tp.event] += 1
      
      # Sample only every nth event to reduce memory pressure
      @sample_counter += 1
      next unless (@sample_counter % @sample_interval) == 0
      
      # Store minimal information, avoid retaining large objects
      log_sampled_event(tp)
    end
  end

  def enable
    # Clear counters to start fresh
    @event_counts.clear
    @sample_counter = 0
    GC.start  # Clean up before enabling
    
    @tracer.enable
  end

  def disable
    @tracer.disable
    
    # Force garbage collection after disabling
    GC.start
    
    # Report statistics without retaining trace data
    @event_counts.each do |event, count|
      puts "#{event}: #{count} events"
    end
    
    @event_counts.clear
  end

  private

  def log_sampled_event(tp)
    # Create minimal data structure, avoid binding retention
    event_data = {
      event: tp.event,
      method: tp.method_id&.to_s,  # Convert to string to avoid symbol retention
      path: File.basename(tp.path), # Use basename to reduce string size
      line: tp.lineno
    }
    
    # Log immediately rather than storing
    puts "Sample: #{event_data}"
  end
end

Selective tracing reduces overhead by filtering events based on specific criteria before executing callback logic. This approach minimizes the performance impact while maintaining useful monitoring coverage.

# High-performance selective tracing
class SelectiveTracer
  def initialize
    @target_classes = Set.new
    @target_methods = Set.new
    @enabled = false
  end

  def add_class_filter(*classes)
    @target_classes.merge(classes.map(&:to_s))
  end

  def add_method_filter(*methods)
    @target_methods.merge(methods.map(&:to_s))
  end

  def start_tracing
    return if @enabled

    @tracer = TracePoint.new(:call) do |tp|
      # Fast filtering using string comparison
      class_name = tp.defined_class.to_s
      method_name = tp.method_id.to_s
      
      # Skip early if not in target classes
      next unless @target_classes.empty? || @target_classes.include?(class_name)
      
      # Skip early if not in target methods
      next unless @target_methods.empty? || @target_methods.include?(method_name)
      
      # Only perform expensive operations for filtered events
      handle_filtered_event(tp, class_name, method_name)
    end

    @tracer.enable
    @enabled = true
  end

  def stop_tracing
    return unless @enabled
    
    @tracer.disable
    @tracer = nil
    @enabled = false
  end

  private

  def handle_filtered_event(tp, class_name, method_name)
    # Minimize object creation and method calls
    timestamp = Process.clock_gettime(Process::CLOCK_MONOTONIC)
    puts "#{timestamp}: #{class_name}##{method_name}"
  end
end

Thread Safety & Concurrency

TracePoint objects are not thread-safe by default, and enabling tracing from multiple threads can lead to race conditions and inconsistent behavior. Each thread maintains its own trace state, but callback execution can interfere with shared data structures.

# Thread-safe tracing with synchronization
class ThreadSafeTracer
  def initialize(events)
    @tracer = TracePoint.new(*events) do |tp|
      thread_id = Thread.current.object_id
      
      @mutex.synchronize do
        @thread_events[thread_id] ||= []
        @thread_events[thread_id] << {
          event: tp.event,
          method: tp.method_id,
          thread: Thread.current.name || thread_id,
          timestamp: Time.now
        }
      end
    end
    
    @mutex = Mutex.new
    @thread_events = {}
    @enabled = false
  end

  def enable
    @mutex.synchronize do
      return false if @enabled
      
      @thread_events.clear
      @tracer.enable
      @enabled = true
    end
  end

  def disable
    @mutex.synchronize do
      return false unless @enabled
      
      @tracer.disable
      @enabled = false
      
      # Report per-thread statistics
      @thread_events.each do |thread_id, events|
        puts "Thread #{thread_id}: #{events.length} events"
      end
      
      @thread_events.clear
    end
  end
end

Concurrent tracing scenarios require careful coordination to prevent data corruption and ensure consistent reporting. Multiple threads enabling or disabling traces simultaneously can create undefined behavior.

# Multi-threaded application with coordinated tracing
class ConcurrentTracer
  def initialize
    @global_tracer = nil
    @control_mutex = Mutex.new
    @event_queue = Queue.new
    @worker_thread = nil
    @running = false
  end

  def start_monitoring
    @control_mutex.synchronize do
      return false if @running
      
      # Start background worker for event processing
      @running = true
      @worker_thread = Thread.new { event_processor }
      
      # Enable global tracing
      @global_tracer = TracePoint.new(:call, :return) do |tp|
        # Queue events for background processing
        event_data = {
          thread_id: Thread.current.object_id,
          thread_name: Thread.current.name,
          event: tp.event,
          method: tp.method_id,
          class: tp.defined_class,
          timestamp: Process.clock_gettime(Process::CLOCK_MONOTONIC)
        }
        
        # Non-blocking queue operation
        @event_queue << event_data rescue nil
      end
      
      @global_tracer.enable
      true
    end
  end

  def stop_monitoring
    @control_mutex.synchronize do
      return false unless @running
      
      @running = false
      @global_tracer&.disable
      
      # Signal worker thread to stop
      @event_queue << :stop
      @worker_thread&.join(5)  # Wait up to 5 seconds
      
      @global_tracer = nil
      @worker_thread = nil
      true
    end
  end

  private

  def event_processor
    thread_stats = Hash.new { |h, k| h[k] = Hash.new(0) }
    
    while @running
      begin
        event = @event_queue.pop
        break if event == :stop
        
        # Process events in background thread
        thread_id = event[:thread_id]
        thread_stats[thread_id][event[:event]] += 1
        
        # Periodic reporting to avoid memory buildup
        if thread_stats.values.sum { |stats| stats.values.sum } % 1000 == 0
          report_statistics(thread_stats)
          thread_stats.clear
        end
        
      rescue StandardError => e
        puts "Event processing error: #{e.message}"
      end
    end
    
    report_statistics(thread_stats) unless thread_stats.empty?
  end

  def report_statistics(stats)
    puts "Thread activity summary:"
    stats.each do |thread_id, events|
      total = events.values.sum
      puts "  Thread #{thread_id}: #{total} events (#{events})"
    end
  end
end

Thread-local tracing allows monitoring specific threads without affecting global performance. This approach enables focused debugging of concurrent issues while minimizing system-wide overhead.

# Thread-specific tracing utilities
module ThreadLocalTracing
  def self.trace_current_thread(events, duration: nil)
    current_thread = Thread.current
    thread_tracer = TracePoint.new(*events) do |tp|
      # Only trace events in the current thread
      next unless Thread.current == current_thread
      
      puts "[#{current_thread.name || current_thread.object_id}] #{tp.event}: #{tp.method_id}"
    end
    
    thread_tracer.enable
    
    if duration
      # Automatic timeout
      Timer.new(duration) { thread_tracer.disable }
    end
    
    # Return tracer for manual control
    thread_tracer
  end

  def self.trace_thread_lifecycle
    TracePoint.new(:thread_begin, :thread_end) do |tp|
      case tp.event
      when :thread_begin
        puts "Thread started: #{Thread.current.name || Thread.current.object_id}"
      when :thread_end
        puts "Thread ending: #{Thread.current.name || Thread.current.object_id}"
      end
    end.tap(&:enable)
  end

  class Timer
    def initialize(duration, &block)
      Thread.new do
        sleep duration
        block.call
      end
    end
  end
end

Reference

TracePoint Class Methods

Method Parameters Returns Description
TracePoint.new(*events, &block) events (Symbol Array), block (Proc) TracePoint Creates new trace object for specified events
TracePoint.trace(*events, &block) events (Symbol Array), block (Proc) Object Creates and enables trace for block execution

TracePoint Instance Methods

Method Parameters Returns Description
#enable(&block) block (optional Proc) TracePoint Enables tracing globally or for block
#disable None TracePoint Disables active tracing
#enabled? None Boolean Returns current trace status
#event None Symbol Current event type
#method_id None Symbol Method name for call/return events
#defined_class None Class Class defining the traced method
#path None String Source file path
#lineno None Integer Source line number
#binding None Binding Execution context binding
#self None Object Current object context
#return_value None Object Return value for return events
#raised_exception None Exception Exception object for raise events

Supported Event Types

Event Triggered When Available Methods
:call Ruby method called method_id, defined_class, self, binding
:return Ruby method returns method_id, defined_class, self, return_value
:c_call C extension method called method_id, defined_class, self
:c_return C extension method returns method_id, defined_class, self, return_value
:line Ruby line executed binding, self
:class Class/module definition begins self
:end Class/module definition ends self
:b_call Block called binding, self
:b_return Block returns binding, self, return_value
:raise Exception raised raised_exception, self
:rescue Exception rescued raised_exception, self
:thread_begin Thread starts None
:thread_end Thread ends None

Legacy Tracing Methods

Method Parameters Returns Description
set_trace_func(proc) proc (Proc or nil) Proc Sets global trace function
Kernel#trace_var(symbol, cmd) symbol (Symbol), cmd (Proc/String) nil Traces global variable changes
Kernel#untrace_var(symbol, cmd) symbol (Symbol), cmd (optional) Array Removes variable trace

Performance Characteristics

Operation Relative Cost Notes
No tracing 1x Baseline performance
:call events 2-5x Method call overhead
:line events 10-50x Very high frequency events
:return events 2-5x Similar to call events
Complex callbacks 5-100x Depends on callback logic
Multiple active traces Additive Each trace adds overhead

Common Event Combinations

Use Case Recommended Events Notes
Method profiling :call, :return Measure execution time
Exception debugging :raise, :rescue Track error propagation
Line-by-line debugging :line Very high overhead
Class loading :class, :end Monitor definitions
Block execution :b_call, :b_return Trace block invocations
Thread monitoring :thread_begin, :thread_end Lifecycle tracking
Full execution trace All events Maximum overhead

Error Types

Error Class Common Causes Prevention
RuntimeError Accessing invalid trace methods Check event type before access
SystemStackError Recursive trace callbacks Implement recursion detection
NoMethodError Wrong method for event type Use conditional method access
ArgumentError Invalid event symbols Validate events before creation
ThreadError Concurrent trace operations Implement thread synchronization