RSpec Events Profiler

event_profiler.rb

module RSpec
  class EventProfiler # :nodoc:
    # Add #duration method to floats
    module FloatDuration
      refine Float do
        def duration
          t = self
          format("%02d:%02d.%03d", t / 60, t % 60, t.modulo(1) * 1000)
        end
      end
    end

    using FloatDuration

    NOTIFICATIONS = [:example_group_started, :example_group_finished, :example_started].freeze

    def initialize
      @time = 0.0
      @count = 0
      @total_time = 0.0
      @total_count = 0
      @example_groups = Hash.new { |h, k| h[k] = { count: 0 } }
      @event = ENV['PROF_EVENT'] != '1' ? ENV['PROF_EVENT'] : 'sql.active_record'
      @take = (ENV['PROF_NUM'] || 5).to_i

      ActiveSupport::Notifications.subscribe(@event) do |*args|
        track(*args)
      end
    end

    def track(_event, start, finish, _id, _data)
      spent = finish - start
      @time += spent
      @total_time += spent
      @count += 1
      @total_count += 1
    end

    attr_reader :example_groups

    def example_group_started(notification)
      return unless notification.group.top_level?
      @time = 0.0
      @count = 0
      @example_groups[notification.group][:description] = notification.group.top_level_description.to_s
    end

    def example_group_finished(notification)
      return unless notification.group.top_level?

      @example_groups[notification.group][:total_time] = @time
      @example_groups[notification.group][:total_count] = @count
    end

    def example_started(notification)
      group = notification.example.example_group.parent_groups.last
      @example_groups[group][:count] += 1
    end

    def print
      puts "\n"
      puts "Profiling #{@event}\n\n"
      puts "Total time: #{@total_time.duration}\n"
      puts "Total events: #{@total_count}\n"

      slowest = @example_groups.values.sort_by { |g| -g[:total_time] }.take(@take)

      puts "Top #{@take} slowest suites:\n\n"

      slowest.each do |group|
        puts "\n"
        puts "#{group[:description]} – #{group[:total_time].duration} "\
             "(#{group[:total_count]} / #{group[:count]} – #{(group[:total_count].to_f / group[:count]).round(2)})"
      end
      puts "\n"
    end
  end
end

if ENV['PROF_EVENT']
  RSpec.configure do |config|
    listener = RSpec::EventProfiler.new

    config.reporter.register_listener(listener, *RSpec::EventProfiler::NOTIFICATIONS)

    config.after(:suite) do
      listener.print
    end
  end
end