From 0a166133821fa1e2500a87364d49deb802158c3b Mon Sep 17 00:00:00 2001 From: Simon Coffey Date: Sun, 14 Jun 2015 13:08:16 +0100 Subject: [PATCH 1/6] Support multiple dependent failures in FakeRunner To illustrate cases for which a recursive bisection strategy is faster than subset enumeration, FakeRunner needs to support failures that are dependent on multiple candidate examples. --- spec/rspec/core/bisect/coordinator_spec.rb | 2 +- spec/rspec/core/bisect/example_minimizer_spec.rb | 2 +- spec/support/fake_bisect_runner.rb | 6 +++++- 3 files changed, 7 insertions(+), 3 deletions(-) diff --git a/spec/rspec/core/bisect/coordinator_spec.rb b/spec/rspec/core/bisect/coordinator_spec.rb index 1713b644c5..67ca4a6396 100644 --- a/spec/rspec/core/bisect/coordinator_spec.rb +++ b/spec/rspec/core/bisect/coordinator_spec.rb @@ -10,7 +10,7 @@ module RSpec::Core FakeBisectRunner.new( 1.upto(8).map { |i| "#{i}.rb[1:1]" }, %w[ 2.rb[1:1] ], - { "5.rb[1:1]" => "4.rb[1:1]" } + { "5.rb[1:1]" => %w[ 4.rb[1:1] ] } ) end diff --git a/spec/rspec/core/bisect/example_minimizer_spec.rb b/spec/rspec/core/bisect/example_minimizer_spec.rb index 14dbb08def..0c6ee9177f 100644 --- a/spec/rspec/core/bisect/example_minimizer_spec.rb +++ b/spec/rspec/core/bisect/example_minimizer_spec.rb @@ -9,7 +9,7 @@ module RSpec::Core FakeBisectRunner.new( %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ], %w[ ex_2 ], - { "ex_5" => "ex_4" } + { "ex_5" => %w[ ex_4 ] } ) end diff --git a/spec/support/fake_bisect_runner.rb b/spec/support/fake_bisect_runner.rb index 45df8edea4..8e4e0d8697 100644 --- a/spec/support/fake_bisect_runner.rb +++ b/spec/support/fake_bisect_runner.rb @@ -11,7 +11,7 @@ def original_results def run(ids) failures = ids & always_failures dependent_failures.each do |failing_example, depends_upon| - failures << failing_example if ids.include?(depends_upon) + failures << failing_example if dependency_satisfied?(depends_upon, ids) end RSpec::Core::Formatters::BisectFormatter::RunResults.new(ids.sort, failures.sort) @@ -20,4 +20,8 @@ def run(ids) def repro_command_from(locations) "rspec #{locations.sort.join(' ')}" end + + def dependency_satisfied?(depends_upon, ids) + depends_upon.all? { |d| ids.include?(d) } + end end From 13f89e3a7a9baccca22c6eca1bd0890fc1c4ba39 Mon Sep 17 00:00:00 2001 From: Simon Coffey Date: Sun, 14 Jun 2015 13:18:43 +0100 Subject: [PATCH 2/6] Test the number of rounds to 'reduce' pathological case If an expected failure depends on a large number of the passing examples, the subset enumeration strategy can take a large number of rounds to minimise the run. Add a test to count rounds in the worst case, where a failure depends on all of the preceding examples. With 8 candidates preceding a failure, a recursive strategy could return in 15 rounds (1 + 2 + 4 + 8). --- .../core/bisect/example_minimizer_spec.rb | 47 +++++++++++++++++++ 1 file changed, 47 insertions(+) diff --git a/spec/rspec/core/bisect/example_minimizer_spec.rb b/spec/rspec/core/bisect/example_minimizer_spec.rb index 0c6ee9177f..0f16e7c1bc 100644 --- a/spec/rspec/core/bisect/example_minimizer_spec.rb +++ b/spec/rspec/core/bisect/example_minimizer_spec.rb @@ -19,6 +19,53 @@ module RSpec::Core expect(minimizer.repro_command_for_currently_needed_ids).to eq("rspec ex_2 ex_4 ex_5") end + context 'with an unminimisable run' do + class RoundCountingReporter < RSpec::Core::NullReporter + attr_accessor :round_count + + def publish(event, *_args) + public_send(event) if respond_to? event + end + + def bisect_individual_run_start + self.round_count ||= 0 + self.round_count += 1 + end + end + + let(:counting_reporter) { RoundCountingReporter.new } + let(:fake_runner) do + FakeBisectRunner.new( + %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ex_9 ], + [], + { "ex_9" => %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ] } + ) + end + let(:minimizer) { Bisect::ExampleMinimizer.new(fake_runner, counting_reporter) } + + it 'returns the full command if the run can not be reduced' do + minimizer.find_minimal_repro + + expect(minimizer.repro_command_for_currently_needed_ids).to eq( + "rspec ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ex_9" + ) + end + + it 'detects an unminimisable run in the minimum number of rounds' do + minimizer.find_minimal_repro + + # The recursive bisection strategy should take 1 + 2 + 4 + 8 = 15 runs + # to determine that a failure is fully dependent on 8 preceding + # examples: + # + # 1 run to determine that any of the candidates are culprits + # 2 runs to determine that each half contains a culprit + # 4 runs to determine that each quarter contains a culprit + # 8 runs to determine that each candidate is a culprit + expect(counting_reporter.round_count).to eq(15) + end + end + it 'ignores flapping examples that did not fail on the initial full run but fail on later runs' do def fake_runner.run(ids) super.tap do |results| From e8f8a530d4d41885c5943e872f4852498a105481 Mon Sep 17 00:00:00 2001 From: Simon Coffey Date: Sun, 14 Jun 2015 20:22:12 +0100 Subject: [PATCH 3/6] Add bisection test case where culprits > 50% of candidates --- .../core/bisect/example_minimizer_spec.rb | 20 +++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/spec/rspec/core/bisect/example_minimizer_spec.rb b/spec/rspec/core/bisect/example_minimizer_spec.rb index 0f16e7c1bc..471c7b165c 100644 --- a/spec/rspec/core/bisect/example_minimizer_spec.rb +++ b/spec/rspec/core/bisect/example_minimizer_spec.rb @@ -19,6 +19,26 @@ module RSpec::Core expect(minimizer.repro_command_for_currently_needed_ids).to eq("rspec ex_2 ex_4 ex_5") end + it 'reduces a failure when more than 50% of examples are implicated' do + fake_runner.always_failures = [] + fake_runner.dependent_failures = { "ex_8" => %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ] } + minimizer = Bisect::ExampleMinimizer.new(fake_runner, RSpec::Core::NullReporter) + minimizer.find_minimal_repro + expect(minimizer.repro_command_for_currently_needed_ids).to eq( + "rspec ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_8" + ) + end + + it 'reduces a failure with multiple dependencies' do + fake_runner.always_failures = [] + fake_runner.dependent_failures = { "ex_8" => %w[ ex_1 ex_3 ex_5 ex_7 ] } + minimizer = Bisect::ExampleMinimizer.new(fake_runner, RSpec::Core::NullReporter) + minimizer.find_minimal_repro + expect(minimizer.repro_command_for_currently_needed_ids).to eq( + "rspec ex_1 ex_3 ex_5 ex_7 ex_8" + ) + end + context 'with an unminimisable run' do class RoundCountingReporter < RSpec::Core::NullReporter attr_accessor :round_count From 8048b6f1c132f22d4df91e672f4d8c58cf0c044c Mon Sep 17 00:00:00 2001 From: Simon Coffey Date: Sun, 14 Jun 2015 21:01:49 +0100 Subject: [PATCH 4/6] Add bisection test case for reducing independent failures --- .../core/bisect/example_minimizer_spec.rb | 44 +++++++++++++------ 1 file changed, 30 insertions(+), 14 deletions(-) diff --git a/spec/rspec/core/bisect/example_minimizer_spec.rb b/spec/rspec/core/bisect/example_minimizer_spec.rb index 471c7b165c..1a5bc921be 100644 --- a/spec/rspec/core/bisect/example_minimizer_spec.rb +++ b/spec/rspec/core/bisect/example_minimizer_spec.rb @@ -19,6 +19,17 @@ module RSpec::Core expect(minimizer.repro_command_for_currently_needed_ids).to eq("rspec ex_2 ex_4 ex_5") end + it 'reduces a failure where none of the passing examples are implicated' do + no_dependents_runner = FakeBisectRunner.new( + %w[ ex_1 ex_2 ], + %w[ ex_2 ], + {} + ) + minimizer = Bisect::ExampleMinimizer.new(no_dependents_runner, RSpec::Core::NullReporter) + minimizer.find_minimal_repro + expect(minimizer.repro_command_for_currently_needed_ids).to eq("rspec ex_2") + end + it 'reduces a failure when more than 50% of examples are implicated' do fake_runner.always_failures = [] fake_runner.dependent_failures = { "ex_8" => %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ] } @@ -39,40 +50,45 @@ module RSpec::Core ) end - context 'with an unminimisable run' do - class RoundCountingReporter < RSpec::Core::NullReporter + context 'with an unminimisable failure' do + class RunCountingReporter < RSpec::Core::NullReporter attr_accessor :round_count + attr_accessor :example_count + def initialize + @round_count = 0 + end - def publish(event, *_args) - public_send(event) if respond_to? event + def publish(event, *args) + send(event, *args) if respond_to? event end - def bisect_individual_run_start - self.round_count ||= 0 + def bisect_individual_run_start(_notification) self.round_count += 1 end end - let(:counting_reporter) { RoundCountingReporter.new } + let(:counting_reporter) { RunCountingReporter.new } let(:fake_runner) do FakeBisectRunner.new( %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ex_9 ], [], - { "ex_9" => %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ] } + "ex_9" => %w[ ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ] ) end - let(:minimizer) { Bisect::ExampleMinimizer.new(fake_runner, counting_reporter) } + let(:counting_minimizer) do + Bisect::ExampleMinimizer.new(fake_runner, counting_reporter) + end - it 'returns the full command if the run can not be reduced' do - minimizer.find_minimal_repro + it 'returns the full command if the failure can not be reduced' do + counting_minimizer.find_minimal_repro - expect(minimizer.repro_command_for_currently_needed_ids).to eq( + expect(counting_minimizer.repro_command_for_currently_needed_ids).to eq( "rspec ex_1 ex_2 ex_3 ex_4 ex_5 ex_6 ex_7 ex_8 ex_9" ) end - it 'detects an unminimisable run in the minimum number of rounds' do - minimizer.find_minimal_repro + it 'detects an unminimisable failure in the minimum number of runs' do + counting_minimizer.find_minimal_repro # The recursive bisection strategy should take 1 + 2 + 4 + 8 = 15 runs # to determine that a failure is fully dependent on 8 preceding From d177934b83afaf7a1e041fe955fcbf3369ade77c Mon Sep 17 00:00:00 2001 From: Simon Coffey Date: Sun, 14 Jun 2015 19:28:00 +0100 Subject: [PATCH 5/6] Use recursive strategy for bisection MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit To speed up bisection of complex dependent failures, a recursive bisection strategy is introduced in place of permutation searching. The strategy works as follows: 1. Split the candidate set into two slices 2. Test each slice with the expected failure(s) 3. If either slice can be ignored: - recurse on the other slice 4. If neither slice can be ignored, for each slice: - recurse on slice, retaining other slice for test runs This is easier to illustrate graphically - shown below is a case where a single expected failure depends on two preceding non-failing examples: [✘] - expected failure (failing) [✔︎] - expected failure (passing) . - uninvolved example % - culprit Failing run: . % . . . . % . [✘] Divide candidates in two and test: . . % . [✔︎] . % . . [✔︎] Both sides implicated Recurse on LHS with RHS fixed . . . . % . [✔︎] . % . . % . [✘] % . . % . [✘] Identified ^ Recurse on RHS with LHS result % % . [✘] % . [✔︎] % % [✘] Identified ^ Both sides returned, final results: % % [✘] --- lib/rspec/core/bisect/example_minimizer.rb | 97 +++++++++++-------- lib/rspec/core/bisect/subset_enumerator.rb | 39 -------- .../core/bisect/subset_enumerator_spec.rb | 47 --------- 3 files changed, 57 insertions(+), 126 deletions(-) delete mode 100644 lib/rspec/core/bisect/subset_enumerator.rb delete mode 100644 spec/rspec/core/bisect/subset_enumerator_spec.rb diff --git a/lib/rspec/core/bisect/example_minimizer.rb b/lib/rspec/core/bisect/example_minimizer.rb index f8a6022daf..dd173d4870 100644 --- a/lib/rspec/core/bisect/example_minimizer.rb +++ b/lib/rspec/core/bisect/example_minimizer.rb @@ -1,5 +1,3 @@ -RSpec::Support.require_rspec_core "bisect/subset_enumerator" - module RSpec module Core module Bisect @@ -18,20 +16,62 @@ def initialize(runner, reporter) def find_minimal_repro prep - self.remaining_ids = non_failing_example_ids + _, duration = track_duration do + bisect(non_failing_example_ids) + end - each_bisect_round do |subsets| - ids_to_ignore = subsets.find do |ids| - get_expected_failures_for?(remaining_ids - ids) - end + notify(:bisect_complete, :round => 10, :duration => duration, + :original_non_failing_count => non_failing_example_ids.size, + :remaining_count => remaining_ids.size) - next :done unless ids_to_ignore + remaining_ids + failed_example_ids + end - self.remaining_ids -= ids_to_ignore - notify(:bisect_ignoring_ids, :ids_to_ignore => ids_to_ignore, :remaining_ids => remaining_ids) + def bisect(candidate_ids) + notify(:bisect_dependency_check_started) + if get_expected_failures_for?([]) + notify(:bisect_dependency_check_failed) + self.remaining_ids = [] + return + end + notify(:bisect_dependency_check_passed) + + bisect_over(candidate_ids) + end + + def bisect_over(candidate_ids) + return if candidate_ids.one? + + slice_size = (candidate_ids.length / 2.0).ceil + lhs, rhs = candidate_ids.each_slice(slice_size).to_a + + notify( + :bisect_round_started, + :round => 10, + :subset_size => slice_size, + :remaining_count => candidate_ids.size + ) + + ids_to_ignore = [lhs, rhs].find do |ids| + get_expected_failures_for?(remaining_ids - ids) end - currently_needed_ids + if ids_to_ignore + self.remaining_ids -= ids_to_ignore + notify( + :bisect_ignoring_ids, + :ids_to_ignore => ids_to_ignore, + :remaining_ids => remaining_ids + ) + bisect_over(candidate_ids - ids_to_ignore) + else + notify( + :bisect_multiple_culprits_detected, + :duration => duration + ) + bisect_over(lhs) + bisect_over(rhs) + end end def currently_needed_ids @@ -52,6 +92,7 @@ def prep original_results = runner.original_results @all_example_ids = original_results.all_example_ids @failed_example_ids = original_results.failed_example_ids + @remaining_ids = non_failing_example_ids end if @failed_example_ids.empty? @@ -70,7 +111,11 @@ def non_failing_example_ids def get_expected_failures_for?(ids) ids_to_run = ids + failed_example_ids - notify(:bisect_individual_run_start, :command => runner.repro_command_from(ids_to_run)) + notify( + :bisect_individual_run_start, + :command => runner.repro_command_from(ids_to_run), + :ids_to_run => ids_to_run + ) results, duration = track_duration { runner.run(ids_to_run) } notify(:bisect_individual_run_complete, :duration => duration, :results => results) @@ -79,34 +124,6 @@ def get_expected_failures_for?(ids) (failed_example_ids & results.failed_example_ids) == failed_example_ids end - INFINITY = (1.0 / 0) # 1.8.7 doesn't define Float::INFINITY so we define our own... - - def each_bisect_round(&block) - last_round, duration = track_duration do - 1.upto(INFINITY) do |round| - break if :done == bisect_round(round, &block) - end - end - - notify(:bisect_complete, :round => last_round, :duration => duration, - :original_non_failing_count => non_failing_example_ids.size, - :remaining_count => remaining_ids.size) - end - - def bisect_round(round) - value, duration = track_duration do - subsets = SubsetEnumerator.new(remaining_ids) - notify(:bisect_round_started, :round => round, - :subset_size => subsets.subset_size, - :remaining_count => remaining_ids.size) - - yield subsets - end - - notify(:bisect_round_finished, :duration => duration, :round => round) - value - end - def track_duration start = ::RSpec::Core::Time.now [yield, ::RSpec::Core::Time.now - start] diff --git a/lib/rspec/core/bisect/subset_enumerator.rb b/lib/rspec/core/bisect/subset_enumerator.rb deleted file mode 100644 index 7dc52cf88d..0000000000 --- a/lib/rspec/core/bisect/subset_enumerator.rb +++ /dev/null @@ -1,39 +0,0 @@ -module RSpec - module Core - module Bisect - # Enumerates each subset of the given list of ids that is half the - # size of the total list, so that hopefully we can discard half the - # list each repeatedly in order to our minimal repro case. - # @private - class SubsetEnumerator - include Enumerable - - def initialize(ids) - @ids = ids - end - - def subset_size - @subset_size ||= (@ids.size / 2.0).ceil - end - - def each - yielded = Set.new - slice_size = subset_size - combo_count = 1 - - while slice_size > 0 - @ids.each_slice(slice_size).to_a.combination(combo_count) do |combos| - subset = combos.flatten - next if yielded.include?(subset) - yield subset - yielded << subset - end - - slice_size /= 2 - combo_count *= 2 - end - end - end - end - end -end diff --git a/spec/rspec/core/bisect/subset_enumerator_spec.rb b/spec/rspec/core/bisect/subset_enumerator_spec.rb deleted file mode 100644 index 7f612e1a98..0000000000 --- a/spec/rspec/core/bisect/subset_enumerator_spec.rb +++ /dev/null @@ -1,47 +0,0 @@ -require 'rspec/core/bisect/subset_enumerator' - -module RSpec::Core - RSpec.describe Bisect::SubsetEnumerator do - def enum_for(ids) - Bisect::SubsetEnumerator.new(ids) - end - - it 'is enumerable' do - expect(enum_for([])).to be_an(Enumerable) - end - - it 'systematically enumerates each subset of the given size, starting off with disjoint sets' do - ids = %w[ 1 2 3 4 5 6 7 8 ] - enum = enum_for(ids) - combos = enum.to_a - expect(combos).to start_with([ - # start with each half... - %w[ 1 2 3 4 ], %w[ 5 6 7 8 ], - # then cut in 4ths and combine those in all the unseen combos... - %w[ 1 2 5 6 ], %w[ 1 2 7 8 ], - %w[ 3 4 5 6 ], %w[ 3 4 7 8 ], - # then cut in 8ths and do the same... - %w[ 1 2 3 5 ], %w[ 1 2 3 6 ], %w[ 1 2 3 7 ], %w[ 1 2 3 8 ], - %w[ 1 2 4 5 ], %w[ 1 2 4 6 ], %w[ 1 2 4 7 ], %w[ 1 2 4 8 ] - ]) - - # We don't care to specify the rest of the order, but we care that all combos were hit. - expect(combos).to match_array(ids.combination(4)) - end - - it 'works with a list size that is not a power of 2' do - ids = %w[ 1 2 3 4 5 6 7 ] - enum = enum_for(ids) - combos = enum.to_a - expect(combos).to start_with([ - %w[ 1 2 3 4 ], %w[ 5 6 7 ], - %w[ 1 2 5 6 ], %w[ 1 2 7 ], - %w[ 3 4 5 6 ], %w[ 3 4 7 ] - ]) - - # Would be better to do: expect(combos).to match_array(ids.combination(4)) - # ...but we include a few extra sets of 3 due to our algorithm. - expect(combos).to include(*ids.combination(4)) - end - end -end From 5a2f4763d6ea1ec7e7aa8545a1483d690003dc50 Mon Sep 17 00:00:00 2001 From: Simon Coffey Date: Wed, 17 Jun 2015 18:35:40 +0100 Subject: [PATCH 6/6] Basic recursive bisect formatter This modifies BisectProgressFormatter to more closely model the recursive bisection algorithm, fixing the associated BisectCoordinator specs. --- features/command_line/bisect.feature | 36 +++---- features/support/send_sigint_during_bisect.rb | 4 +- lib/rspec/core/bisect/example_minimizer.rb | 46 +++++--- .../formatters/bisect_progress_formatter.rb | 59 +++++++--- spec/rspec/core/bisect/coordinator_spec.rb | 101 +++++++++++++----- 5 files changed, 173 insertions(+), 73 deletions(-) diff --git a/features/command_line/bisect.feature b/features/command_line/bisect.feature index d56df3c1d2..4c915e8d83 100644 --- a/features/command_line/bisect.feature +++ b/features/command_line/bisect.feature @@ -54,12 +54,12 @@ Feature: Bisect Bisect started using options: "--seed 1234" Running suite to find failures... (0.16755 seconds) Starting bisect with 1 failing example and 9 non-failing examples. + Checking that failure(s) are order-dependent... failure appears to be order-dependent - Round 1: searching for 5 non-failing examples (of 9) to ignore: .. (0.30166 seconds) - Round 2: searching for 3 non-failing examples (of 5) to ignore: .. (0.30306 seconds) - Round 3: searching for 2 non-failing examples (of 3) to ignore: .. (0.33292 seconds) - Round 4: searching for 1 non-failing example (of 2) to ignore: . (0.16476 seconds) - Round 5: searching for 1 non-failing example (of 1) to ignore: . (0.15329 seconds) + Round 1: bisecting over non-failing examples 1-9 .. ignoring examples 6-9 (0.30166 seconds) + Round 2: bisecting over non-failing examples 1-5 .. ignoring examples 4-5 (0.30306 seconds) + Round 3: bisecting over non-failing examples 1-3 .. ignoring example 3 (0.33292 seconds) + Round 4: bisecting over non-failing examples 1-2 . ignoring example 1 (0.16476 seconds) Bisect complete! Reduced necessary non-failing examples from 9 to 1 in 1.26 seconds. The minimal reproduction command is: @@ -75,10 +75,11 @@ Feature: Bisect Bisect started using options: "--seed 1234" Running suite to find failures... (0.17102 seconds) Starting bisect with 1 failing example and 9 non-failing examples. + Checking that failure(s) are order-dependent... failure appears to be order-dependent - Round 1: searching for 5 non-failing examples (of 9) to ignore: .. (0.32943 seconds) - Round 2: searching for 3 non-failing examples (of 5) to ignore: .. (0.3154 seconds) - Round 3: searching for 2 non-failing examples (of 3) to ignore: .. + Round 1: bisecting over non-failing examples 1-9 .. ignoring examples 6-9 (0.32943 seconds) + Round 2: bisecting over non-failing examples 1-5 .. ignoring examples 4-5 (0.3154 seconds) + Round 3: bisecting over non-failing examples 1-3 .. ignoring example 3 (0.2175 seconds) Bisect aborted! @@ -106,8 +107,10 @@ Feature: Bisect - ./spec/calculator_7_spec.rb[1:1] - ./spec/calculator_8_spec.rb[1:1] - ./spec/calculator_9_spec.rb[1:1] - - Round 1: searching for 5 non-failing examples (of 9) to ignore: + Checking that failure(s) are order-dependent.. + - Running: rspec ./spec/calculator_1_spec.rb[1:1] --seed 1234 (n.nnnn seconds) + - Failure appears to be order-dependent + Round 1: bisecting over non-failing examples 1-9 - Running: rspec ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_6_spec.rb[1:1] ./spec/calculator_7_spec.rb[1:1] ./spec/calculator_8_spec.rb[1:1] ./spec/calculator_9_spec.rb[1:1] --seed 1234 (0.15302 seconds) - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_2_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] ./spec/calculator_4_spec.rb[1:1] ./spec/calculator_5_spec.rb[1:1] --seed 1234 (0.19708 seconds) - Examples we can safely ignore (4): @@ -121,8 +124,7 @@ Feature: Bisect - ./spec/calculator_3_spec.rb[1:1] - ./spec/calculator_4_spec.rb[1:1] - ./spec/calculator_5_spec.rb[1:1] - - Round finished (0.35172 seconds) - Round 2: searching for 3 non-failing examples (of 5) to ignore: + Round 2: bisecting over non-failing examples 1-5 - Running: rspec ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_4_spec.rb[1:1] ./spec/calculator_5_spec.rb[1:1] --seed 1234 (0.15836 seconds) - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_2_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] --seed 1234 (0.19065 seconds) - Examples we can safely ignore (2): @@ -132,8 +134,7 @@ Feature: Bisect - ./spec/calculator_10_spec.rb[1:1] - ./spec/calculator_2_spec.rb[1:1] - ./spec/calculator_3_spec.rb[1:1] - - Round finished (0.35022 seconds) - Round 3: searching for 2 non-failing examples (of 3) to ignore: + Round 3: bisecting over non-failing examples 1-3 - Running: rspec ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_2_spec.rb[1:1] --seed 1234 (0.21028 seconds) - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] --seed 1234 (0.1975 seconds) - Examples we can safely ignore (1): @@ -141,17 +142,12 @@ Feature: Bisect - Remaining non-failing examples (2): - ./spec/calculator_10_spec.rb[1:1] - ./spec/calculator_3_spec.rb[1:1] - - Round finished (0.40882 seconds) - Round 4: searching for 1 non-failing example (of 2) to ignore: + Round 4: bisecting over non-failing examples 1-2 - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] --seed 1234 (0.17173 seconds) - Examples we can safely ignore (1): - ./spec/calculator_3_spec.rb[1:1] - Remaining non-failing examples (1): - ./spec/calculator_10_spec.rb[1:1] - - Round finished (0.17234 seconds) - Round 5: searching for 1 non-failing example (of 1) to ignore: - - Running: rspec ./spec/calculator_1_spec.rb[1:1] --seed 1234 (0.18279 seconds) - - Round finished (0.18312 seconds) Bisect complete! Reduced necessary non-failing examples from 9 to 1 in 1.47 seconds. The minimal reproduction command is: diff --git a/features/support/send_sigint_during_bisect.rb b/features/support/send_sigint_during_bisect.rb index 9002f73635..13f65c7bcf 100644 --- a/features/support/send_sigint_during_bisect.rb +++ b/features/support/send_sigint_during_bisect.rb @@ -5,8 +5,8 @@ module RSpec::Core::Formatters BisectProgressFormatter = Class.new(remove_const :BisectProgressFormatter) do RSpec::Core::Formatters.register self - def bisect_round_finished(notification) - return super unless notification.round == 3 + def bisect_round_started(notification) + return super unless @round_count == 3 Process.kill("INT", Process.pid) # Process.kill is not a synchronous call, so to ensure the output diff --git a/lib/rspec/core/bisect/example_minimizer.rb b/lib/rspec/core/bisect/example_minimizer.rb index dd173d4870..69667d9ae4 100644 --- a/lib/rspec/core/bisect/example_minimizer.rb +++ b/lib/rspec/core/bisect/example_minimizer.rb @@ -20,7 +20,7 @@ def find_minimal_repro bisect(non_failing_example_ids) end - notify(:bisect_complete, :round => 10, :duration => duration, + notify(:bisect_complete, :duration => duration, :original_non_failing_count => non_failing_example_ids.size, :remaining_count => remaining_ids.size) @@ -42,31 +42,34 @@ def bisect(candidate_ids) def bisect_over(candidate_ids) return if candidate_ids.one? - slice_size = (candidate_ids.length / 2.0).ceil - lhs, rhs = candidate_ids.each_slice(slice_size).to_a - notify( :bisect_round_started, - :round => 10, - :subset_size => slice_size, - :remaining_count => candidate_ids.size + :candidate_range => example_range(candidate_ids), + :candidates_count => candidate_ids.size ) - ids_to_ignore = [lhs, rhs].find do |ids| - get_expected_failures_for?(remaining_ids - ids) + slice_size = (candidate_ids.length / 2.0).ceil + lhs, rhs = candidate_ids.each_slice(slice_size).to_a + + ids_to_ignore, duration = track_duration do + [lhs, rhs].find do |ids| + get_expected_failures_for?(remaining_ids - ids) + end end if ids_to_ignore self.remaining_ids -= ids_to_ignore notify( - :bisect_ignoring_ids, + :bisect_round_ignoring_ids, :ids_to_ignore => ids_to_ignore, - :remaining_ids => remaining_ids + :ignore_range => example_range(ids_to_ignore), + :remaining_ids => remaining_ids, + :duration => duration ) bisect_over(candidate_ids - ids_to_ignore) else notify( - :bisect_multiple_culprits_detected, + :bisect_round_detected_multiple_culprits, :duration => duration ) bisect_over(lhs) @@ -83,8 +86,27 @@ def repro_command_for_currently_needed_ids "(Not yet enough information to provide any repro command)" end + # @private + # Convenience class for describing a subset of the candidate examples + ExampleRange = Struct.new(:start, :finish) do + def description + if start == finish + "example #{start}" + else + "examples #{start}-#{finish}" + end + end + end + private + def example_range(ids) + ExampleRange.new( + non_failing_example_ids.find_index(ids.first) + 1, + non_failing_example_ids.find_index(ids.last) + 1 + ) + end + def prep notify(:bisect_starting, :original_cli_args => runner.original_cli_args) diff --git a/lib/rspec/core/formatters/bisect_progress_formatter.rb b/lib/rspec/core/formatters/bisect_progress_formatter.rb index 3b12c219ef..3f0a643d87 100644 --- a/lib/rspec/core/formatters/bisect_progress_formatter.rb +++ b/lib/rspec/core/formatters/bisect_progress_formatter.rb @@ -9,10 +9,14 @@ class BisectProgressFormatter < BaseTextFormatter # We've named all events with a `bisect_` prefix to prevent naming collisions. Formatters.register self, :bisect_starting, :bisect_original_run_complete, :bisect_round_started, :bisect_individual_run_complete, - :bisect_round_finished, :bisect_complete, :bisect_repro_command, - :bisect_failed, :bisect_aborted + :bisect_complete, :bisect_repro_command, + :bisect_failed, :bisect_aborted, + :bisect_round_ignoring_ids, :bisect_round_detected_multiple_culprits, + :bisect_dependency_check_started, :bisect_dependency_check_passed, + :bisect_dependency_check_failed def bisect_starting(notification) + @round_count = 0 options = notification.original_cli_args.join(' ') output.puts "Bisect started using options: #{options.inspect}" output.print "Running suite to find failures..." @@ -26,17 +30,35 @@ def bisect_original_run_complete(notification) output.puts "Starting bisect with #{failures} and #{non_failures}." end + def bisect_dependency_check_started(_notification) + output.print "Checking that failure(s) are order-dependent.." + end + + def bisect_dependency_check_passed(_notification) + output.puts " failure appears to be order-dependent" + end + + def bisect_dependency_check_failed(_notification) + output.puts " failure is not order-dependent" + end + def bisect_round_started(notification, include_trailing_space=true) - search_desc = Helpers.pluralize( - notification.subset_size, "non-failing example" - ) + @round_count += 1 + range_desc = notification.candidate_range.description - output.print "\nRound #{notification.round}: searching for #{search_desc}" \ - " (of #{notification.remaining_count}) to ignore:" + output.print "\nRound #{@round_count}: bisecting over non-failing #{range_desc}" output.print " " if include_trailing_space end - def bisect_round_finished(notification) + def bisect_round_ignoring_ids(notification) + range_desc = notification.ignore_range.description + + output.print " ignoring #{range_desc}" + output.print " (#{Helpers.format_duration(notification.duration)})" + end + + def bisect_round_detected_multiple_culprits(notification) + output.print " multiple culprits detected - splitting candidates" output.print " (#{Helpers.format_duration(notification.duration)})" end @@ -71,7 +93,7 @@ def bisect_aborted(notification) # Designed to provide details for us when we need to troubleshoot bisect bugs. class BisectDebugFormatter < BisectProgressFormatter Formatters.register self, :bisect_original_run_complete, :bisect_individual_run_start, - :bisect_individual_run_complete, :bisect_round_finished, :bisect_ignoring_ids + :bisect_individual_run_complete, :bisect_round_ignoring_ids def bisect_original_run_complete(notification) output.puts " (#{Helpers.format_duration(notification.duration)})" @@ -88,20 +110,27 @@ def bisect_individual_run_complete(notification) output.print " (#{Helpers.format_duration(notification.duration)})" end - def bisect_round_started(notification) - super(notification, false) + def bisect_dependency_check_passed(_notification) + output.print "\n - Failure appears to be order-dependent" end - def bisect_round_finished(notification) - output.print "\n - Round finished" - super + def bisect_dependency_check_failed(_notification) + output.print "\n - Failure is not order-dependent" end - def bisect_ignoring_ids(notification) + def bisect_round_started(notification) + super(notification, false) + end + + def bisect_round_ignoring_ids(notification) output.print "\n - #{describe_ids 'Examples we can safely ignore', notification.ids_to_ignore}" output.print "\n - #{describe_ids 'Remaining non-failing examples', notification.remaining_ids}" end + def bisect_round_detected_multiple_culprits(_notification) + output.print "\n - Multiple culprits detected - splitting candidates" + end + private def describe_ids(description, ids) diff --git a/spec/rspec/core/bisect/coordinator_spec.rb b/spec/rspec/core/bisect/coordinator_spec.rb index 67ca4a6396..002f6ca0ca 100644 --- a/spec/rspec/core/bisect/coordinator_spec.rb +++ b/spec/rspec/core/bisect/coordinator_spec.rb @@ -10,7 +10,7 @@ module RSpec::Core FakeBisectRunner.new( 1.upto(8).map { |i| "#{i}.rb[1:1]" }, %w[ 2.rb[1:1] ], - { "5.rb[1:1]" => %w[ 4.rb[1:1] ] } + { "5.rb[1:1]" => %w[ 1.rb[1:1] 4.rb[1:1] ] } ) end @@ -34,14 +34,15 @@ def find_minimal_repro(output, formatter=Formatters::BisectProgressFormatter) |Bisect started using options: "" |Running suite to find failures... (n.nnnn seconds) |Starting bisect with 2 failing examples and 6 non-failing examples. + |Checking that failure(s) are order-dependent... failure appears to be order-dependent | - |Round 1: searching for 3 non-failing examples (of 6) to ignore: .. (n.nnnn seconds) - |Round 2: searching for 2 non-failing examples (of 3) to ignore: . (n.nnnn seconds) - |Round 3: searching for 1 non-failing example (of 1) to ignore: . (n.nnnn seconds) - |Bisect complete! Reduced necessary non-failing examples from 6 to 1 in n.nnnn seconds. + |Round 1: bisecting over non-failing examples 1-6 .. ignoring examples 4-6 (n.nnnn seconds) + |Round 2: bisecting over non-failing examples 1-3 .. multiple culprits detected - splitting candidates (n.nnnn seconds) + |Round 3: bisecting over non-failing examples 1-2 .. ignoring example 2 (n.nnnn seconds) + |Bisect complete! Reduced necessary non-failing examples from 6 to 2 in n.nnnn seconds. | |The minimal reproduction command is: - | rspec 2.rb[1:1] 4.rb[1:1] 5.rb[1:1] + | rspec 1.rb[1:1] 2.rb[1:1] 4.rb[1:1] 5.rb[1:1] EOS end @@ -63,8 +64,10 @@ def find_minimal_repro(output, formatter=Formatters::BisectProgressFormatter) | - 6.rb[1:1] | - 7.rb[1:1] | - 8.rb[1:1] - | - |Round 1: searching for 3 non-failing examples (of 6) to ignore: + |Checking that failure(s) are order-dependent.. + | - Running: rspec 2.rb[1:1] 5.rb[1:1] (n.nnnn seconds) + | - Failure appears to be order-dependent + |Round 1: bisecting over non-failing examples 1-6 | - Running: rspec 2.rb[1:1] 5.rb[1:1] 6.rb[1:1] 7.rb[1:1] 8.rb[1:1] (n.nnnn seconds) | - Running: rspec 1.rb[1:1] 2.rb[1:1] 3.rb[1:1] 4.rb[1:1] 5.rb[1:1] (n.nnnn seconds) | - Examples we can safely ignore (3): @@ -75,32 +78,82 @@ def find_minimal_repro(output, formatter=Formatters::BisectProgressFormatter) | - 1.rb[1:1] | - 3.rb[1:1] | - 4.rb[1:1] - | - Round finished (n.nnnn seconds) - |Round 2: searching for 2 non-failing examples (of 3) to ignore: + |Round 2: bisecting over non-failing examples 1-3 | - Running: rspec 2.rb[1:1] 4.rb[1:1] 5.rb[1:1] (n.nnnn seconds) - | - Examples we can safely ignore (2): - | - 1.rb[1:1] + | - Running: rspec 1.rb[1:1] 2.rb[1:1] 3.rb[1:1] 5.rb[1:1] (n.nnnn seconds) + | - Multiple culprits detected - splitting candidates + |Round 3: bisecting over non-failing examples 1-2 + | - Running: rspec 2.rb[1:1] 3.rb[1:1] 4.rb[1:1] 5.rb[1:1] (n.nnnn seconds) + | - Running: rspec 1.rb[1:1] 2.rb[1:1] 4.rb[1:1] 5.rb[1:1] (n.nnnn seconds) + | - Examples we can safely ignore (1): | - 3.rb[1:1] - | - Remaining non-failing examples (1): + | - Remaining non-failing examples (2): + | - 1.rb[1:1] | - 4.rb[1:1] - | - Round finished (n.nnnn seconds) - |Round 3: searching for 1 non-failing example (of 1) to ignore: - | - Running: rspec 2.rb[1:1] 5.rb[1:1] (n.nnnn seconds) - | - Round finished (n.nnnn seconds) - |Bisect complete! Reduced necessary non-failing examples from 6 to 1 in n.nnnn seconds. + |Bisect complete! Reduced necessary non-failing examples from 6 to 2 in n.nnnn seconds. | |The minimal reproduction command is: - | rspec 2.rb[1:1] 4.rb[1:1] 5.rb[1:1] + | rspec 1.rb[1:1] 2.rb[1:1] 4.rb[1:1] 5.rb[1:1] EOS end + context "with an order-independent failure" do + it "detects the independent case and prints the minimal reproduction" do + fake_runner.dependent_failures = {} + output = StringIO.new + find_minimal_repro(output) + output = normalize_durations(output.string) + + expect(output).to eq(<<-EOS.gsub(/^\s+\|/, '')) + |Bisect started using options: "" + |Running suite to find failures... (n.nnnn seconds) + |Starting bisect with 1 failing example and 7 non-failing examples. + |Checking that failure(s) are order-dependent... failure is not order-dependent + | + |Bisect complete! Reduced necessary non-failing examples from 7 to 0 in n.nnnn seconds. + | + |The minimal reproduction command is: + | rspec 2.rb[1:1] + EOS + end + + it "can use the debug formatter for detailed output" do + fake_runner.dependent_failures = {} + output = StringIO.new + find_minimal_repro(output, Formatters::BisectDebugFormatter) + output = normalize_durations(output.string) + + expect(output).to eq(<<-EOS.gsub(/^\s+\|/, '')) + |Bisect started using options: "" + |Running suite to find failures... (n.nnnn seconds) + | - Failing examples (1): + | - 2.rb[1:1] + | - Non-failing examples (7): + | - 1.rb[1:1] + | - 3.rb[1:1] + | - 4.rb[1:1] + | - 5.rb[1:1] + | - 6.rb[1:1] + | - 7.rb[1:1] + | - 8.rb[1:1] + |Checking that failure(s) are order-dependent.. + | - Running: rspec 2.rb[1:1] (n.nnnn seconds) + | - Failure is not order-dependent + |Bisect complete! Reduced necessary non-failing examples from 7 to 0 in n.nnnn seconds. + | + |The minimal reproduction command is: + | rspec 2.rb[1:1] + EOS + end + end + context "when the user aborst the bisect with ctrl-c" do let(:aborting_formatter) do Class.new(Formatters::BisectProgressFormatter) do Formatters.register self - def bisect_round_finished(notification) - return super unless notification.round == 2 + def bisect_round_started(notification) + return super unless @round_count == 1 Process.kill("INT", Process.pid) # Process.kill is not a synchronous call, so to ensure the output @@ -128,14 +181,14 @@ def bisect_round_finished(notification) |Bisect started using options: "" |Running suite to find failures... (n.nnnn seconds) |Starting bisect with 2 failing examples and 6 non-failing examples. + |Checking that failure(s) are order-dependent... failure appears to be order-dependent | - |Round 1: searching for 3 non-failing examples (of 6) to ignore: .. (n.nnnn seconds) - |Round 2: searching for 2 non-failing examples (of 3) to ignore: . + |Round 1: bisecting over non-failing examples 1-6 .. ignoring examples 4-6 (n.nnnn seconds) | |Bisect aborted! | |The most minimal reproduction command discovered so far is: - | rspec 2.rb[1:1] 4.rb[1:1] 5.rb[1:1] + | rspec 1.rb[1:1] 2.rb[1:1] 3.rb[1:1] 4.rb[1:1] 5.rb[1:1] EOS end end