diff --git a/features/configuration/profile.feature b/features/configuration/profile.feature index 47d0ec7d7b..7d2d6d1677 100644 --- a/features/configuration/profile.feature +++ b/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 diff --git a/features/step_definitions/additional_cli_steps.rb b/features/step_definitions/additional_cli_steps.rb index 609c1246f7..4d7da1b465 100644 --- a/features/step_definitions/additional_cli_steps.rb +++ b/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 diff --git a/lib/rspec/core/example_group.rb b/lib/rspec/core/example_group.rb index 138151f5cc..97529553ea 100644 --- a/lib/rspec/core/example_group.rb +++ b/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) diff --git a/lib/rspec/core/notifications.rb b/lib/rspec/core/notifications.rb index b3d1c6b55b..25f0faae90 100644 --- a/lib/rspec/core/notifications.rb +++ b/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 diff --git a/lib/rspec/core/profiler.rb b/lib/rspec/core/profiler.rb index ff5373be0d..afe7731105 100644 --- a/lib/rspec/core/profiler.rb +++ b/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 diff --git a/spec/rspec/core/formatters/profile_formatter_spec.rb b/spec/rspec/core/formatters/profile_formatter_spec.rb index 2b313f112a..9009b181aa 100644 --- a/spec/rspec/core/formatters/profile_formatter_spec.rb +++ b/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 diff --git a/spec/rspec/core/profiler_spec.rb b/spec/rspec/core/profiler_spec.rb index 68029dbb00..7bd370a5cb 100644 --- a/spec/rspec/core/profiler_spec.rb +++ b/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