Log duration of method calls

time_logger.rb

module TimeLogger
  def self.included(base)
    base.extend(ClassMethods)
  end

  module ClassMethods
    attr_writer :time_logger

    def time_logger
      @time_logger ||= Logger.new(File.join(Rails.root, 'log', 'time_logger.log'))
    end

    def log_time_for(*methods)
      methods.each do |m|
        metaclass = (class << self; self; end)
        metaclass.send :alias_method, :"old_#{m}", m
        metaclass.send :define_method, m do |*args|
          t = Time.now
          result = send(:"old_#{m}", *args)
          time = (Time.now - t).round(2)
          time_logger.debug "#{Time.now.to_s(:db)}: Duration #{time} seconds when calling #{self.name}.#{m} with [#{args.join(', ')}]"
          result
        end
      end
    end
  end

end

time_logger_spec.rb

require 'tempfile'
require 'active_support/all'
require 'time_logger'

class Dummy
  include TimeLogger
  def self.my_method(*args); end
  log_time_for :my_method
end

describe TimeLogger do

  before do
    @file = StringIO.new
    Dummy.time_logger = Logger.new @file
  end

  after do
    @file.close
  end

  it "should have a logger setup" do
    Dummy.time_logger.should be_a(Logger)
  end

  describe "#log_time_for" do

    it "should log class and method name" do
      Dummy.my_method
      @file.should have_logged /Dummy.my_method/
    end

    it "should log duration for method call" do
      Dummy.my_method
      @file.should have_logged /Duration \d+\.\d+ seconds/
    end

    it "should log method parameters" do
      Dummy.my_method 42
      @file.should have_logged /\[42\]/
    end

  end

end

RSpec::Matchers.define :have_logged do |expected|
  match do |actual|
    if actual.class == StringIO
      actual.string.split("\n").detect {|line| line.try :match, expected}
    else
      actual.readlines.last.detect {|line| line.try :match, expected}
    end
  end
end