CrackedRuby logo

CrackedRuby

Method Call Tracking

Method Call Tracking in Ruby encompasses techniques for monitoring, intercepting, and logging method invocations using TracePoint, method_missing, aliasing, and metaprogramming approaches.

Metaprogramming TracePoint API
5.10.2

Overview

Method call tracking in Ruby involves monitoring method invocations as they occur during program execution. Ruby provides several mechanisms for implementing call tracking, including the TracePoint API for runtime tracing, method_missing for catching undefined method calls, method aliasing for wrapping existing methods, and module prepending for non-destructive method interception.

The primary classes involved are TracePoint for comprehensive runtime tracing, Method and UnboundMethod for method introspection, and various metaprogramming techniques using modules and classes. TracePoint offers the most comprehensive tracking capabilities, monitoring call, return, line, class, and other execution events.

# Basic TracePoint method tracking
trace = TracePoint.new(:call) do |tp|
  puts "Called: #{tp.defined_class}##{tp.method_id}"
end

trace.enable
"hello".upcase
trace.disable
# => Called: String#upcase

Method call tracking serves multiple purposes including debugging, performance profiling, security auditing, and implementing aspect-oriented programming patterns. Different tracking approaches offer varying levels of granularity and performance overhead.

# Method missing for call interception
class CallTracker
  def method_missing(method_name, *args, **kwargs)
    puts "Intercepted: #{method_name} with #{args.size} arguments"
    super
  end
end

tracker = CallTracker.new
tracker.undefined_method("arg1", "arg2")
# => Intercepted: undefined_method with 2 arguments

The tracking mechanisms integrate with Ruby's object model and execution engine, allowing fine-grained control over which methods are monitored and what information is captured during tracking.

Basic Usage

TracePoint provides the foundation for method call tracking in Ruby. The :call event fires when methods are invoked, while :return captures method completion. TracePoint objects expose detailed execution context through methods like defined_class, method_id, and binding.

# Tracking method calls and returns
trace = TracePoint.new(:call, :return) do |tp|
  case tp.event
  when :call
    puts "#{tp.defined_class}##{tp.method_id}"
  when :return
    puts "#{tp.defined_class}##{tp.method_id} returned #{tp.return_value}"
  end
end

trace.enable do
  [1, 2, 3].map(&:to_s)
end
# => → Array#map
# => → Integer#to_s
# => ← Integer#to_s returned "1"
# => → Integer#to_s
# => ← Integer#to_s returned "2"
# => → Integer#to_s
# => ← Integer#to_s returned "3"
# => ← Array#map returned ["1", "2", "3"]

Method aliasing creates tracking wrappers around existing methods. This approach modifies method definitions to include tracking logic while preserving original functionality.

class String
  alias_method :original_upcase, :upcase
  
  def upcase
    puts "String#upcase called on: #{self.inspect}"
    result = original_upcase
    puts "String#upcase returning: #{result.inspect}"
    result
  end
end

"hello".upcase
# => String#upcase called on: "hello"
# => String#upcase returning: "HELLO"

Module prepending offers non-destructive method tracking by inserting tracking modules into the method lookup chain. Prepended modules receive method calls before the original class methods.

module CallTracker
  def upcase
    puts "Tracking: #{self.class}#upcase"
    super
  end
end

String.prepend(CallTracker)

"test".upcase
# => Tracking: String#upcase
# => "TEST"

Method missing enables tracking calls to undefined methods, which proves useful for implementing proxy objects and dynamic method handling.

class MethodProxy
  def initialize(target)
    @target = target
  end
  
  def method_missing(method_name, *args, **kwargs, &block)
    puts "Proxying: #{method_name}"
    @target.public_send(method_name, *args, **kwargs, &block)
  rescue NoMethodError
    puts "Method not found: #{method_name}"
    raise
  end
  
  def respond_to_missing?(method_name, include_private = false)
    @target.respond_to?(method_name, include_private)
  end
end

proxy = MethodProxy.new([1, 2, 3])
proxy.length
# => Proxying: length
# => 3

Advanced Usage

Complex tracking scenarios require combining multiple approaches and handling edge cases. Conditional tracking based on method signatures, caller context, or runtime conditions provides targeted monitoring without excessive overhead.

class SelectiveTracker
  def self.track_methods(*method_names, &block)
    trace = TracePoint.new(:call) do |tp|
      if method_names.include?(tp.method_id)
        context = {
          class: tp.defined_class,
          method: tp.method_id,
          file: tp.path,
          line: tp.lineno,
          caller: caller_locations(1, 1).first&.label
        }
        block.call(context)
      end
    end
    
    trace.enable
    yield
    trace.disable
  end
end

SelectiveTracker.track_methods(:map, :select) do |context|
  puts "#{context[:caller]}#{context[:class]}##{context[:method]} at #{context[:file]}:#{context[:line]}"
end do
  numbers = [1, 2, 3, 4, 5]
  evens = numbers.select(&:even?).map(&:to_s)
end

Tracking method calls with parameter inspection requires careful handling of complex data structures and potential circular references. Parameter logging must balance detail with performance.

class ParameterTracker
  def self.track_with_params(target_class, method_name)
    target_class.class_eval do
      alias_method "#{method_name}_without_tracking", method_name
      
      define_method(method_name) do |*args, **kwargs, &block|
        param_info = {
          args: args.map { |arg| safe_inspect(arg) },
          kwargs: kwargs.transform_values { |v| safe_inspect(v) },
          block: block ? "block given" : "no block"
        }
        
        puts "#{self.class}##{method_name} called with:"
        puts "  Args: #{param_info[:args]}"
        puts "  Kwargs: #{param_info[:kwargs]}" unless param_info[:kwargs].empty?
        puts "  Block: #{param_info[:block]}"
        
        result = public_send("#{method_name}_without_tracking", *args, **kwargs, &block)
        puts "  Returned: #{safe_inspect(result)}"
        result
      end
      
      private
      
      def safe_inspect(obj, max_length: 100)
        inspected = obj.inspect
        inspected.length > max_length ? "#{inspected[0, max_length]}..." : inspected
      rescue StandardError
        obj.class.name
      end
    end
  end
end

ParameterTracker.track_with_params(Array, :select)

[1, 2, 3, 4, 5].select(&:even?)
# => Array#select called with:
# =>   Args: []
# =>   Kwargs: {}
# =>   Block: block given
# =>   Returned: [2, 4]

Stack-aware tracking maintains call hierarchies and measures nested execution times. This approach requires managing call stacks and timing information across recursive or deeply nested method calls.

class HierarchicalTracker
  def initialize
    @call_stack = []
    @start_times = {}
  end
  
  def enable
    @trace = TracePoint.new(:call, :return) do |tp|
      case tp.event
      when :call
        handle_call(tp)
      when :return
        handle_return(tp)
      end
    end
    @trace.enable
  end
  
  def disable
    @trace&.disable
  end
  
  private
  
  def handle_call(tp)
    indent = "  " * @call_stack.size
    method_sig = "#{tp.defined_class}##{tp.method_id}"
    @call_stack.push(method_sig)
    @start_times[method_sig] = Process.clock_gettime(Process::CLOCK_MONOTONIC)
    puts "#{indent}#{method_sig}"
  end
  
  def handle_return(tp)
    method_sig = @call_stack.pop
    duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - @start_times[method_sig]
    indent = "  " * @call_stack.size
    puts "#{indent}#{method_sig} (#{(duration * 1000).round(2)}ms)"
  end
end

tracker = HierarchicalTracker.new
tracker.enable

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

fibonacci(5)
tracker.disable

Error Handling & Debugging

Method call tracking introduces potential failure points that require careful error handling. TracePoint callbacks can raise exceptions that interfere with normal program execution, while tracking overhead may mask or alter timing-dependent bugs.

TracePoint exception handling prevents tracking errors from disrupting the traced program. Exceptions within trace blocks require isolation to maintain program stability.

class SafeTracker
  def self.safe_trace(*events, &block)
    TracePoint.new(*events) do |tp|
      begin
        block.call(tp)
      rescue StandardError => e
        warn "Trace error: #{e.class}: #{e.message}"
        warn "  Location: #{tp.path}:#{tp.lineno}"
        warn "  Method: #{tp.defined_class}##{tp.method_id}" if tp.respond_to?(:method_id)
      end
    end
  end
  
  def self.with_error_logging(&block)
    trace = safe_trace(:call, :return) do |tp|
      case tp.event
      when :call
        puts "Call: #{tp.defined_class}##{tp.method_id}"
      when :return
        puts "Return: #{tp.return_value.inspect}"
        # Potential error if return_value can't be inspected
        nil.some_undefined_method # This will be caught
      end
    end
    
    trace.enable
    yield
    trace.disable
  end
end

SafeTracker.with_error_logging do
  "hello".upcase
end
# => Call: String#upcase
# => Trace error: NoMethodError: undefined method `some_undefined_method' for nil:NilClass

Debugging tracking issues requires identifying when tracking interferes with program behavior. Common problems include infinite recursion when tracking methods called by the tracker itself, and performance degradation from excessive logging.

class DebugTracker
  def initialize
    @recursive_calls = Set.new
    @call_count = 0
    @max_calls = 10000
  end
  
  def enable_with_safeguards
    @trace = TracePoint.new(:call) do |tp|
      @call_count += 1
      
      # Prevent infinite recursion
      method_key = [tp.defined_class, tp.method_id]
      if @recursive_calls.include?(method_key)
        next
      end
      
      # Prevent excessive tracking
      if @call_count > @max_calls
        warn "Stopping trace: exceeded maximum calls (#{@max_calls})"
        @trace.disable
        next
      end
      
      @recursive_calls.add(method_key)
      
      begin
        handle_call(tp)
      ensure
        @recursive_calls.delete(method_key)
      end
    end
    
    @trace.enable
  end
  
  private
  
  def handle_call(tp)
    # Avoid calling methods that might trigger more tracing
    method_info = "#{tp.defined_class}##{tp.method_id}"
    $stderr.write("#{method_info}\n") # Direct write to avoid method calls
  end
end

Method aliasing conflicts occur when multiple tracking systems modify the same methods. Detection and resolution of aliasing conflicts prevents method loss and unexpected behavior.

module AliasConflictDetector
  def self.safe_alias_method(klass, new_name, original_name)
    if klass.method_defined?(new_name)
      existing_method = klass.instance_method(new_name)
      original_method = klass.instance_method(original_name)
      
      if existing_method != original_method
        raise "Alias conflict: #{new_name} already exists and differs from #{original_name}"
      else
        warn "Alias #{new_name} already exists but is identical to #{original_name}"
        return false
      end
    end
    
    klass.alias_method(new_name, original_name)
    true
  end
  
  def self.track_method_safely(klass, method_name, &tracker_block)
    backup_name = "#{method_name}_without_tracking_#{SecureRandom.hex(4)}"
    
    unless safe_alias_method(klass, backup_name, method_name)
      return false
    end
    
    klass.define_method(method_name) do |*args, **kwargs, &block|
      tracker_block.call(self, method_name, args, kwargs)
      public_send(backup_name, *args, **kwargs, &block)
    end
    
    true
  rescue StandardError => e
    warn "Failed to track #{klass}##{method_name}: #{e.message}"
    false
  end
end

Performance & Memory

Method call tracking imposes significant performance overhead that varies based on tracking scope and implementation approach. TracePoint represents the heaviest approach due to its comprehensive monitoring, while targeted aliasing offers better performance for specific methods.

Benchmarking different tracking approaches reveals performance characteristics across various workloads. TracePoint overhead scales with total method calls, while aliasing overhead affects only tracked methods.

require 'benchmark'

class PerformanceTester
  def self.benchmark_tracking_approaches(iterations: 100_000)
    # Test data
    test_array = (1..100).to_a
    
    results = {}
    
    # Baseline - no tracking
    results[:baseline] = Benchmark.measure do
      iterations.times { test_array.map(&:to_s) }
    end
    
    # TracePoint tracking
    trace = TracePoint.new(:call) { |tp| nil }
    results[:tracepoint] = Benchmark.measure do
      trace.enable
      iterations.times { test_array.map(&:to_s) }
      trace.disable
    end
    
    # Method aliasing
    Array.class_eval do
      alias_method :map_without_tracking, :map
      def map(&block)
        map_without_tracking(&block)
      end
    end
    
    results[:aliasing] = Benchmark.measure do
      iterations.times { test_array.map(&:to_s) }
    end
    
    results.each do |approach, time|
      overhead = approach == :baseline ? 0 : ((time.real / results[:baseline].real - 1) * 100).round(1)
      puts "#{approach}: #{time.real.round(4)}s (#{overhead}% overhead)"
    end
  end
end

PerformanceTester.benchmark_tracking_approaches

Memory consumption tracking reveals how different approaches affect memory usage patterns. TracePoint maintains internal state that grows with execution complexity, while aliasing creates additional method objects.

class MemoryTracker
  def self.measure_memory_usage(&block)
    GC.start
    before = GC.stat[:total_allocated_objects]
    yield
    GC.start
    after = GC.stat[:total_allocated_objects]
    after - before
  end
  
  def self.compare_tracking_memory
    test_iterations = 10_000
    
    baseline_objects = measure_memory_usage do
      test_iterations.times { "test".upcase }
    end
    
    tracepoint_objects = measure_memory_usage do
      trace = TracePoint.new(:call) { |tp| nil }
      trace.enable
      test_iterations.times { "test".upcase }
      trace.disable
    end
    
    puts "Baseline: #{baseline_objects} objects allocated"
    puts "TracePoint: #{tracepoint_objects} objects allocated"
    puts "Overhead: #{tracepoint_objects - baseline_objects} additional objects"
  end
end

MemoryTracker.compare_tracking_memory

Optimized tracking implementations minimize overhead through selective monitoring, efficient data structures, and lazy evaluation of tracking data. Sampling techniques reduce tracking frequency while maintaining statistical accuracy.

class OptimizedTracker
  def initialize(sample_rate: 0.1)
    @sample_rate = sample_rate
    @sample_counter = 0
    @tracking_data = {}
  end
  
  def enable_sampling
    @trace = TracePoint.new(:call) do |tp|
      @sample_counter += 1
      
      # Sample only specified percentage of calls
      next unless (@sample_counter * @sample_rate).to_i > ((@sample_counter - 1) * @sample_rate).to_i
      
      method_key = "#{tp.defined_class}##{tp.method_id}"
      @tracking_data[method_key] ||= { count: 0, last_seen: Time.now }
      @tracking_data[method_key][:count] += 1
      @tracking_data[method_key][:last_seen] = Time.now
    end
    
    @trace.enable
  end
  
  def disable_and_report
    @trace.disable
    
    puts "Method call statistics (#{(@sample_rate * 100).to_i}% sample):"
    @tracking_data.each do |method, stats|
      estimated_calls = (stats[:count] / @sample_rate).round
      puts "  #{method}: ~#{estimated_calls} calls"
    end
  end
end

Production Patterns

Production method call tracking requires balancing monitoring needs with performance constraints. Selective tracking of critical methods, configurable logging levels, and efficient data aggregation enable practical monitoring without significant overhead.

Application monitoring integrates method tracking with logging frameworks and metrics collection systems. Structured logging formats enable downstream analysis and alerting based on method call patterns.

require 'logger'
require 'json'

class ProductionTracker
  def initialize(logger: Logger.new($stdout), level: :info)
    @logger = logger
    @level = level
    @tracked_methods = Set.new
    @call_counts = Hash.new(0)
    @error_counts = Hash.new(0)
    @timing_data = {}
  end
  
  def track_class_methods(klass, *method_names)
    method_names.each do |method_name|
      track_method(klass, method_name)
    end
  end
  
  def track_method(klass, method_name)
    method_key = "#{klass}##{method_name}"
    return if @tracked_methods.include?(method_key)
    
    @tracked_methods.add(method_key)
    
    klass.class_eval do
      alias_method "#{method_name}_without_tracking", method_name
      
      define_method(method_name) do |*args, **kwargs, &block|
        start_time = Process.clock_gettime(Process::CLOCK_MONOTONIC)
        
        begin
          result = public_send("#{method_name}_without_tracking", *args, **kwargs, &block)
          duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start_time
          
          @call_counts[method_key] += 1
          @timing_data[method_key] = (@timing_data[method_key] || []) << duration
          
          log_method_call(method_key, duration, success: true)
          result
        rescue StandardError => e
          duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start_time
          @error_counts[method_key] += 1
          
          log_method_call(method_key, duration, success: false, error: e)
          raise
        end
      end
    end
  end
  
  def generate_report
    report = {
      timestamp: Time.now.iso8601,
      summary: {
        total_calls: @call_counts.values.sum,
        total_errors: @error_counts.values.sum,
        tracked_methods: @tracked_methods.size
      },
      methods: {}
    }
    
    @tracked_methods.each do |method_key|
      calls = @call_counts[method_key]
      errors = @error_counts[method_key]
      timings = @timing_data[method_key] || []
      
      report[:methods][method_key] = {
        calls: calls,
        errors: errors,
        error_rate: calls > 0 ? (errors.to_f / calls * 100).round(2) : 0,
        avg_duration: timings.empty? ? 0 : (timings.sum / timings.size * 1000).round(2),
        max_duration: timings.empty? ? 0 : (timings.max * 1000).round(2)
      }
    end
    
    report
  end
  
  private
  
  def log_method_call(method_key, duration, success:, error: nil)
    log_data = {
      method: method_key,
      duration_ms: (duration * 1000).round(2),
      success: success,
      timestamp: Time.now.iso8601
    }
    
    log_data[:error] = error.class.name if error
    
    case @level
    when :debug
      @logger.debug(JSON.generate(log_data))
    when :info
      @logger.info("#{method_key}: #{log_data[:duration_ms]}ms") if success
      @logger.warn("#{method_key} failed: #{error&.class}") unless success
    end
  end
end

# Usage in Rails application
tracker = ProductionTracker.new(logger: Rails.logger, level: :info)
tracker.track_class_methods(User, :authenticate, :create, :update)
tracker.track_class_methods(Order, :process_payment, :send_confirmation)

# Periodic reporting
Thread.new do
  loop do
    sleep 300 # Report every 5 minutes
    report = tracker.generate_report
    Rails.logger.info("Method tracking report: #{JSON.generate(report)}")
  end
end

Error tracking and alerting systems integrate with method tracking to identify problematic code paths. Threshold-based alerting notifies operations teams when error rates or response times exceed acceptable limits.

class AlertingTracker
  def initialize(alert_thresholds: {})
    @alert_thresholds = {
      error_rate: 5.0,        # 5% error rate
      avg_duration: 1000.0,   # 1 second average
      max_duration: 5000.0    # 5 second maximum
    }.merge(alert_thresholds)
    
    @metrics = Hash.new { |h, k| h[k] = { calls: 0, errors: 0, durations: [] } }
    @alerts_sent = Set.new
  end
  
  def track_with_alerts(klass, method_name)
    method_key = "#{klass}##{method_name}"
    
    klass.class_eval do
      alias_method "#{method_name}_without_alerts", method_name
      
      define_method(method_name) do |*args, **kwargs, &block|
        start_time = Process.clock_gettime(Process::CLOCK_MONOTONIC)
        
        begin
          result = public_send("#{method_name}_without_alerts", *args, **kwargs, &block)
          duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start_time
          
          @metrics[method_key][:calls] += 1
          @metrics[method_key][:durations] << duration
          
          check_alerts(method_key)
          result
        rescue StandardError => e
          duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start_time
          
          @metrics[method_key][:calls] += 1
          @metrics[method_key][:errors] += 1
          @metrics[method_key][:durations] << duration
          
          check_alerts(method_key)
          raise
        end
      end
    end
  end
  
  private
  
  def check_alerts(method_key)
    metrics = @metrics[method_key]
    return if metrics[:calls] < 10 # Need minimum sample size
    
    error_rate = (metrics[:errors].to_f / metrics[:calls] * 100)
    avg_duration = (metrics[:durations].sum / metrics[:durations].size * 1000)
    max_duration = (metrics[:durations].max * 1000)
    
    alerts = []
    
    if error_rate > @alert_thresholds[:error_rate]
      alerts << "High error rate: #{error_rate.round(1)}%"
    end
    
    if avg_duration > @alert_thresholds[:avg_duration]
      alerts << "Slow average response: #{avg_duration.round(1)}ms"
    end
    
    if max_duration > @alert_thresholds[:max_duration]
      alerts << "Very slow response: #{max_duration.round(1)}ms"
    end
    
    unless alerts.empty?
      alert_key = "#{method_key}:#{alerts.join('|')}"
      unless @alerts_sent.include?(alert_key)
        send_alert(method_key, alerts, metrics)
        @alerts_sent.add(alert_key)
      end
    end
  end
  
  def send_alert(method_key, alerts, metrics)
    alert_message = "ALERT: #{method_key}\n"
    alerts.each { |alert| alert_message += "  - #{alert}\n" }
    alert_message += "  Calls: #{metrics[:calls]}, Errors: #{metrics[:errors]}"
    
    # Integration points for actual alerting systems
    puts alert_message
    # Slack webhook, PagerDuty, etc.
  end
end

Reference

TracePoint Events

Event Trigger Access Methods
:call Method call defined_class, method_id, path, lineno
:return Method return defined_class, method_id, return_value
:c_call C method call defined_class, method_id
:c_return C method return defined_class, method_id, return_value
:raise Exception raised raised_exception
:rescue Exception rescued raised_exception
:line Line execution path, lineno
:class Class/module definition defined_class
:end Class/module end defined_class
:fiber_switch Fiber switch None
:thread_begin Thread start None
:thread_end Thread end None

TracePoint Methods

Method Returns Description
#binding Binding Execution context binding
#defined_class Class/Module Class where method is defined
#event Symbol Current trace event type
#lineno Integer Line number in source file
#method_id Symbol Method name being traced
#path String Source file path
#raised_exception Exception Exception object (for :raise, :rescue)
#return_value Object Method return value (for :return, :c_return)
#self Object Receiver object
#enable(target: nil, &block) TracePoint Enable tracing
#disable TracePoint Disable tracing
#enabled? Boolean Check if tracing is enabled

Method Object Methods

Method Returns Description
Method#call(*args, **kwargs, &block) Object Call the method
Method#[](*args) Object Call with arguments
Method#arity Integer Number of parameters
Method#name Symbol Method name
Method#owner Class/Module Class/module defining method
Method#parameters Array Parameter information
Method#source_location Array File and line number
Method#super_method Method/nil Overridden method
UnboundMethod#bind(obj) Method Bind to specific object

Common Metaprogramming Methods

Method Context Description
alias_method(new_name, original_name) Class Create method alias
define_method(name, &block) Class Define instance method
method_missing(method_name, *args, **kwargs, &block) Instance Handle undefined method calls
respond_to_missing?(method_name, include_private) Instance Check if method_missing handles method
prepend(module) Class Insert module before class in lookup
public_send(method_name, *args) Instance Call public method dynamically
send(method_name, *args) Instance Call method dynamically (including private)
instance_method(method_name) Class Get unbound method
method(method_name) Instance Get bound method object

Performance Considerations

Approach Overhead Scope Use Case
TracePoint :call Very High Global Comprehensive debugging
TracePoint :return Very High Global Return value monitoring
Method Aliasing Medium Per-method Targeted tracking
Module Prepending Low Per-class Clean method wrapping
Method Missing Low Per-class Dynamic method handling
Refinements Very Low Scoped Localized modifications

Error Handling Patterns

Pattern Implementation Benefits
Safe Callbacks begin/rescue in trace blocks Prevents trace interference
Recursion Guards Call stack tracking Avoids infinite recursion
Resource Limits Call counters and timeouts Prevents resource exhaustion
Graceful Degradation Fallback to no-tracking Maintains functionality
Error Isolation Separate error handling thread Keeps main execution clean