Merge pull request #1992 from rspec/fix-group-profiling

Fix group profiling

Author: myronmarston

features/configuration/profile.feature

@@ -226,8 +226,11 @@ Feature: Profile examples
         before(:context) do
           sleep 0.2
         end
-        it "example" do
-          expect(10).to eq(10)
+
+        context "nested" do
+          it "example" do
+            expect(10).to eq(10)
+          end
         end
       end
 
@@ -239,4 +242,4 @@ Feature: Profile examples
       end
       """
     When I run `rspec spec --profile 1`
-    Then the output should contain "slow before context hook"
+    Then the output should report "slow before context hook" as the slowest example group

features/step_definitions/additional_cli_steps.rb

@@ -197,6 +197,30 @@
   expect(normalize_failure_output(all_output)).to include(normalize_failure_output(string))
 end
 
+Then(/^the output should report "slow before context hook" as the slowest example group$/) do
+  # These expectations are trying to guard against a regression that introduced
+  # this output:
+  #   Top 1 slowest example groups:
+  #     slow before context hook
+  #       Inf seconds average (0.00221 seconds / 0 examples) RSpec::ExampleGroups::SlowBeforeContextHook::Nested
+  #
+  # Problems:
+  # - "Inf seconds"
+  # - 0 examples
+  # - "Nested" group listed (it should be the outer group)
+  # - The example group class name is listed (it should be the location)
+
+  expect(all_output).not_to match(/nested/i)
+  expect(all_output).not_to match(/inf/i)
+  expect(all_output).not_to match(/\b0 examples/i)
+
+  seconds = '\d+(?:\.\d+)? seconds'
+
+  expect(all_output).to match(
+    %r{Top 1 slowest example groups?:\n\s+slow before context hook\n\s+#{seconds} average \(#{seconds} / 1 example\) \./spec/example_spec\.rb:1}
+  )
+end
+
 module Normalization
   def normalize_failure_output(text)
     whitespace_normalized = text.lines.map { |line| line.sub(/\s+$/, '').sub(/:in .*$/, '') }.join

lib/rspec/core/example_group.rb

@@ -436,6 +436,11 @@ def self.parent_groups
         @parent_groups ||= ancestors.select { |a| a < RSpec::Core::ExampleGroup }
       end
 
+      # @private
+      def self.top_level?
+        superclass == ExampleGroup
+      end
+
       # @private
       def self.ensure_example_groups_are_configured
         unless defined?(@@example_groups_configured)

lib/rspec/core/notifications.rb

@@ -450,7 +450,8 @@ def calculate_slowest_groups
           hash[:average] = hash[:total_time].to_f / hash[:count]
         end
 
-        @example_groups.sort_by { |_, hash| -hash[:average] }.first(number_of_examples)
+        groups = @example_groups.sort_by { |_, hash| -hash[:average] }.first(number_of_examples)
+        groups.map { |group, data| [group.location, data] }
       end
     end
 

lib/rspec/core/profiler.rb

@@ -11,11 +11,15 @@ def initialize
       attr_reader :example_groups
 
       def example_group_started(notification)
+        return unless notification.group.top_level?
+
         @example_groups[notification.group][:start] = Time.now
         @example_groups[notification.group][:description] = notification.group.top_level_description
       end
 
       def example_group_finished(notification)
+        return unless notification.group.top_level?
+
         @example_groups[notification.group][:total_time] =  Time.now - @example_groups[notification.group][:start]
       end
 

spec/rspec/core/formatters/json_formatter_spec.rb

@@ -163,17 +163,19 @@ def profile *groups
 
     context "with multiple example groups", :slow do
       before do
-        example_clock = class_double(RSpec::Core::Time, :now => RSpec::Core::Time.now + 5)
+        start = Time.utc(2015, 6, 10, 12, 30)
+        now = start
+
+        allow(RSpec::Core::Time).to receive(:now) { now }
 
         group1 = RSpec.describe("slow group") do
-          example("example") do |example|
-            # make it look slow without actually taking up precious time
-            example.clock = example_clock
-          end
+          example("example") { }
+          after { now += 100 }
         end
         group2 = RSpec.describe("fast group") do
           example("example 1") { }
           example("example 2") { }
+          after { now += 1 }
         end
         profile group1, group2
       end
@@ -187,14 +189,6 @@ def profile *groups
       end
 
       it "ranks the example groups by average time" do |ex|
-        if ENV['TRAVIS'] && RSpec::Support::Ruby.mri? && RUBY_VERSION == '2.0.0' &&
-           $original_rspec_configuration.loaded_spec_files.to_a == [File.expand_path(__FILE__)]
-          RSpec.current_example = ex # necessary due to sandboxing so that `skip` works.
-          skip "This spec fails on Travis on MRI 2.0.0 only when this spec file runs " \
-            "individually. It passes on Travis when run as part of the entire suite " \
-            "and I can't repro locally, so we are skipping it for this case."
-        end
-
         expect(formatter.output_hash[:profile][:groups].first[:description]).to eq("slow group")
       end
     end

spec/rspec/core/formatters/profile_formatter_spec.rb

@@ -31,10 +31,6 @@ def profile *groups
       it "prints the percentage taken from the total runtime" do
         expect(formatter_output.string).to match(/, 100.0% of total time\):/)
       end
-
-      it "doesn't profile a single example group" do
-        expect(formatter_output.string).not_to match(/slowest example groups/)
-      end
     end
 
     context "with one example group" do
@@ -51,18 +47,23 @@ def profile *groups
       end
 
       it_should_behave_like "profiles examples"
+
+      it "doesn't profile a single example group" do
+        expect(formatter_output.string).not_to match(/slowest example groups/)
+      end
     end
 
     context "with multiple example groups" do
       before do
         example_clock = class_double(RSpec::Core::Time, :now => RSpec::Core::Time.now + 0.5)
 
+        @slow_group_line_number = __LINE__ + 1
         group1 = RSpec.describe("slow group") do
           example("example") do |example|
             # make it look slow without actually taking up precious time
             example.clock = example_clock
           end
-            example_line_number = __LINE__ - 4
+          example_line_number = __LINE__ - 4
         end
         group2 = RSpec.describe("fast group") do
           example("example 1") { }
@@ -71,6 +72,8 @@ def profile *groups
         profile group1, group2
       end
 
+      it_should_behave_like "profiles examples"
+
       it "prints the slowest example groups" do
         expect(formatter_output.string).to match(/slowest example groups/)
       end
@@ -82,18 +85,10 @@ def profile *groups
       it "ranks the example groups by average time" do
         expect(formatter_output.string).to match(/slow group(.*)fast group/m)
       end
-    end
 
-    it "depends on parent_groups to get the top level example group" do
-      ex = nil
-      group = RSpec.describe
-      group.describe("group 2") do
-        describe "group 3" do
-          ex = example("nested example 1")
-        end
+      it "prints the location of the slow groups" do
+        expect(formatter_output.string).to include("#{RSpec::Core::Metadata.relative_path __FILE__}:#{@slow_group_line_number}")
       end
-
-      expect(ex.example_group.parent_groups.last).to eq(group)
     end
   end
 end

spec/rspec/core/profiler_spec.rb

@@ -17,23 +17,26 @@
       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
+    let(:group) { RSpec.describe "My Group" }
 
     describe '#example_group_started' do
-      it 'records example groups start time and description via id' do
+      it 'records example groups start time and description' 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
+
+      context "when the group is not a top-level group" do
+        let(:group) { super().describe "nested" }
+
+        it 'no-ops since we only consider top-level groups for profiling' do
+          expect {
+            profiler.example_group_started group_notification group
+          }.not_to change(profiler, :example_groups)
+        end
+      end
     end
 
     describe '#example_group_finished' do
@@ -42,13 +45,23 @@ def group
         allow(::RSpec::Core::Time).to receive(:now) { now + 1 }
       end
 
-      it 'records example groups total time and description via id' do
+      it 'records example groups total time and description' 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
+
+      context "when the group is not a top-level group" do
+        let(:group) { super().describe "nested" }
+
+        it 'no-ops since we only consider top-level groups for profiling' do
+          expect {
+            profiler.example_group_finished group_notification group
+          }.not_to change(profiler, :example_groups)
+        end
+      end
     end
 
     describe '#example_started' do