Merge pull request #1971 from rspec/refactor_issue_1878

Refactor group profile to include before hooks

Author: JonRowe

features/configuration/profile.feature

@@ -218,3 +218,25 @@ Feature: Profile examples
     When I run `rspec spec --fail-fast --profile`
     Then the output should not contain "Top 2 slowest examples"
     And the output should not contain "example 1"
+
+  Scenario: Using `--profile` with slow before hooks includes hook execution time
+    Given a file named "spec/example_spec.rb" with:
+      """ruby
+      RSpec.describe "slow before context hook" do
+        before(:context) do
+          sleep 0.2
+        end
+        it "example" do
+          expect(10).to eq(10)
+        end
+      end
+
+      RSpec.describe "slow example" do
+        it "slow example" do
+          sleep 0.1
+          expect(10).to eq(10)
+        end
+      end
+      """
+    When I run `rspec spec --profile 1`
+    Then the output should contain "slow before context hook"

lib/rspec/core.rb

@@ -137,6 +137,7 @@ def self.world
   # Namespace for the rspec-core code.
   module Core
     autoload :ExampleStatusPersister, "rspec/core/example_status_persister"
+    autoload :Profiler,               "rspec/core/profiler"
 
     # @private
     # This avoids issues with reporting time caused by examples that

lib/rspec/core/formatters.rb

@@ -126,7 +126,11 @@ def setup_default(output_stream, deprecation_stream)
         add FallbackMessageFormatter, output_stream
       end
 
-      return unless RSpec.configuration.profile_examples? && !existing_formatter_implements?(:dump_profile)
+      return unless RSpec.configuration.profile_examples?
+
+      @reporter.setup_profiler
+
+      return if existing_formatter_implements?(:dump_profile)
 
       add RSpec::Core::Formatters::ProfileFormatter, output_stream
     end

lib/rspec/core/formatters/json_formatter.rb

@@ -60,8 +60,7 @@ def dump_profile(profile)
         # @api private
         def dump_profile_slowest_examples(profile)
           @output_hash[:profile] = {}
-          sorted_examples = profile.slowest_examples
-          @output_hash[:profile][:examples] = sorted_examples.map do |example|
+          @output_hash[:profile][:examples] = profile.slowest_examples.map do |example|
             format_example(example).tap do |hash|
               hash[:run_time] = example.execution_result.run_time
             end

lib/rspec/core/notifications.rb

@@ -400,8 +400,16 @@ def duplicate_rerun_locations
     # @attr duration [Float] the time taken (in seconds) to run the suite
     # @attr examples [Array<RSpec::Core::Example>] the examples run
     # @attr number_of_examples [Fixnum] the number of examples to profile
-    ProfileNotification = Struct.new(:duration, :examples, :number_of_examples)
+    # @attr example_groups [Array<RSpec::Core::Profiler>] example groups run
     class ProfileNotification
+      def initialize(duration, examples, number_of_examples, example_groups)
+        @duration = duration
+        @examples = examples
+        @number_of_examples = number_of_examples
+        @example_groups = example_groups
+      end
+      attr_reader :duration, :examples, :number_of_examples
+
       # @return [Array<RSpec::Core::Example>] the slowest examples
       def slowest_examples
         @slowest_examples ||=
@@ -435,26 +443,14 @@ def slowest_groups
     private
 
       def calculate_slowest_groups
-        example_groups = {}
-
-        examples.each do |example|
-          location = example.example_group.parent_groups.last.metadata[:location]
-
-          location_hash = example_groups[location] ||= Hash.new(0)
-          location_hash[:total_time]  += example.execution_result.run_time
-          location_hash[:count]       += 1
-          next if location_hash.key?(:description)
-          location_hash[:description] = example.example_group.top_level_description
-        end
-
         # stop if we've only one example group
-        return {} if example_groups.keys.length <= 1
+        return {} if @example_groups.keys.length <= 1
 
-        example_groups.each_value do |hash|
+        @example_groups.each_value do |hash|
           hash[:average] = hash[:total_time].to_f / hash[:count]
         end
 
-        example_groups.sort_by { |_, hash| -hash[:average] }.first(number_of_examples)
+        @example_groups.sort_by { |_, hash| -hash[:average] }.first(number_of_examples)
       end
     end
 

lib/rspec/core/profiler.rb

@@ -0,0 +1,28 @@
+module RSpec
+  module Core
+    # @private
+    class Profiler
+      NOTIFICATIONS = [:example_group_started, :example_group_finished, :example_started]
+
+      def initialize
+        @example_groups = Hash.new { |h, k| h[k] = { :count => 0 } }
+      end
+
+      attr_reader :example_groups
+
+      def example_group_started(notification)
+        @example_groups[notification.group][:start] = Time.now
+        @example_groups[notification.group][:description] = notification.group.top_level_description
+      end
+
+      def example_group_finished(notification)
+        @example_groups[notification.group][:total_time] =  Time.now - @example_groups[notification.group][:start]
+      end
+
+      def example_started(notification)
+        group = notification.example.example_group.parent_groups.last
+        @example_groups[group][:count] += 1
+      end
+    end
+  end
+end

lib/rspec/core/reporter.rb

@@ -28,6 +28,13 @@ def reset
       @examples = []
       @failed_examples = []
       @pending_examples = []
+      @profiler = Profiler.new if defined?(@profiler)
+    end
+
+    # @private
+    def setup_profiler
+      @profiler = Profiler.new
+      register_listener @profiler, *Profiler::NOTIFICATIONS
     end
 
     # Registers a listener to a list of notifications. The reporter will send
@@ -149,7 +156,8 @@ def finish
         notify :deprecation_summary, Notifications::NullNotification
         unless mute_profile_output?
           notify :dump_profile, Notifications::ProfileNotification.new(@duration, @examples,
-                                                                       @configuration.profile_examples)
+                                                                       @configuration.profile_examples,
+                                                                       @profiler.example_groups)
         end
         notify :dump_summary, Notifications::SummaryNotification.new(@duration, @examples, @failed_examples,
                                                                      @pending_examples, @load_time)

spec/rspec/core/formatters/json_formatter_spec.rb

@@ -133,8 +133,8 @@ def profile *groups
     end
 
     before do
+      setup_profiler
       formatter
-      config.profile_examples = 10
     end
 
     context "with one example group" do
@@ -183,7 +183,7 @@ def profile *groups
       end
 
       it "provides information" do
-        expect(formatter.output_hash[:profile][:groups].first.keys).to match_array([:total_time, :count, :description, :average, :location])
+        expect(formatter.output_hash[:profile][:groups].first.keys).to match_array([:total_time, :count, :description, :average, :location, :start])
       end
 
       it "ranks the example groups by average time" do

spec/rspec/core/formatters/profile_formatter_spec.rb

@@ -4,6 +4,7 @@
   include FormatterSupport
 
   def profile *groups
+    setup_profiler
     groups.each { |group| group.run(reporter) }
     examples = groups.map(&:examples).flatten
     total_time = examples.map { |e| e.execution_result.run_time }.inject(&:+)

spec/rspec/core/formatters_spec.rb

@@ -163,6 +163,7 @@ module RSpec::Core::Formatters
         context "without an existing profile formatter" do
           it "will add the profile formatter" do
             allow(reporter).to receive(:registered_listeners).with(:dump_profile) { [] }
+            expect(reporter).to receive(:setup_profiler)
             expect {
               setup_default
             }.to change { loader.formatters }.
@@ -174,6 +175,7 @@ module RSpec::Core::Formatters
         context "when a formatter that implement #dump_profile is added" do
           it "wont add the profile formatter" do
             allow(reporter).to receive(:registered_listeners).with(:dump_profile) { [:json] }
+            expect(reporter).to receive(:setup_profiler)
             setup_default
             expect(
               loader.formatters.map(&:class)

spec/rspec/core/profiler_spec.rb

@@ -0,0 +1,69 @@
+require 'rspec/core/profiler'
+
+RSpec.describe 'RSpec::Core::Profiler' do
+  let(:profiler) { RSpec::Core::Profiler.new }
+
+  it 'starts with an empty hash of example_groups' do
+    expect(profiler.example_groups).to be_empty.and be_a Hash
+  end
+
+  context 'when hooked into the reporter' do
+    include FormatterSupport
+
+    let(:description ) { "My Group" }
+    let(:now) { ::Time.utc(2015, 6, 2) }
+
+    before do
+      allow(::RSpec::Core::Time).to receive(:now) { now }
+    end
+
+    def group
+      @group ||=
+        begin
+          group = super
+          allow(group).to receive(:top_level_description) { description }
+          group
+        end
+    end
+
+    describe '#example_group_started' do
+      it 'records example groups start time and description via id' do
+        expect {
+          profiler.example_group_started group_notification group
+        }.to change { profiler.example_groups[group] }.
+          from(a_hash_excluding(:start, :description)).
+          to(a_hash_including(:start => now, :description => description))
+      end
+    end
+
+    describe '#example_group_finished' do
+      before do
+        profiler.example_group_started group_notification group
+        allow(::RSpec::Core::Time).to receive(:now) { now + 1 }
+      end
+
+      it 'records example groups total time and description via id' do
+        expect {
+          profiler.example_group_finished group_notification group
+        }.to change { profiler.example_groups[group] }.
+          from(a_hash_excluding(:total_time)).
+          to(a_hash_including(:total_time => 1.0))
+      end
+    end
+
+    describe '#example_started' do
+      let(:example) { new_example }
+      before do
+        allow(example).to receive(:example_group) { group }
+        allow(group).to receive(:parent_groups) { [group] }
+        profiler.example_group_started group_notification group
+      end
+
+      it 'increments the count of examples for its parent group' do
+        expect {
+          profiler.example_started example_notification example
+        }.to change { profiler.example_groups[group][:count] }.by 1
+      end
+    end
+  end
+end

spec/rspec/core/reporter_spec.rb

@@ -25,6 +25,7 @@ module RSpec::Core
       it "dumps the failure summary after the profile and deprecation summary so failures don't scroll off the screen and get missed" do
         config.profile_examples = 10
         formatter = instance_double("RSpec::Core::Formatter::ProgressFormatter")
+        reporter.setup_profiler
         reporter.register_listener(formatter, :dump_summary, :dump_profile, :deprecation_summary)
 
         expect(formatter).to receive(:deprecation_summary).ordered

spec/support/formatter_support.rb

@@ -185,6 +185,11 @@ def setup_reporter(*streams)
     @reporter = config.reporter
   end
 
+  def setup_profiler
+    config.profile_examples = true
+    reporter.setup_profiler
+  end
+
   def formatter_output
     @formatter_output ||= StringIO.new
   end
@@ -220,6 +225,7 @@ def new_example(metadata = {})
     instance_double(RSpec::Core::Example,
                      :description             => "Example",
                      :full_description        => "Example",
+                     :example_group           => group,
                      :execution_result        => result,
                      :location                => "",
                      :location_rerun_argument => "",
@@ -234,7 +240,9 @@ def examples(n)
   end
 
   def group
-    class_double "RSpec::Core::ExampleGroup", :description => "Group"
+    group = class_double "RSpec::Core::ExampleGroup", :description => "Group"
+    allow(group).to receive(:parent_groups) { [group] }
+    group
   end
 
   def start_notification(count)
@@ -249,8 +257,8 @@ def example_notification(specific_example = new_example)
    ::RSpec::Core::Notifications::ExampleNotification.for specific_example
   end
 
-  def group_notification
-   ::RSpec::Core::Notifications::GroupNotification.new group
+  def group_notification group_to_notify = group
+   ::RSpec::Core::Notifications::GroupNotification.new group_to_notify
   end
 
   def message_notification(message)
@@ -274,7 +282,7 @@ def summary_notification(duration, examples, failed, pending, time)
   end
 
   def profile_notification(duration, examples, number)
-    ::RSpec::Core::Notifications::ProfileNotification.new duration, examples, number
+    ::RSpec::Core::Notifications::ProfileNotification.new duration, examples, number, reporter.instance_variable_get('@profiler').example_groups
   end
 
 end

spec/support/matchers.rb

@@ -123,3 +123,4 @@ def failure_reason(example)
 RSpec::Matchers.define_negated_matcher :exclude, :include
 RSpec::Matchers.define_negated_matcher :excluding, :include
 RSpec::Matchers.define_negated_matcher :avoid_changing,   :change
+RSpec::Matchers.define_negated_matcher :a_hash_excluding, :include