Method tracer for Ruby classes

dog.rb

class Dog 
  attr_writer :name

  def initialize(name)
    @name = name
  end 

  def bark
    puts "patrick"
  end
end

example.rb

require "tracer"

# turn on method tracing for every Dog instance
Tracer.measure(Dog)

dog = Dog.new("sparky")

dog.name = "patrick"
dog.bark

example_output.txt

Dog#name= called with arguments ["patrick"]
Dog#name= took 1.7329000002064276e-05 and returned "patrick"

Dog#bark called with arguments []
Dog#bark took 3.9409999999406864e-05 and returned nil

tracer.rb

require "benchmark"

module Tracer
  extend self

  def measure(klass)
    methods = klass.instance_methods(false)

    klass.class_eval do
      methods.each do |method|
        alias_method :"original_#{method}", method

        define_method(method) do |*args|
          Tracer.log_method_start(self.class.name, method, args)

          result = nil 

          duration = Benchmark.realtime do
            result = self.send(:"original_#{method}", *args)
          end 

          Tracer.log_method_end(self.class.name, method, result, duration)

          result
        end
      end
    end
  end

  def log_method_start(klass_name, method_name, arguments)
    puts "#{klass_name}##{method_name} called with arguments #{arguments.inspect}"
  end

  def log_method_end(klass_name, method_name, result, duration)
    puts "#{klass_name}##{method_name} took #{duration} and returned #{result.inspect}"
    puts "\n"
  end

end

This is really nice.

Small nitpick but as a general rule you shouldn’t assume anything about the class you’re getting; it might already define methods that start with original_, e.g.:

class C
  def a; end
  def original_a; end
end

Tracer.measure(C)
C.new.a

Output:

C#a called with arguments []
C#original_a called with arguments []
C#original_a took 4.0e-06 and returned nil

C#a took 6.2e-05 and returned nil

You can also get an infinite loop by calling Tracer.measure(C) twice before C.new.a (this works with any class).

Here is a possible solution (not extensively tested):

  def measure(klass)
    methods = klass.instance_methods(false)

    klass.class_eval do
      methods.each do |name|
        method = instance_method(name)

        define_method(name) do |*args|
          Tracer.log_method_start(self.class.name, name, args)

          result = nil
          m = method.bind(self)

          duration = Benchmark.realtime do
            result = m.call(*args)
          end

          Tracer.log_method_end(self.class.name, name, result, duration)

          result
        end
      end
    end
  end

Output:

C#a called with arguments []
C#a took 5.0e-06 and returned nil