barinek.com: the official website

Stopwatch

require 'singleton'

module Stopwatch

  if defined?(ActiveRecord) && defined?(ActiveRecord::ConnectionAdapters)
    ActiveRecord::ConnectionAdapters::AbstractAdapter.class_eval do
      def log_with_watcher(sql, name = "SQL", binds = [], &block)
        Stopwatch.instance.event("sql '#{name}'.") do
          log_without_watcher(sql, name, binds, &block)
        end
      end

      alias_method_chain :log, :watcher
    end
  end

  if defined?(ActionController)
    ActionController::Base.class_eval do
      def render_with_watcher(*args, &block)
        Stopwatch.instance.event("render.") do
          render_without_watcher(*args, &block)
        end
      end

      alias_method_chain :render, :watcher
    end
  end

  def self.watch(&block)
    watcher = Watcher.instance
    running = watcher.running
    watcher.start
    response = yield watcher
    watcher.stop unless running
    response
  end

  def self.instance
    Stopwatch::Watcher.instance
  end

  def self.reset
    Stopwatch::Watcher.instance.reset
  end

  class Split
    attr_reader :time, :message

    def initialize(time, message)
      @time = time
      @message = message
    end
  end

  class Event
    attr_reader :duration, :message

    def initialize(duration, message)
      @duration = duration
      @message = message
    end
  end

  class Tally
    attr_reader :duration, :message, :count

    def initialize(message)
      @message = message
      @duration = 0.0
      @count = 0.0
    end

    def add(event)
      @duration += event.duration
      @count += 1
    end
  end

  class Watcher
    include Singleton

    attr_reader :running, :splits, :events

    def initialize
      @running = false
      @splits = []
      @events = []
    end

    def start
      return if @running
      reset
      @running = true
      @start = Time.now
      puts "\n[stopwatch @time=#{human_time(0.0)}] started."
    end

    def stop
      @stop = Time.now
      @running = false
      puts "[stopwatch @time=#{human_time(@stop - @start)}] stopped."
    end

    def reset
      @running = false
      @splits = []
      @events = []
    end

    def split(message)
      split_time = Time.now
      @splits.push Split.new(split_time, message)
    end

    def event(message)
      start = Time.now
      result = yield
      stop = Time.now
      duration = stop - start
      @events.push Event.new(duration, message) if @running
      result
    end

    def report
      report_splits
      report_events
    end

    private

    def report_splits
      last_time = nil
      @splits.each do |split|
        time = split.time
        message = split.message
        elapsed = last_time ? time - last_time : time - @start
        last_time = time
        puts "[stopwatch @time=#{human_time(elapsed)}] split #{message} "
      end unless @splits.empty?
    end

    def report_events
      tallies = {}
      @events.each do |event|
        tallies[event.message] = Tally.new(event.message) unless tallies[event.message]
        tallies[event.message].add(event)
      end
      tallies.each do |key,tally|
        puts "[stopwatch @time=#{human_time(tally.duration)}] event #{tally.message} (#{tally.count.to_i})"
      end
    end

    def human_time(time)
      "%.2fms" % (time * 1_000)
    end

  end

end



require "test/unit"

require File.expand_path(File.join(File.dirname(__FILE__), "stopwatch"))

class TestStopwatch  Test::Unit::TestCase

  class ExampleLogger
    include Singleton

    def log(message)
      p message
    end

    def self.alias_method_chain(target, feature)
      alias_method "#{target}_without_#{feature}", target
      alias_method target, "#{target}_with_#{feature}"
    end
  end

  ExampleLogger.class_eval do
    def log_with_test(message, &block)
      Stopwatch.instance.event("a") do
        log_without_test(message, &block)
      end
    end

    alias_method_chain :log, :test
  end

  def setup
    Stopwatch.reset
  end

  def test_watch
    assert(!Stopwatch.instance.running)
    Stopwatch.watch do
      assert(Stopwatch.instance.running)
    end
    assert(!Stopwatch.instance.running)
  end

  def test_splits
    Stopwatch.watch do |watcher|
      watcher.split("a")
      watcher.split("b")
      watcher.split("c")
    end
    assert_equal(Stopwatch.instance.splits.size, 3)
    assert_equal(Stopwatch.instance.splits.collect { |split| split.message }, ["a", "b", "c"])
  end

  def test_nested
    Stopwatch.watch do |watcher|
      watcher.split("a")
      Stopwatch.watch do |watcher|
        watcher.split("b")
      end
      assert(Stopwatch.instance.running)
    end
    assert_equal(Stopwatch.instance.splits.size, 2)
    assert_equal(Stopwatch.instance.splits.collect { |split| split.message }, ["a", "b"])
  end

  def test_split_report
    Stopwatch.watch do |watcher|
      watcher.split("a")
      watcher.split("b")
      watcher.split("c")
      watcher.report
    end
  end

  def test_events
    Stopwatch.watch do |watcher|
      ExampleLogger.instance.log("message")
      Stopwatch.instance.event("b") do
      end
    end
    assert_equal(Stopwatch.instance.events.size, 2)
    assert_equal(Stopwatch.instance.events.collect { |event| event.message }, ["a", "b"])
  end

  def test_no_events
    Stopwatch.watch do |watcher|
    end
    ExampleLogger.instance.log("message")
    Stopwatch.instance.event("b") do
    end
    assert_equal(Stopwatch.instance.events.size, 0)
  end

end