Skip to content

Commit

Permalink
Fix group profile output regressions introduced in rspec#1971.
Browse files Browse the repository at this point in the history
Regressions fixed by this commit:

- We only considered top-level groups before, but rspec#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 rspec#1989.
  • Loading branch information
myronmarston committed Jun 12, 2015
1 parent a05496b commit bc11555
Show file tree
Hide file tree
Showing 7 changed files with 69 additions and 14 deletions.
9 changes: 6 additions & 3 deletions features/configuration/profile.feature
Expand Up @@ -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
Expand All @@ -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
24 changes: 24 additions & 0 deletions features/step_definitions/additional_cli_steps.rb
Expand Up @@ -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
Expand Down
5 changes: 5 additions & 0 deletions lib/rspec/core/example_group.rb
Expand Up @@ -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)
Expand Down
3 changes: 2 additions & 1 deletion lib/rspec/core/notifications.rb
Expand Up @@ -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

Expand Down
4 changes: 4 additions & 0 deletions lib/rspec/core/profiler.rb
Expand Up @@ -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

Expand Down
5 changes: 5 additions & 0 deletions spec/rspec/core/formatters/profile_formatter_spec.rb
Expand Up @@ -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
Expand Down Expand Up @@ -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
33 changes: 23 additions & 10 deletions spec/rspec/core/profiler_spec.rb
Expand Up @@ -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
Expand All @@ -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
Expand Down

0 comments on commit bc11555

Please sign in to comment.