Trace metrics for methods defined in Ruby code

call_metrics.rb

require 'pp'
require 'set'

module CountThings
  COUNTS = Hash.new { |h, k| h[k] = Hash.new { |h, k| h[k] = 0 } }
  TIMINGS = Hash.new { |h, k| h[k] = Hash.new { |h, k| h[k] = [] } }
  TRACED_METHODS = Hash.new { |h, k| h[k] = Set.new }

  module_function

  def call(klass, method, stack, args)
    start = Time.now
    result = yield
    finish = Time.now
    TIMINGS[klass][method] << Invocation.new(
      klass,
      method,
      finish - start,
      stack,
      args,
    )
    result
  ensure
    COUNTS[klass][method] += 1
  end

  def total_time(klass, method)
    TIMINGS[klass][method].sum(&:execution_time)
  end

  def average_time(klass, method)
    total_time(klass, method) / call_count(klass, method)
  end

  def call_count(klass, method)
    COUNTS[klass][method]
  end

  def median_time(klass, method)
    percentile_time(50, klass, method)
  end

  def percentile_time(percentile, klass, method)
    timings = TIMINGS[klass][method]
    timings.sort[(timings.count * percentile / 100.0).to_i]
  end

  def order_by_most_time_spent
    TIMINGS
      .flat_map do |klass, methods|
        methods.map { |method, timings| [[klass, method], timings.sum(&:execution_time)] }
      end
      .sort_by { |method, total_time| -total_time }
      .to_h
  end

  class Invocation
    include Comparable

    attr_reader :execution_time

    def initialize(klass, method_name, execution_time, call_stack, args)
      @klass = klass
      @method_name = method_name
      @execution_time = execution_time
      @call_stack = call_stack
      @args = args
    end

    def <=>(other)
      execution_time <=> other.execution_time
    end
  end
end

class BasicObject
  # Enable tracking of method calls. In real code, you might want to until
  # after framework code is loaded to execute this.
  # It's not foolproof because some classes can override this, but it's
  # so uncommon to do this in Ruby that it'll get you most of the way there.
  def self.method_added(name)
    return if name.to_s.start_with? 'untraced_'
    return if instance_methods.include? "untraced_#{name}"
    return if ::CountThings::TRACED_METHODS[self].include? name
    ::CountThings::TRACED_METHODS[self] << name

    class_eval do
      alias_method "untraced_#{name}", name
      define_method name do |*args, &block|
        ::CountThings.call self.class, name, caller, args do
          send "untraced_#{name}", *args, &block
        end
      end
    end
  end
end

###################
# All methods defined beyond this point are tracked

class Foo
  def hello(world = 'world')
    sleep rand(0.0...0.1) # Give it a variance in execution time
    "omg #{world}"
  end
end

class Bar < Foo
end

# Running these calls in threads because they take too long otherwise
Array
  .new(1_000) { Thread.new { Foo.new.hello(:world) } }
  .each(&:join)
Foo.new.to_s

Bar.new.hello

pp CountThings::COUNTS
# {Foo=>{:hello=>1000}, Bar=>{:hello=>1}}

pp CountThings.call_count(Foo, :hello)
# 1000
pp CountThings.total_time(Foo, :hello)
# 490.437512
pp CountThings.average_time(Foo, :hello)
# 0.490437512
pp CountThings.median_time(Foo, :hello)
# 0.486538
pp CountThings.percentile_time(99, Foo, :hello)
# 0.990356

pp CountThings.order_by_most_time_spent
# {[Foo, :hello]=>490.437512, [Bar, :hello]=>0.899982}