Fix group profile output regressions introduced in #1971.

Regressions fixed by this commit:

- We only considered top-level groups before, but #1971
  made it consider nested groups as well.  However, the
  example count was only incremented on the top-level
  group, which meant the output said “Inf seconds”
  since `float / 0` returns `Infinity`.
- We were wrongly listing the example group class name
  rather than the location. This is because we changed from
  locations to groups in the hash.

Fixes #1989.

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)
+        Hash[ 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/profile_formatter_spec.rb

@@ -57,6 +57,7 @@ def profile *groups
       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
@@ -84,6 +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
+
+      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
     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