capybara_timers.rb

# Copyright 2018 Marketplacer under the MIT license.
class CapybaraTimers
  class << self
    attr_accessor :nesting, :total_time

    def setup
      # Wrap every DSL method and every matcher with our timing function
      Capybara::Session::DSL_METHODS.each do |name|
        setup_timer_on_method(Capybara::DSL, name)
      end
      Capybara::Node::Matchers.public_instance_methods.each do |name|
        setup_timer_on_method(Capybara::Node::Base, name)
      end
      # The .path method can be quite slow in selenium - up to 500ms
      setup_timer_on_method(Capybara::Selenium::Node, :path)

      RSpec.configure do |config|
        config.before :suite do
          CapybaraTimers.total_time = 0
        end
        config.after :suite do
          $stderr.printf "CAPYBARA TOTAL %0.2fs\n", CapybaraTimers.total_time if CapybaraTimers.total_time > 0
        end

        config.before :each do
          CapybaraTimers.nesting = 0
        end
      end
    end

    private

    def setup_timer_on_method klass, name
      klass.send(:alias_method, "__timing_#{name}", name)
      klass.send(:define_method, name) do |*args, &block|
        result = nil

        CapybaraTimers.nesting += 1

        elapsed = Benchmark.realtime do
          result = send("__timing_#{name}", *args, &block)
        end

        # Don't add to our global timer if we're nested as we don't
        # want to double-count
        CapybaraTimers.total_time += elapsed if CapybaraTimers.nesting == 1

        # Find the first thing in the backtrace that matches our own repo
        callers = caller_locations(1)
        my_caller = callers.find do |c|
          c.path && c.path.include?(Rails.root.to_s) && !c.path.include?("capybara_timers")
        end
        my_caller ||= callers.first # Unlikely, but possible.

        path = my_caller.path.gsub(Rails.root.to_s + '/', "")
        nesting = " " * ((CapybaraTimers.nesting - 1) * 2)

        # Only inspect the first arg, and only inspect if a string or int - if we get
        # passed a Node calling inspect on it triggers .path, which is slow.
        args_s = args.first.is_a?(String) || args.first.is_a?(Integer) ? args.first.inspect : args.class.to_s

        if elapsed >= 0.01
          $stderr.printf "%s%0.2fs %s:%d %s %s\n", nesting, elapsed, path, my_caller.lineno, name, args_s
        end

        CapybaraTimers.nesting -= 1

        # Ensure we return the original result to the caller
        result
      end
    end
  end
end

CapybaraTimers.setup if ENV["CAPYBARA_TIMERS"]