log_with_time.rb

class Object
  def log_with_time txt=nil, thld=100, with_stat=nil, &block
    with_stat ||= false
    start = Time.now
    result = yield

    taken = ((Time.now - start) * 1000).round(1)
    dbg = ["===="]
    dbg << txt.to_s.ljust(50) if txt

    if with_stat
      $stat ||= {}
      $stat[:runs] ||= []

      $stat[:runs] << taken
      $stat[:avg] = ($stat[:runs].inject(:+) / (cnt = $stat[:runs].size)).round(1)
      dbg << "(#{$stat[:avg]}ms on #{cnt} runs)"
    end
    dbg << "(#{taken}ms)"

    Rails.logger.debug dbg.join(' ') if taken > thld
    result
  end
end

def go
  sleep(slept = rand(1.0..2.0))
  slept
end


# USAGE:
# 1. log method call duration:

pry(main)> log_with_time("go took:") { go }
==== go took:                                           (1854.1ms)

# 2. log set threshold for logged duration (will log calls longer than 2000ms):
pry(main)> log_with_time("go took:", 2000) { go }
# => no log

# 3. log method call duration series:
pry(main)> 10.times do |i| 
pry(main)*  log_with_time("go took:", 0, true) { go }
pry(main)* end
==== go took:                                       (1507.9ms on 1 runs) (1507.9ms)
==== go took:                                       (1256.6ms on 2 runs) (1005.3ms)
==== go took:                                       (1212.9ms on 3 runs) (1125.5ms)
==== go took:                                       (1171.8ms on 4 runs) (1048.4ms)
==== go took:                                       (1315.4ms on 5 runs) (1889.8ms)
==== go took:                                       (1345.9ms on 6 runs) (1498.2ms)
==== go took:                                       (1327.6ms on 7 runs) (1218.2ms)
==== go took:                                       (1359.7ms on 8 runs) (1584.5ms)
==== go took:                                       (1333.7ms on 9 runs) (1125.1ms)
==== go took:                                       (1345.1ms on 10 runs) (1447.6ms)

pry(main)> $stat
=> {:runs=>[1507.9, 1005.3, 1125.5, 1048.4, 1889.8, 1498.2, 1218.2, 1584.5, 1125.1, 1447.6], :avg=>1345.1}